Improves panic reports to scope and fixes source field on events (#170)

* Improves panic reports to scope and fixes source field on events

* restore missing method

* changes

* Changes based in the review

* fixes after rebase

* path fixes after rebase

Author: tonyredondo

agent/agent.go

@@ -292,10 +292,12 @@ func NewAgent(options ...Option) (*Agent, error) {
 	agent.metadata[tags.Dependencies] = getDependencyMap()
 
 	// Expand '~' in source root
+	var sourceRoot string
 	if sRoot, ok := agent.metadata[tags.SourceRoot]; ok {
 		cSRoot := sRoot.(string)
 		cSRoot = filepath.Clean(cSRoot)
 		if sRootEx, err := homedir.Expand(cSRoot); err == nil {
+			sourceRoot = sRootEx
 			agent.metadata[tags.SourceRoot] = sRootEx
 		}
 	}
@@ -335,10 +337,11 @@ func NewAgent(options ...Option) (*Agent, error) {
 		},
 		MaxLogsPerSpan: 10000,
 		// Log the error in the current span
-		OnSpanFinishPanic: scopeError.LogErrorInRawSpan,
+		OnSpanFinishPanic: scopeError.WriteExceptionEventInRawSpan,
 	})
 	instrumentation.SetTracer(agent.tracer)
 	instrumentation.SetLogger(agent.logger)
+	instrumentation.SetSourceRoot(sourceRoot)
 	if agent.setGlobalTracer || env.ScopeTracerGlobal.Value {
 		opentracing.SetGlobalTracer(agent.Tracer())
 	}
@@ -352,7 +355,7 @@ func (a *Agent) setupLogging() error {
 	if err != nil {
 		return err
 	}
-	a.recorderFilename = path.Join(dir, filename)
+	a.recorderFilename = filepath.Join(dir, filename)
 
 	file, err := os.OpenFile(a.recorderFilename, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666)
 	if err != nil {
@@ -442,7 +445,7 @@ func getLogPath() (string, error) {
 	}
 
 	// If the log folder can't be used we return a temporal path, so we don't miss the agent logs
-	logFolder = path.Join(os.TempDir(), "scope")
+	logFolder = filepath.Join(os.TempDir(), "scope")
 	if _, err := os.Stat(logFolder); err == nil {
 		return logFolder, nil
 	} else if os.IsNotExist(err) && os.Mkdir(logFolder, 0755) == nil {

errors/handler.go

@@ -1,6 +1,7 @@
 package errors
 
 import (
+	"context"
 	"fmt"
 	"path/filepath"
 	"strings"
@@ -10,6 +11,8 @@ import (
 	"github.com/opentracing/opentracing-go"
 	"github.com/opentracing/opentracing-go/log"
 
+	"go.undefinedlabs.com/scopeagent/instrumentation"
+	"go.undefinedlabs.com/scopeagent/tags"
 	"go.undefinedlabs.com/scopeagent/tracer"
 )
 
@@ -28,32 +31,33 @@ type StackFrames struct {
 	Package    string
 }
 
-var MarkSpanAsError = errors.New("")
+var markSpanAsError = errors.New("")
 
 // Write exception event in span using the recover data from panic
-func LogError(span opentracing.Span, recoverData interface{}, skipFrames int) {
-	var exceptionFields = getExceptionLogFields(recoverData, skipFrames+1)
-	span.LogFields(exceptionFields...)
+func WriteExceptionEvent(span opentracing.Span, recoverData interface{}, skipFrames int) {
 	span.SetTag("error", true)
+	if recoverData == markSpanAsError {
+		return
+	}
+	var exceptionFields = getExceptionLogFields("error", recoverData, skipFrames+1)
+	span.LogFields(exceptionFields...)
 }
 
-func LogErrorInRawSpan(rawSpan *tracer.RawSpan, err **errors.Error) {
+func WriteExceptionEventInRawSpan(rawSpan *tracer.RawSpan, err **errors.Error) {
 	if rawSpan.Tags == nil {
 		rawSpan.Tags = opentracing.Tags{}
 	}
-	if *err == MarkSpanAsError {
-		rawSpan.Tags["error"] = true
-	} else {
-		var exceptionFields = getExceptionLogFields(*err, 1)
+	rawSpan.Tags["error"] = true
+	if *err != markSpanAsError {
+		var exceptionFields = getExceptionLogFields("error", *err, 1)
 		if rawSpan.Logs == nil {
 			rawSpan.Logs = []opentracing.LogRecord{}
 		}
 		rawSpan.Logs = append(rawSpan.Logs, opentracing.LogRecord{
 			Timestamp: time.Now(),
 			Fields:    exceptionFields,
 		})
-		rawSpan.Tags["error"] = true
-		*err = MarkSpanAsError
+		*err = markSpanAsError
 	}
 }
 
@@ -80,6 +84,17 @@ func getCurrentStackFrames(skip int) []StackFrames {
 	return stackFrames
 }
 
+// Write log event with stacktrace in span using the recover data from panic
+func LogPanic(ctx context.Context, recoverData interface{}, skipFrames int) {
+	span := opentracing.SpanFromContext(ctx)
+	if span == nil {
+		return
+	}
+	var exceptionFields = getExceptionLogFields(tags.LogEvent, recoverData, skipFrames+1)
+	exceptionFields = append(exceptionFields, log.String(tags.LogEventLevel, tags.LogLevel_ERROR))
+	span.LogFields(exceptionFields...)
+}
+
 // Gets the current stacktrace
 func GetCurrentStackTrace(skip int) map[string]interface{} {
 	var exFrames []map[string]interface{}
@@ -101,25 +116,27 @@ func GetCurrentError(recoverData interface{}) *errors.Error {
 	return errors.Wrap(recoverData, 1)
 }
 
-func getExceptionLogFields(recoverData interface{}, skipFrames int) []log.Field {
+func getExceptionLogFields(eventType string, recoverData interface{}, skipFrames int) []log.Field {
 	if recoverData != nil {
 		err := errors.Wrap(recoverData, 2+skipFrames)
 		errMessage := err.Error()
-		errStack := err.StackFrames() //filterStackFrames(err.StackFrames())
+		errStack := err.StackFrames()
 		exceptionData := getExceptionFrameData(errMessage, errStack)
 		source := ""
 
 		if errStack != nil && len(errStack) > 0 {
+			sourceRoot := instrumentation.GetSourceRoot()
 			for _, currentFrame := range errStack {
-				if currentFrame.Package != "runtime" && currentFrame.File != "" {
+				dir := filepath.Dir(currentFrame.File)
+				if strings.Index(dir, sourceRoot) != -1 {
 					source = fmt.Sprintf("%s:%d", currentFrame.File, currentFrame.LineNumber)
 					break
 				}
 			}
 		}
 
 		fields := make([]log.Field, 5)
-		fields[0] = log.String(EventType, "error")
+		fields[0] = log.String(EventType, eventType)
 		fields[1] = log.String(EventSource, source)
 		fields[2] = log.String(EventMessage, errMessage)
 		fields[3] = log.String(EventStack, getStringStack(err, errStack))
@@ -137,18 +154,6 @@ func getStringStack(err *errors.Error, errStack []errors.StackFrame) string {
 	return fmt.Sprintf("[%s]: %s\n\n%s", err.TypeName(), err.Error(), strings.Join(frames, ""))
 }
 
-// Filter stack frames from the go-agent
-func filterStackFrames(errStack []errors.StackFrame) []errors.StackFrame {
-	var stack []errors.StackFrame
-	for _, frame := range errStack {
-		if strings.Contains(frame.Package, "undefinedlabs/go-agent") {
-			continue
-		}
-		stack = append(stack, frame)
-	}
-	return stack
-}
-
 func getExceptionFrameData(errMessage string, errStack []errors.StackFrame) map[string]interface{} {
 	var exFrames []map[string]interface{}
 	for _, frame := range errStack {

instrumentation/nethttp/server.go

@@ -181,9 +181,7 @@ func middlewareFunc(tr opentracing.Tracer, h http.HandlerFunc, options ...MWOpti
 			}
 
 			if r := recover(); r != nil {
-				if r != errors.MarkSpanAsError {
-					errors.LogError(sp, r, 1)
-				}
+				errors.WriteExceptionEvent(sp, r, 1)
 				sp.Finish()
 				panic(r)
 			}

instrumentation/testing/tb.go

@@ -2,10 +2,14 @@ package testing
 
 import (
 	"fmt"
-	"github.com/opentracing/opentracing-go/log"
-	"go.undefinedlabs.com/scopeagent/tags"
 	"path/filepath"
 	"runtime"
+
+	"github.com/opentracing/opentracing-go/log"
+
+	"go.undefinedlabs.com/scopeagent/errors"
+	"go.undefinedlabs.com/scopeagent/instrumentation"
+	"go.undefinedlabs.com/scopeagent/tags"
 )
 
 // ***************************
@@ -217,15 +221,19 @@ func (test *Test) Helper() {
 	test.t.Helper()
 }
 
+// Log panic data with stacktrace
+func (test *Test) LogPanic(recoverData interface{}, skipFrames int) {
+	errors.LogPanic(test.ctx, recoverData, skipFrames+1)
+}
+
 func getSourceFileAndNumber() string {
 	var source string
-	if pc, file, line, ok := runtime.Caller(2); ok == true {
+	if pc, file, line, ok := instrumentation.GetCallerInsideSourceRoot(2); ok == true {
 		pcEntry := runtime.FuncForPC(pc).Entry()
 		// Try to detect the patch function
 		if isAPatchPointer(pcEntry) {
 			// The monkey patching version adds 4 frames to the stack.
-			if _, file, line, ok := runtime.Caller(6); ok == true {
-				file = filepath.Clean(file)
+			if _, file, line, ok := instrumentation.GetCallerInsideSourceRoot(6); ok == true {
 				source = fmt.Sprintf("%s:%d", file, line)
 			}
 		} else {

instrumentation/testing/testing.go

@@ -172,10 +172,7 @@ func (test *Test) end() {
 
 	if r := recover(); r != nil {
 		test.span.SetTag("test.status", tags.TestStatus_FAIL)
-		test.span.SetTag("error", true)
-		if r != errors.MarkSpanAsError {
-			errors.LogError(test.span, r, 1)
-		}
+		errors.WriteExceptionEvent(test.span, r, 1)
 		test.span.FinishWithOptions(finishOptions)
 		panic(r)
 	}
@@ -262,8 +259,7 @@ func PanicAllRunningTests(e interface{}, skip int) {
 	for _, v := range tmp {
 		delete(autoInstrumentedTests, v.t)
 		v.t.Fail()
-		v.span.SetTag("error", true)
-		errors.LogError(v.span, e, 1+skip)
+		errors.WriteExceptionEvent(v.span, e, 1+skip)
 		v.end()
 	}
 }

instrumentation/tracer.go

@@ -1,15 +1,20 @@
 package instrumentation
 
 import (
-	"github.com/opentracing/opentracing-go"
 	"io/ioutil"
 	"log"
+	"path/filepath"
+	"runtime"
+	"strings"
 	"sync"
+
+	"github.com/opentracing/opentracing-go"
 )
 
 var (
-	tracer opentracing.Tracer = opentracing.NoopTracer{}
-	logger                    = log.New(ioutil.Discard, "", 0)
+	tracer     opentracing.Tracer = opentracing.NoopTracer{}
+	logger                        = log.New(ioutil.Discard, "", 0)
+	sourceRoot                    = ""
 
 	m sync.RWMutex
 )
@@ -41,3 +46,37 @@ func Logger() *log.Logger {
 
 	return logger
 }
+
+func SetSourceRoot(root string) {
+	m.Lock()
+	defer m.Unlock()
+
+	sourceRoot = root
+}
+
+func GetSourceRoot() string {
+	m.RLock()
+	defer m.RUnlock()
+
+	return sourceRoot
+}
+
+//go:noinline
+func GetCallerInsideSourceRoot(skip int) (pc uintptr, file string, line int, ok bool) {
+	pcs := make([]uintptr, 64)
+	count := runtime.Callers(skip+2, pcs)
+	pcs = pcs[0:count]
+	frames := runtime.CallersFrames(pcs)
+	for {
+		frame, more := frames.Next()
+		file := filepath.Clean(frame.File)
+		dir := filepath.Dir(file)
+		if strings.Index(dir, sourceRoot) != -1 {
+			return frame.PC, file, frame.Line, true
+		}
+		if !more {
+			break
+		}
+	}
+	return
+}