Commit 21817055 by Domas Committed by GitHub

Logging: sourcemap support for frontend stacktraces (#30590)

parent 74702659
......@@ -34,6 +34,7 @@ require (
github.com/getsentry/sentry-go v0.9.0
github.com/go-macaron/binding v0.0.0-20190806013118-0b4f37bab25b
github.com/go-macaron/gzip v0.0.0-20160222043647-cad1c6580a07
github.com/go-sourcemap/sourcemap v2.1.3+incompatible
github.com/go-sql-driver/mysql v1.5.0
github.com/go-stack/stack v1.8.0
github.com/gobwas/glob v0.2.3
......
......@@ -488,6 +488,8 @@ github.com/go-openapi/validate v0.19.3/go.mod h1:90Vh6jjkTn+OT1Eefm0ZixWNFjhtOH7
github.com/go-openapi/validate v0.19.8/go.mod h1:8DJv2CVJQ6kGNpFW6eV9N3JviE1C85nY1c2z52x1Gk4=
github.com/go-redis/redis/v8 v8.0.0-beta.10.0.20200905143926-df7fe4e2ce72/go.mod h1:CJP1ZIHwhosNYwIdaHPZK9vHsM3+roNBaZ7U9Of1DXc=
github.com/go-redis/redis/v8 v8.2.3/go.mod h1:ysgGY09J/QeDYbu3HikWEIPCwaeOkuNoTgKayTEaEOw=
github.com/go-sourcemap/sourcemap v2.1.3+incompatible h1:W1iEw64niKVGogNgBN3ePyLFfuisuzeidWPMPWmECqU=
github.com/go-sourcemap/sourcemap v2.1.3+incompatible/go.mod h1:F8jJfvm2KbVjc5NqelyYJmf/v5J0dwNLS2mL4sNA1Jg=
github.com/go-sql-driver/mysql v1.4.0/go.mod h1:zAC/RDZ24gD3HViQzih4MyKcchzm+sOG5ZlKdlhCg5w=
github.com/go-sql-driver/mysql v1.4.1/go.mod h1:zAC/RDZ24gD3HViQzih4MyKcchzm+sOG5ZlKdlhCg5w=
github.com/go-sql-driver/mysql v1.5.0 h1:ozyZYNQW3x3HtqT1jira07DN2PArx2v7/mN66gGcHOs=
......
......@@ -7,6 +7,7 @@ import (
"github.com/go-macaron/binding"
"github.com/grafana/grafana/pkg/api/avatar"
"github.com/grafana/grafana/pkg/api/dtos"
"github.com/grafana/grafana/pkg/api/frontendlogging"
"github.com/grafana/grafana/pkg/api/routing"
"github.com/grafana/grafana/pkg/infra/log"
"github.com/grafana/grafana/pkg/middleware"
......@@ -444,5 +445,6 @@ func (hs *HTTPServer) registerRoutes() {
r.Delete("/api/snapshots/:key", reqEditorRole, routing.Wrap(DeleteDashboardSnapshot))
// Frontend logs
r.Post("/log", middleware.RateLimit(hs.Cfg.Sentry.EndpointRPS, hs.Cfg.Sentry.EndpointBurst, time.Now), bind(frontendSentryEvent{}), routing.Wrap(hs.logFrontendMessage))
sourceMapStore := frontendlogging.NewSourceMapStore(hs.Cfg, frontendlogging.ReadSourceMapFromFS)
r.Post("/log", middleware.RateLimit(hs.Cfg.Sentry.EndpointRPS, hs.Cfg.Sentry.EndpointBurst, time.Now), bind(frontendlogging.FrontendSentryEvent{}), routing.Wrap(NewFrontendLogMessageHandler(sourceMapStore)))
}
package api
import (
"fmt"
"strings"
"github.com/getsentry/sentry-go"
"github.com/grafana/grafana/pkg/api/frontendlogging"
"github.com/grafana/grafana/pkg/api/response"
"github.com/grafana/grafana/pkg/infra/log"
"github.com/grafana/grafana/pkg/models"
"github.com/inconshreveable/log15"
)
var frontendLogger = log.New("frontend")
type frontendSentryExceptionValue struct {
Value string `json:"value,omitempty"`
Type string `json:"type,omitempty"`
Stacktrace sentry.Stacktrace `json:"stacktrace,omitempty"`
}
type frontendSentryException struct {
Values []frontendSentryExceptionValue `json:"values,omitempty"`
}
type frontendLogMessageHandler func(c *models.ReqContext, event frontendlogging.FrontendSentryEvent) response.Response
type frontendSentryEvent struct {
*sentry.Event
Exception *frontendSentryException `json:"exception,omitempty"`
}
func (value *frontendSentryExceptionValue) FmtMessage() string {
return fmt.Sprintf("%s: %s", value.Type, value.Value)
}
func (value *frontendSentryExceptionValue) FmtStacktrace() string {
var stacktrace = value.FmtMessage()
for _, frame := range value.Stacktrace.Frames {
stacktrace += fmt.Sprintf("\n at %s (%s:%v:%v)", frame.Function, frame.Filename, frame.Lineno, frame.Colno)
}
return stacktrace
}
func (exception *frontendSentryException) FmtStacktraces() string {
var stacktraces []string
for _, value := range exception.Values {
stacktraces = append(stacktraces, value.FmtStacktrace())
}
return strings.Join(stacktraces, "\n\n")
}
func addEventContextToLogContext(rootPrefix string, logCtx log15.Ctx, eventCtx map[string]interface{}) {
for key, element := range eventCtx {
prefix := fmt.Sprintf("%s_%s", rootPrefix, key)
switch v := element.(type) {
case map[string]interface{}:
addEventContextToLogContext(prefix, logCtx, v)
default:
logCtx[prefix] = fmt.Sprintf("%v", v)
}
}
}
func (event *frontendSentryEvent) ToLogContext() log15.Ctx {
var ctx = make(log15.Ctx)
ctx["url"] = event.Request.URL
ctx["user_agent"] = event.Request.Headers["User-Agent"]
ctx["event_id"] = event.EventID
ctx["original_timestamp"] = event.Timestamp
if event.Exception != nil {
ctx["stacktrace"] = event.Exception.FmtStacktraces()
}
addEventContextToLogContext("context", ctx, event.Contexts)
if len(event.User.Email) > 0 {
ctx["user_email"] = event.User.Email
ctx["user_id"] = event.User.ID
}
return ctx
}
func (hs *HTTPServer) logFrontendMessage(c *models.ReqContext, event frontendSentryEvent) response.Response {
func NewFrontendLogMessageHandler(store *frontendlogging.SourceMapStore) frontendLogMessageHandler {
return func(c *models.ReqContext, event frontendlogging.FrontendSentryEvent) response.Response {
var msg = "unknown"
if len(event.Message) > 0 {
......@@ -87,7 +22,7 @@ func (hs *HTTPServer) logFrontendMessage(c *models.ReqContext, event frontendSen
msg = event.Exception.Values[0].FmtMessage()
}
var ctx = event.ToLogContext()
var ctx = event.ToLogContext(store)
switch event.Level {
case sentry.LevelError:
......@@ -101,4 +36,5 @@ func (hs *HTTPServer) logFrontendMessage(c *models.ReqContext, event frontendSen
}
return response.Success("ok")
}
}
package api
import (
"errors"
"io/ioutil"
"net/http"
"os"
"strings"
"testing"
"time"
"github.com/getsentry/sentry-go"
"github.com/grafana/grafana/pkg/api/frontendlogging"
"github.com/grafana/grafana/pkg/api/response"
"github.com/grafana/grafana/pkg/api/routing"
"github.com/grafana/grafana/pkg/models"
"github.com/grafana/grafana/pkg/plugins"
"github.com/grafana/grafana/pkg/setting"
log "github.com/inconshreveable/log15"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
)
type logScenarioFunc func(c *scenarioContext, logs []*log.Record)
type SourceMapReadRecord struct {
dir string
path string
}
type logScenarioFunc func(c *scenarioContext, logs []*log.Record, sourceMapReads []SourceMapReadRecord)
func logSentryEventScenario(t *testing.T, desc string, event frontendSentryEvent, fn logScenarioFunc) {
func logSentryEventScenario(t *testing.T, desc string, event frontendlogging.FrontendSentryEvent, fn logScenarioFunc) {
t.Run(desc, func(t *testing.T) {
logs := []*log.Record{}
sourceMapReads := []SourceMapReadRecord{}
origHandler := frontendLogger.GetHandler()
frontendLogger.SetHandler(log.FuncHandler(func(r *log.Record) error {
logs = append(logs, r)
......@@ -30,16 +44,39 @@ func logSentryEventScenario(t *testing.T, desc string, event frontendSentryEvent
})
sc := setupScenarioContext(t, "/log")
hs := HTTPServer{}
cfg := &setting.Cfg{
StaticRootPath: "/staticroot",
}
readSourceMap := func(dir string, path string) ([]byte, error) {
sourceMapReads = append(sourceMapReads, SourceMapReadRecord{
dir: dir,
path: path,
})
if strings.Contains(path, "error") {
return nil, errors.New("epic hard drive failure")
}
if strings.HasSuffix(path, "foo.js.map") {
f, err := ioutil.ReadFile("./frontendlogging/test-data/foo.js.map")
require.NoError(t, err)
return f, nil
}
return nil, os.ErrNotExist
}
sourceMapStore := frontendlogging.NewSourceMapStore(cfg, readSourceMap)
loggingHandler := NewFrontendLogMessageHandler(sourceMapStore)
handler := routing.Wrap(func(w http.ResponseWriter, c *models.ReqContext) response.Response {
sc.context = c
return hs.logFrontendMessage(c, event)
return loggingHandler(c, event)
})
sc.m.Post(sc.url, handler)
sc.fakeReqWithParams("POST", sc.url, map[string]string{}).exec()
fn(sc, logs)
fn(sc, logs, sourceMapReads)
})
}
......@@ -47,6 +84,12 @@ func TestFrontendLoggingEndpoint(t *testing.T) {
ts, err := time.Parse("2006-01-02T15:04:05.000Z", "2020-10-22T06:29:29.078Z")
require.NoError(t, err)
// fake plugin route so we will try to find a source map there. I can't believe I can do this
plugins.StaticRoutes = append(plugins.StaticRoutes, &plugins.PluginStaticRoute{
Directory: "/usr/local/telepathic-panel",
PluginId: "telepathic",
})
t.Run("FrontendLoggingEndpoint", func(t *testing.T) {
request := sentry.Request{
URL: "http://localhost:3000/",
......@@ -60,15 +103,17 @@ func TestFrontendLoggingEndpoint(t *testing.T) {
ID: "45",
}
errorEvent := frontendSentryEvent{
&sentry.Event{
event := sentry.Event{
EventID: "123",
Level: sentry.LevelError,
Request: &request,
Timestamp: ts,
},
&frontendSentryException{
Values: []frontendSentryExceptionValue{
}
errorEvent := frontendlogging.FrontendSentryEvent{
Event: &event,
Exception: &frontendlogging.FrontendSentryException{
Values: []frontendlogging.FrontendSentryExceptionValue{
{
Type: "UserError",
Value: "Please replace user and try again",
......@@ -93,7 +138,7 @@ func TestFrontendLoggingEndpoint(t *testing.T) {
},
}
logSentryEventScenario(t, "Should log received error event", errorEvent, func(sc *scenarioContext, logs []*log.Record) {
logSentryEventScenario(t, "Should log received error event", errorEvent, func(sc *scenarioContext, logs []*log.Record, sourceMapReads []SourceMapReadRecord) {
assert.Equal(t, 200, sc.resp.Code)
assert.Len(t, logs, 1)
assertContextContains(t, logs[0], "logger", "frontend")
......@@ -107,8 +152,8 @@ func TestFrontendLoggingEndpoint(t *testing.T) {
assert.NotContains(t, logs[0].Ctx, "context")
})
messageEvent := frontendSentryEvent{
&sentry.Event{
messageEvent := frontendlogging.FrontendSentryEvent{
Event: &sentry.Event{
EventID: "123",
Level: sentry.LevelInfo,
Request: &request,
......@@ -116,10 +161,10 @@ func TestFrontendLoggingEndpoint(t *testing.T) {
Message: "hello world",
User: user,
},
nil,
Exception: nil,
}
logSentryEventScenario(t, "Should log received message event", messageEvent, func(sc *scenarioContext, logs []*log.Record) {
logSentryEventScenario(t, "Should log received message event", messageEvent, func(sc *scenarioContext, logs []*log.Record, sourceMapReads []SourceMapReadRecord) {
assert.Equal(t, 200, sc.resp.Code)
assert.Len(t, logs, 1)
assert.Equal(t, "hello world", logs[0].Msg)
......@@ -135,8 +180,8 @@ func TestFrontendLoggingEndpoint(t *testing.T) {
assertContextContains(t, logs[0], "user_id", user.ID)
})
eventWithContext := frontendSentryEvent{
&sentry.Event{
eventWithContext := frontendlogging.FrontendSentryEvent{
Event: &sentry.Event{
EventID: "123",
Level: sentry.LevelInfo,
Request: &request,
......@@ -151,16 +196,91 @@ func TestFrontendLoggingEndpoint(t *testing.T) {
"bar": "baz",
},
},
nil,
Exception: nil,
}
logSentryEventScenario(t, "Should log event context", eventWithContext, func(sc *scenarioContext, logs []*log.Record) {
logSentryEventScenario(t, "Should log event context", eventWithContext, func(sc *scenarioContext, logs []*log.Record, sourceMapReads []SourceMapReadRecord) {
assert.Equal(t, 200, sc.resp.Code)
assert.Len(t, logs, 1)
assertContextContains(t, logs[0], "context_foo_one", "two")
assertContextContains(t, logs[0], "context_foo_three", "4")
assertContextContains(t, logs[0], "context_bar", "baz")
})
errorEventForSourceMapping := frontendlogging.FrontendSentryEvent{
Event: &event,
Exception: &frontendlogging.FrontendSentryException{
Values: []frontendlogging.FrontendSentryExceptionValue{
{
Type: "UserError",
Value: "Please replace user and try again",
Stacktrace: sentry.Stacktrace{
Frames: []sentry.Frame{
{
Function: "foofn",
Filename: "http://localhost:3000/public/build/moo/foo.js", // source map found and mapped, core
Lineno: 2,
Colno: 5,
},
{
Function: "foofn",
Filename: "http://localhost:3000/public/plugins/telepathic/foo.js", // plugin, source map found and mapped
Lineno: 3,
Colno: 10,
},
{
Function: "explode",
Filename: "http://localhost:3000/public/build/error.js", // reading source map throws error
Lineno: 3,
Colno: 10,
},
{
Function: "wat",
Filename: "http://localhost:3000/public/build/bar.js", // core, but source map not found on fs
Lineno: 3,
Colno: 10,
},
{
Function: "nope",
Filename: "http://localhost:3000/baz.js", // not core or plugin, wont even attempt to get source map
Lineno: 3,
Colno: 10,
},
{
Function: "fake",
Filename: "http://localhost:3000/public/build/../../secrets.txt", // path will be sanitized
Lineno: 3,
Colno: 10,
},
},
},
},
},
},
}
logSentryEventScenario(t, "Should load sourcemap and transform stacktrace line when possible", errorEventForSourceMapping, func(sc *scenarioContext, logs []*log.Record, sourceMapReads []SourceMapReadRecord) {
assert.Equal(t, 200, sc.resp.Code)
assert.Len(t, logs, 1)
assertContextContains(t, logs[0], "stacktrace", `UserError: Please replace user and try again
at ? (core|webpack:///./some_source.ts:2:2)
at ? (telepathic|webpack:///./some_source.ts:3:2)
at explode (http://localhost:3000/public/build/error.js:3:10)
at wat (http://localhost:3000/public/build/bar.js:3:10)
at nope (http://localhost:3000/baz.js:3:10)
at fake (http://localhost:3000/public/build/../../secrets.txt:3:10)`)
assert.Len(t, sourceMapReads, 5)
assert.Equal(t, "/staticroot", sourceMapReads[0].dir)
assert.Equal(t, "build/moo/foo.js.map", sourceMapReads[0].path)
assert.Equal(t, "/usr/local/telepathic-panel", sourceMapReads[1].dir)
assert.Equal(t, "/foo.js.map", sourceMapReads[1].path)
assert.Equal(t, "/staticroot", sourceMapReads[2].dir)
assert.Equal(t, "build/error.js.map", sourceMapReads[2].path)
assert.Equal(t, "/staticroot", sourceMapReads[3].dir)
assert.Equal(t, "build/bar.js.map", sourceMapReads[3].path)
assert.Equal(t, "/staticroot", sourceMapReads[4].dir)
assert.Equal(t, "secrets.txt.map", sourceMapReads[4].path)
})
})
}
......
package frontendlogging
import (
"fmt"
"strings"
"github.com/getsentry/sentry-go"
"github.com/grafana/grafana/pkg/infra/log"
"github.com/inconshreveable/log15"
)
var logger = log.New("frontendlogging")
type FrontendSentryExceptionValue struct {
Value string `json:"value,omitempty"`
Type string `json:"type,omitempty"`
Stacktrace sentry.Stacktrace `json:"stacktrace,omitempty"`
}
type FrontendSentryException struct {
Values []FrontendSentryExceptionValue `json:"values,omitempty"`
}
type FrontendSentryEvent struct {
*sentry.Event
Exception *FrontendSentryException `json:"exception,omitempty"`
}
func (value *FrontendSentryExceptionValue) FmtMessage() string {
return fmt.Sprintf("%s: %s", value.Type, value.Value)
}
func fmtLine(frame sentry.Frame) string {
module := ""
if len(frame.Module) > 0 {
module = frame.Module + "|"
}
return fmt.Sprintf("\n at %s (%s%s:%v:%v)", frame.Function, module, frame.Filename, frame.Lineno, frame.Colno)
}
func (value *FrontendSentryExceptionValue) FmtStacktrace(store *SourceMapStore) string {
var stacktrace = value.FmtMessage()
for _, frame := range value.Stacktrace.Frames {
mappedFrame, err := store.resolveSourceLocation(frame)
if err != nil {
logger.Error("Error resolving stack trace frame source location", "err", err)
stacktrace += fmtLine(frame) // even if reading source map fails for unexpected reason, still better to log compiled location than nothing at all
} else {
if mappedFrame != nil {
stacktrace += fmtLine(*mappedFrame)
} else {
stacktrace += fmtLine(frame)
}
}
}
return stacktrace
}
func (exception *FrontendSentryException) FmtStacktraces(store *SourceMapStore) string {
var stacktraces []string
for _, value := range exception.Values {
stacktraces = append(stacktraces, value.FmtStacktrace(store))
}
return strings.Join(stacktraces, "\n\n")
}
func addEventContextToLogContext(rootPrefix string, logCtx log15.Ctx, eventCtx map[string]interface{}) {
for key, element := range eventCtx {
prefix := fmt.Sprintf("%s_%s", rootPrefix, key)
switch v := element.(type) {
case map[string]interface{}:
addEventContextToLogContext(prefix, logCtx, v)
default:
logCtx[prefix] = fmt.Sprintf("%v", v)
}
}
}
func (event *FrontendSentryEvent) ToLogContext(store *SourceMapStore) log15.Ctx {
var ctx = make(log15.Ctx)
ctx["url"] = event.Request.URL
ctx["user_agent"] = event.Request.Headers["User-Agent"]
ctx["event_id"] = event.EventID
ctx["original_timestamp"] = event.Timestamp
if event.Exception != nil {
ctx["stacktrace"] = event.Exception.FmtStacktraces(store)
}
addEventContextToLogContext("context", ctx, event.Contexts)
if len(event.User.Email) > 0 {
ctx["user_email"] = event.User.Email
ctx["user_id"] = event.User.ID
}
return ctx
}
package frontendlogging
import (
"io/ioutil"
"net/http"
"net/url"
"os"
"path/filepath"
"strings"
"sync"
sourcemap "github.com/go-sourcemap/sourcemap"
"github.com/getsentry/sentry-go"
"github.com/grafana/grafana/pkg/plugins"
"github.com/grafana/grafana/pkg/setting"
)
type sourceMapLocation struct {
dir string
path string
pluginID string
}
type sourceMap struct {
consumer *sourcemap.Consumer
pluginID string
}
type ReadSourceMapFn func(dir string, path string) ([]byte, error)
func ReadSourceMapFromFS(dir string, path string) ([]byte, error) {
file, err := http.Dir(dir).Open(path)
if err != nil {
return nil, err
}
defer func() {
if err := file.Close(); err != nil {
logger.Error("Failed to close source map file", "err", err)
}
}()
return ioutil.ReadAll(file)
}
type SourceMapStore struct {
cache map[string]*sourceMap
cfg *setting.Cfg
readSourceMap ReadSourceMapFn
sync.Mutex
}
func NewSourceMapStore(cfg *setting.Cfg, readSourceMap ReadSourceMapFn) *SourceMapStore {
return &SourceMapStore{
cache: make(map[string]*sourceMap),
cfg: cfg,
readSourceMap: readSourceMap,
}
}
/* guessSourceMapLocation will attempt to guess location of a source map on fs.
* it does not read the source file or make any web requests,
* just assumes that a [source filename].map file might exist in the same dir as the source file
* and only considers sources coming from grafana core or plugins`
*/
func (store *SourceMapStore) guessSourceMapLocation(sourceURL string) (*sourceMapLocation, error) {
u, err := url.Parse(sourceURL)
if err != nil {
return nil, err
}
// determine if source comes from grafana core, look in public build dir
if strings.HasPrefix(u.Path, "/public/build/") {
return &sourceMapLocation{
dir: store.cfg.StaticRootPath,
path: filepath.Join("build", u.Path[len("/public/build/"):]) + ".map",
pluginID: "",
}, nil
// if source comes from a plugin, look in plugin dir
} else if strings.HasPrefix(u.Path, "/public/plugins/") {
for _, route := range plugins.StaticRoutes {
pluginPrefix := filepath.Join("/public/plugins/", route.PluginId)
if strings.HasPrefix(u.Path, pluginPrefix) {
return &sourceMapLocation{
dir: route.Directory,
path: u.Path[len(pluginPrefix):] + ".map",
pluginID: route.PluginId,
}, nil
}
}
}
return nil, nil
}
func (store *SourceMapStore) getSourceMap(sourceURL string) (*sourceMap, error) {
store.Lock()
defer store.Unlock()
if smap, ok := store.cache[sourceURL]; ok {
return smap, nil
}
sourceMapLocation, err := store.guessSourceMapLocation(sourceURL)
if err != nil {
return nil, err
}
if sourceMapLocation == nil {
// Cache nil value for sourceURL, since we want to flag that we couldn't guess the map location and not try again
store.cache[sourceURL] = nil
return nil, nil
}
path := strings.ReplaceAll(sourceMapLocation.path, "../", "") // just in case
b, err := store.readSourceMap(sourceMapLocation.dir, path)
if err != nil {
if os.IsNotExist(err) {
// Cache nil value for sourceURL, since we want to flag that it wasn't found in the filesystem and not try again
store.cache[sourceURL] = nil
return nil, nil
}
return nil, err
}
consumer, err := sourcemap.Parse(sourceURL+".map", b)
if err != nil {
return nil, err
}
smap := &sourceMap{
consumer: consumer,
pluginID: sourceMapLocation.pluginID,
}
store.cache[sourceURL] = smap
return smap, nil
}
func (store *SourceMapStore) resolveSourceLocation(frame sentry.Frame) (*sentry.Frame, error) {
smap, err := store.getSourceMap(frame.Filename)
if err != nil {
return nil, err
}
if smap == nil {
return nil, nil
}
file, function, line, col, ok := smap.consumer.Source(frame.Lineno, frame.Colno)
if !ok {
return nil, nil
}
// unfortunately in many cases go-sourcemap fails to determine the original function name.
// not a big issue as long as file, line and column are correct
if len(function) == 0 {
function = "?"
}
module := "core"
if len(smap.pluginID) > 0 {
module = smap.pluginID
}
return &sentry.Frame{
Filename: file,
Lineno: line,
Colno: col,
Function: function,
Module: module,
}, nil
}
{"version":3,"file":"some_source.js","sourceRoot":"","sources":["webpack:///./some_source.ts"],"names":[],"mappings":"AAAA,SAAS,GAAG;IACV,IAAM,GAAG,GAAG,GAAG,CAAC;IAChB,OAAO,GAAG,CAAC;AACb,CAAC"}
\ No newline at end of file
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment