From b7cd1efa617715d7f4e8a2f641aa84bf23d75e63 Mon Sep 17 00:00:00 2001 From: Daniel Redondo Date: Sun, 31 May 2020 23:27:49 +0200 Subject: [PATCH 01/11] different test logging instrumentation approach --- instrumentation/testing/logger.go | 307 ++++++++++++++++-------- instrumentation/testing/logger.s | 0 instrumentation/testing/tb.go | 76 +----- instrumentation/testing/testing_test.go | 15 +- 4 files changed, 224 insertions(+), 174 deletions(-) create mode 100644 instrumentation/testing/logger.s diff --git a/instrumentation/testing/logger.go b/instrumentation/testing/logger.go index 7603de81..350c5b7b 100644 --- a/instrumentation/testing/logger.go +++ b/instrumentation/testing/logger.go @@ -1,32 +1,55 @@ package testing import ( - "reflect" + "fmt" + "go.undefinedlabs.com/scopeagent/reflection" "sync" "testing" - "unsafe" + _ "unsafe" + "github.com/opentracing/opentracing-go/log" "github.com/undefinedlabs/go-mpatch" "go.undefinedlabs.com/scopeagent/instrumentation" - "go.undefinedlabs.com/scopeagent/reflection" + "go.undefinedlabs.com/scopeagent/tags" ) var ( - commonPtr reflect.Type // *testing.common type patchLock sync.Mutex - patchesMutex sync.RWMutex - patches = map[string]*mpatch.Patch{} // patches - patchPointersMutex sync.RWMutex - patchPointers = map[uintptr]bool{} // pointers of patch funcs + + errorPatch *mpatch.Patch + errorfPatch *mpatch.Patch + fatalPatch *mpatch.Patch + fatalfPatch *mpatch.Patch + logPatch *mpatch.Patch + logfPatch *mpatch.Patch + skipPatch *mpatch.Patch + skipfPatch *mpatch.Patch ) -func init() { - // We get the *testing.common type to use in the patch method - if cPtr, err := reflection.GetTypePointer(testing.T{}, "common"); err == nil { - commonPtr = cPtr - } -} +//go:linkname lError testing.(*common).Error +func lError(t *testing.T, args ...interface{}) + +//go:linkname lErrorf testing.(*common).Errorf +func lErrorf(t *testing.T, format string, args ...interface{}) + +//go:linkname lFatal testing.(*common).Fatal +func lFatal(t *testing.T, args ...interface{}) + +//go:linkname lFatalf testing.(*common).Fatalf +func lFatalf(t *testing.T, format string, args ...interface{}) + +//go:linkname lLog testing.(*common).Log +func lLog(t *testing.T, args ...interface{}) + +//go:linkname lLogf testing.(*common).Logf +func lLogf(t *testing.T, format string, args ...interface{}) + +//go:linkname lSkip testing.(*common).Skip +func lSkip(t *testing.T, args ...interface{}) + +//go:linkname lSkipf testing.(*common).Skipf +func lSkipf(t *testing.T, format string, args ...interface{}) func PatchTestingLogger() { patchError() @@ -42,132 +65,237 @@ func PatchTestingLogger() { func UnpatchTestingLogger() { patchLock.Lock() defer patchLock.Unlock() - patchPointersMutex.Lock() - defer patchPointersMutex.Unlock() - for _, patch := range patches { - logOnError(patch.Unpatch()) + + if errorPatch != nil { + logOnError(errorPatch.Unpatch()) + } + if errorfPatch != nil { + logOnError(errorfPatch.Unpatch()) + } + if fatalPatch != nil { + logOnError(fatalPatch.Unpatch()) + } + if fatalfPatch != nil { + logOnError(fatalfPatch.Unpatch()) + } + if logPatch != nil { + logOnError(logPatch.Unpatch()) + } + if logfPatch != nil { + logOnError(logfPatch.Unpatch()) + } + if skipPatch != nil { + logOnError(skipPatch.Unpatch()) + } + if skipfPatch != nil { + logOnError(skipfPatch.Unpatch()) } - patches = map[string]*mpatch.Patch{} - patchPointers = map[uintptr]bool{} } func patchError() { - patch("Error", func(test *Test, args []interface{}) { + patchWithArgs(&errorPatch, lError, func(test *Test, args ...interface{}) { test.t.Helper() - test.Error(args...) + test.span.LogFields( + log.String(tags.EventType, tags.LogEvent), + log.String(tags.EventMessage, fmt.Sprint(args...)), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.LogEventLevel, tags.LogLevel_ERROR), + log.String("log.internal_level", "Error"), + log.String("log.logger", "testing"), + ) + }, func(t *testing.T, args ...interface{}) { + t.Helper() + t.Error(args) }) } func patchErrorf() { - patch("Errorf", func(test *Test, args []interface{}) { + patchWithFormatAndArgs(&errorfPatch, lErrorf, func(test *Test, format string, args ...interface{}) { test.t.Helper() - format := args[0].(string) - test.Errorf(format, args[1:]...) + test.span.LogFields( + log.String(tags.EventType, tags.LogEvent), + log.String(tags.EventMessage, fmt.Sprintf(format, args...)), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.LogEventLevel, tags.LogLevel_ERROR), + log.String("log.internal_level", "Error"), + log.String("log.logger", "testing"), + ) + }, func(t *testing.T, format string, args ...interface{}) { + t.Helper() + t.Errorf(format, args) }) } func patchFatal() { - patch("Fatal", func(test *Test, args []interface{}) { + patchWithArgs(&fatalPatch, lFatal, func(test *Test, args ...interface{}) { test.t.Helper() - test.Fatal(args...) + test.span.LogFields( + log.String(tags.EventType, tags.EventTestFailure), + log.String(tags.EventMessage, fmt.Sprint(args...)), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String("log.internal_level", "Fatal"), + log.String("log.logger", "testing"), + ) + }, func(t *testing.T, args ...interface{}) { + t.Helper() + t.Fatal(args) }) } func patchFatalf() { - patch("Fatalf", func(test *Test, args []interface{}) { + patchWithFormatAndArgs(&fatalfPatch, lFatalf, func(test *Test, format string, args ...interface{}) { test.t.Helper() - format := args[0].(string) - test.Fatalf(format, args[1:]...) + test.span.LogFields( + log.String(tags.EventType, tags.EventTestFailure), + log.String(tags.EventMessage, fmt.Sprintf(format, args...)), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String("log.internal_level", "Fatal"), + log.String("log.logger", "testing"), + ) + }, func(t *testing.T, format string, args ...interface{}) { + t.Helper() + t.Fatalf(format, args) }) } func patchLog() { - patch("Log", func(test *Test, args []interface{}) { + patchWithArgs(&logPatch, lLog, func(test *Test, args ...interface{}) { test.t.Helper() - test.Log(args...) + test.span.LogFields( + log.String(tags.EventType, tags.LogEvent), + log.String(tags.EventMessage, fmt.Sprint(args...)), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.LogEventLevel, tags.LogLevel_INFO), + log.String("log.internal_level", "Log"), + log.String("log.logger", "testing"), + ) + }, func(t *testing.T, args ...interface{}) { + t.Helper() + t.Log(args) }) } func patchLogf() { - patch("Logf", func(test *Test, args []interface{}) { + patchWithFormatAndArgs(&logfPatch, lLogf, func(test *Test, format string, args ...interface{}) { test.t.Helper() - format := args[0].(string) - test.Logf(format, args[1:]...) + test.span.LogFields( + log.String(tags.EventType, tags.LogEvent), + log.String(tags.EventMessage, fmt.Sprintf(format, args...)), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.LogEventLevel, tags.LogLevel_INFO), + log.String("log.internal_level", "Log"), + log.String("log.logger", "testing"), + ) + }, func(t *testing.T, format string, args ...interface{}) { + t.Helper() + t.Logf(format, args) }) } func patchSkip() { - patch("Skip", func(test *Test, args []interface{}) { + patchWithArgs(&skipPatch, lSkip, func(test *Test, args ...interface{}) { test.t.Helper() - test.Skip(args...) + test.span.LogFields( + log.String(tags.EventType, tags.EventTestSkip), + log.String(tags.EventMessage, fmt.Sprint(args...)), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String("log.internal_level", "Skip"), + log.String("log.logger", "testing"), + ) + }, func(t *testing.T, args ...interface{}) { + t.Helper() + t.Skip(args) }) } func patchSkipf() { - patch("Skipf", func(test *Test, args []interface{}) { + patchWithFormatAndArgs(&skipfPatch, lSkipf, func(test *Test, format string, args ...interface{}) { test.t.Helper() - format := args[0].(string) - test.Skipf(format, args[1:]...) + test.span.LogFields( + log.String(tags.EventType, tags.EventTestSkip), + log.String(tags.EventMessage, fmt.Sprintf(format, args...)), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String("log.internal_level", "Skip"), + log.String("log.logger", "testing"), + ) + }, func(t *testing.T, format string, args ...interface{}) { + t.Helper() + t.Skipf(format, args) }) } -func createArgs(in []reflect.Value) []interface{} { - var args []interface{} - for _, item := range in { - if item.Kind() == reflect.Slice { - var itemArg []interface{} - for i := 0; i < item.Len(); i++ { - itemArg = append(itemArg, item.Index(i).Interface()) - } - args = append(args, itemArg) +func patchWithArgs(patchValue **mpatch.Patch, method interface{}, + spanFunc func(test *Test, args ...interface{}), + oFunc func(t *testing.T, args ...interface{})) { + + lPatch, err := mpatch.PatchMethod(method, func(t *testing.T, args ...interface{}) { + if t == nil { + instrumentation.Logger().Println("testing.T is nil") + return + } + t.Helper() + test := GetTest(t) + if test == nil { + instrumentation.Logger().Printf("test struct for %v doesn't exist\n", t.Name()) + return + } + if test.span != nil { + spanFunc(test, args...) + } + mu := reflection.GetTestMutex(test.t) + if mu != nil { + mu.Lock() + (*patchValue).Unpatch() + mu.Unlock() + oFunc(t, args...) + mu.Lock() + (*patchValue).Patch() + mu.Unlock() } else { - args = append(args, item.Interface()) + (*patchValue).Unpatch() + oFunc(t, args...) + (*patchValue).Patch() } - } - return args + }) + logOnError(err) + *patchValue = lPatch } -func patch(methodName string, methodBody func(test *Test, argsValues []interface{})) { - patchesMutex.Lock() - defer patchesMutex.Unlock() - patchPointersMutex.Lock() - defer patchPointersMutex.Unlock() +func patchWithFormatAndArgs(patchValue **mpatch.Patch, method interface{}, + spanFunc func(test *Test, format string, args ...interface{}), + oFunc func(t *testing.T, format string, args ...interface{})) { - var method reflect.Method - var ok bool - if method, ok = commonPtr.MethodByName(methodName); !ok { - return - } - - var methodPatch *mpatch.Patch - var err error - methodPatch, err = mpatch.PatchMethodWithMakeFunc(method, func(in []reflect.Value) []reflect.Value { - argIn := createArgs(in[1:]) - t := (*testing.T)(unsafe.Pointer(in[0].Pointer())) + lPatch, err := mpatch.PatchMethod(method, func(t *testing.T, format string, args ...interface{}) { if t == nil { instrumentation.Logger().Println("testing.T is nil") - return nil + return } - t.Helper() - reflection.AddToHelpersMap(t, []string{ - "reflect.callReflect", - "reflect.makeFuncStub", - }) - test := GetTest(t) if test == nil { instrumentation.Logger().Printf("test struct for %v doesn't exist\n", t.Name()) - return nil + return + } + if test.span != nil { + spanFunc(test, format, args...) + } + mu := reflection.GetTestMutex(test.t) + if mu != nil { + mu.Lock() + (*patchValue).Unpatch() + mu.Unlock() + oFunc(t, format, args...) + mu.Lock() + (*patchValue).Patch() + mu.Unlock() + } else { + (*patchValue).Unpatch() + oFunc(t, format, args...) + (*patchValue).Patch() } - methodBody(test, argIn) - return nil }) logOnError(err) - if err == nil { - patches[methodName] = methodPatch - patchPointers[reflect.ValueOf(methodBody).Pointer()] = true - } + *patchValue = lPatch } func logOnError(err error) { @@ -175,18 +303,3 @@ func logOnError(err error) { instrumentation.Logger().Println(err) } } - -func isAPatchPointer(ptr uintptr) bool { - patchPointersMutex.RLock() - defer patchPointersMutex.RUnlock() - if _, ok := patchPointers[ptr]; ok { - return true - } - return false -} - -func getMethodPatch(methodName string) *mpatch.Patch { - patchesMutex.RLock() - defer patchesMutex.RUnlock() - return patches[methodName] -} diff --git a/instrumentation/testing/logger.s b/instrumentation/testing/logger.s new file mode 100644 index 00000000..e69de29b diff --git a/instrumentation/testing/tb.go b/instrumentation/testing/tb.go index 269a958e..f5af9f26 100644 --- a/instrumentation/testing/tb.go +++ b/instrumentation/testing/tb.go @@ -2,10 +2,8 @@ package testing import ( "fmt" - "path/filepath" - "runtime" - "github.com/opentracing/opentracing-go/log" + "path/filepath" "go.undefinedlabs.com/scopeagent/errors" "go.undefinedlabs.com/scopeagent/instrumentation" @@ -17,13 +15,6 @@ import ( func (test *Test) private() {} func (test *Test) Error(args ...interface{}) { - methodPatch := getMethodPatch("Error") - if methodPatch != nil { - patchesMutex.Lock() - defer patchesMutex.Unlock() - methodPatch.Unpatch() - defer methodPatch.Patch() - } test.t.Helper() if test.span != nil { test.span.LogFields( @@ -39,13 +30,6 @@ func (test *Test) Error(args ...interface{}) { } func (test *Test) Errorf(format string, args ...interface{}) { - methodPatch := getMethodPatch("Errorf") - if methodPatch != nil { - patchesMutex.Lock() - defer patchesMutex.Unlock() - methodPatch.Unpatch() - defer methodPatch.Patch() - } test.t.Helper() if test.span != nil { test.span.LogFields( @@ -76,13 +60,6 @@ func (test *Test) Failed() bool { } func (test *Test) Fatal(args ...interface{}) { - methodPatch := getMethodPatch("Fatal") - if methodPatch != nil { - patchesMutex.Lock() - defer patchesMutex.Unlock() - methodPatch.Unpatch() - defer methodPatch.Patch() - } test.t.Helper() if test.span != nil { test.span.LogFields( @@ -97,13 +74,6 @@ func (test *Test) Fatal(args ...interface{}) { } func (test *Test) Fatalf(format string, args ...interface{}) { - methodPatch := getMethodPatch("Fatalf") - if methodPatch != nil { - patchesMutex.Lock() - defer patchesMutex.Unlock() - methodPatch.Unpatch() - defer methodPatch.Patch() - } test.t.Helper() if test.span != nil { test.span.LogFields( @@ -118,13 +88,6 @@ func (test *Test) Fatalf(format string, args ...interface{}) { } func (test *Test) Log(args ...interface{}) { - methodPatch := getMethodPatch("Log") - if methodPatch != nil { - patchesMutex.Lock() - defer patchesMutex.Unlock() - methodPatch.Unpatch() - defer methodPatch.Patch() - } test.t.Helper() if test.span != nil { test.span.LogFields( @@ -140,13 +103,6 @@ func (test *Test) Log(args ...interface{}) { } func (test *Test) Logf(format string, args ...interface{}) { - methodPatch := getMethodPatch("Logf") - if methodPatch != nil { - patchesMutex.Lock() - defer patchesMutex.Unlock() - methodPatch.Unpatch() - defer methodPatch.Patch() - } test.t.Helper() if test.span != nil { test.span.LogFields( @@ -166,13 +122,6 @@ func (test *Test) Name() string { } func (test *Test) Skip(args ...interface{}) { - methodPatch := getMethodPatch("Skip") - if methodPatch != nil { - patchesMutex.Lock() - defer patchesMutex.Unlock() - methodPatch.Unpatch() - defer methodPatch.Patch() - } test.t.Helper() if test.span != nil { test.span.LogFields( @@ -192,13 +141,6 @@ func (test *Test) SkipNow() { } func (test *Test) Skipf(format string, args ...interface{}) { - methodPatch := getMethodPatch("Skipf") - if methodPatch != nil { - patchesMutex.Lock() - defer patchesMutex.Unlock() - methodPatch.Unpatch() - defer methodPatch.Patch() - } test.t.Helper() if test.span != nil { test.span.LogFields( @@ -228,19 +170,9 @@ func (test *Test) LogPanic(recoverData interface{}, skipFrames int) { func getSourceFileAndNumber() string { var source string - 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 := instrumentation.GetCallerInsideSourceRoot(6); ok == true { - source = fmt.Sprintf("%s:%d", file, line) - } - } else { - // If we don't have monkey patching then we skip 2 frames - file = filepath.Clean(file) - source = fmt.Sprintf("%s:%d", file, line) - } + if _, file, line, ok := instrumentation.GetCallerInsideSourceRoot(2); ok == true { + file = filepath.Clean(file) + source = fmt.Sprintf("%s:%d", file, line) } return source } diff --git a/instrumentation/testing/testing_test.go b/instrumentation/testing/testing_test.go index d9dae4d5..40f7748d 100644 --- a/instrumentation/testing/testing_test.go +++ b/instrumentation/testing/testing_test.go @@ -66,16 +66,21 @@ func BenchmarkLoggerPatcher(b *testing.B) { func TestLoggerPatcher(t *testing.T) { tm := time.Now() PatchTestingLogger() - wg := sync.WaitGroup{} - for i := 0; i < 1000; i++ { - wg.Add(1) + //wg := sync.WaitGroup{} + for i := 0; i < 10000; i++ { + //wg.Add(1) go func(x int) { - defer wg.Done() + //defer wg.Done() + //for j:=0; j <100; j++ { t.Log(fmt.Sprintf("Hello world %d", x)) + //t.Logf("Hello world %d", x) + //} }(i) } - wg.Wait() + //wg.Wait() + <-time.After(200 * time.Millisecond) UnpatchTestingLogger() + <-time.After(200 * time.Millisecond) if time.Since(tm) > 2*time.Second { t.Fatal("Test is too slow") } From 904ad18c4b7c2cd7d9a766384fd348a95d949370 Mon Sep 17 00:00:00 2001 From: Daniel Redondo Date: Sun, 31 May 2020 23:54:50 +0200 Subject: [PATCH 02/11] testing logging algorithm change --- instrumentation/testing/logger.go | 329 +++++------------------- instrumentation/testing/tb.go | 6 + instrumentation/testing/testing_test.go | 13 +- 3 files changed, 68 insertions(+), 280 deletions(-) diff --git a/instrumentation/testing/logger.go b/instrumentation/testing/logger.go index 350c5b7b..0e985347 100644 --- a/instrumentation/testing/logger.go +++ b/instrumentation/testing/logger.go @@ -1,8 +1,8 @@ package testing import ( - "fmt" - "go.undefinedlabs.com/scopeagent/reflection" + "runtime" + "strings" "sync" "testing" _ "unsafe" @@ -15,287 +15,74 @@ import ( ) var ( - patchLock sync.Mutex - - errorPatch *mpatch.Patch - errorfPatch *mpatch.Patch - fatalPatch *mpatch.Patch - fatalfPatch *mpatch.Patch - logPatch *mpatch.Patch - logfPatch *mpatch.Patch - skipPatch *mpatch.Patch - skipfPatch *mpatch.Patch + patchLock sync.Mutex + llogPatch *mpatch.Patch ) -//go:linkname lError testing.(*common).Error -func lError(t *testing.T, args ...interface{}) - -//go:linkname lErrorf testing.(*common).Errorf -func lErrorf(t *testing.T, format string, args ...interface{}) - -//go:linkname lFatal testing.(*common).Fatal -func lFatal(t *testing.T, args ...interface{}) - -//go:linkname lFatalf testing.(*common).Fatalf -func lFatalf(t *testing.T, format string, args ...interface{}) +//go:linkname llog testing.(*common).log +func llog(t *testing.T, s string) -//go:linkname lLog testing.(*common).Log -func lLog(t *testing.T, args ...interface{}) - -//go:linkname lLogf testing.(*common).Logf -func lLogf(t *testing.T, format string, args ...interface{}) - -//go:linkname lSkip testing.(*common).Skip -func lSkip(t *testing.T, args ...interface{}) - -//go:linkname lSkipf testing.(*common).Skipf -func lSkipf(t *testing.T, format string, args ...interface{}) +//go:linkname llogdepth testing.(*common).logDepth +func llogdepth(t *testing.T, s string, depth int) func PatchTestingLogger() { - patchError() - patchErrorf() - patchFatal() - patchFatalf() - patchLog() - patchLogf() - patchSkip() - patchSkipf() -} - -func UnpatchTestingLogger() { patchLock.Lock() defer patchLock.Unlock() - - if errorPatch != nil { - logOnError(errorPatch.Unpatch()) - } - if errorfPatch != nil { - logOnError(errorfPatch.Unpatch()) - } - if fatalPatch != nil { - logOnError(fatalPatch.Unpatch()) - } - if fatalfPatch != nil { - logOnError(fatalfPatch.Unpatch()) - } - if logPatch != nil { - logOnError(logPatch.Unpatch()) - } - if logfPatch != nil { - logOnError(logfPatch.Unpatch()) - } - if skipPatch != nil { - logOnError(skipPatch.Unpatch()) - } - if skipfPatch != nil { - logOnError(skipfPatch.Unpatch()) - } -} - -func patchError() { - patchWithArgs(&errorPatch, lError, func(test *Test, args ...interface{}) { - test.t.Helper() - test.span.LogFields( - log.String(tags.EventType, tags.LogEvent), - log.String(tags.EventMessage, fmt.Sprint(args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), - log.String(tags.LogEventLevel, tags.LogLevel_ERROR), - log.String("log.internal_level", "Error"), - log.String("log.logger", "testing"), - ) - }, func(t *testing.T, args ...interface{}) { - t.Helper() - t.Error(args) - }) -} - -func patchErrorf() { - patchWithFormatAndArgs(&errorfPatch, lErrorf, func(test *Test, format string, args ...interface{}) { - test.t.Helper() - test.span.LogFields( - log.String(tags.EventType, tags.LogEvent), - log.String(tags.EventMessage, fmt.Sprintf(format, args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), - log.String(tags.LogEventLevel, tags.LogLevel_ERROR), - log.String("log.internal_level", "Error"), - log.String("log.logger", "testing"), - ) - }, func(t *testing.T, format string, args ...interface{}) { - t.Helper() - t.Errorf(format, args) - }) -} - -func patchFatal() { - patchWithArgs(&fatalPatch, lFatal, func(test *Test, args ...interface{}) { - test.t.Helper() - test.span.LogFields( - log.String(tags.EventType, tags.EventTestFailure), - log.String(tags.EventMessage, fmt.Sprint(args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), - log.String("log.internal_level", "Fatal"), - log.String("log.logger", "testing"), - ) - }, func(t *testing.T, args ...interface{}) { - t.Helper() - t.Fatal(args) - }) -} - -func patchFatalf() { - patchWithFormatAndArgs(&fatalfPatch, lFatalf, func(test *Test, format string, args ...interface{}) { - test.t.Helper() - test.span.LogFields( - log.String(tags.EventType, tags.EventTestFailure), - log.String(tags.EventMessage, fmt.Sprintf(format, args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), - log.String("log.internal_level", "Fatal"), - log.String("log.logger", "testing"), - ) - }, func(t *testing.T, format string, args ...interface{}) { - t.Helper() - t.Fatalf(format, args) - }) -} - -func patchLog() { - patchWithArgs(&logPatch, lLog, func(test *Test, args ...interface{}) { - test.t.Helper() - test.span.LogFields( - log.String(tags.EventType, tags.LogEvent), - log.String(tags.EventMessage, fmt.Sprint(args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), - log.String(tags.LogEventLevel, tags.LogLevel_INFO), - log.String("log.internal_level", "Log"), - log.String("log.logger", "testing"), - ) - }, func(t *testing.T, args ...interface{}) { - t.Helper() - t.Log(args) - }) -} - -func patchLogf() { - patchWithFormatAndArgs(&logfPatch, lLogf, func(test *Test, format string, args ...interface{}) { - test.t.Helper() - test.span.LogFields( - log.String(tags.EventType, tags.LogEvent), - log.String(tags.EventMessage, fmt.Sprintf(format, args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), - log.String(tags.LogEventLevel, tags.LogLevel_INFO), - log.String("log.internal_level", "Log"), - log.String("log.logger", "testing"), - ) - }, func(t *testing.T, format string, args ...interface{}) { - t.Helper() - t.Logf(format, args) - }) -} - -func patchSkip() { - patchWithArgs(&skipPatch, lSkip, func(test *Test, args ...interface{}) { - test.t.Helper() - test.span.LogFields( - log.String(tags.EventType, tags.EventTestSkip), - log.String(tags.EventMessage, fmt.Sprint(args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), - log.String("log.internal_level", "Skip"), - log.String("log.logger", "testing"), - ) - }, func(t *testing.T, args ...interface{}) { - t.Helper() - t.Skip(args) - }) -} - -func patchSkipf() { - patchWithFormatAndArgs(&skipfPatch, lSkipf, func(test *Test, format string, args ...interface{}) { - test.t.Helper() - test.span.LogFields( - log.String(tags.EventType, tags.EventTestSkip), - log.String(tags.EventMessage, fmt.Sprintf(format, args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), - log.String("log.internal_level", "Skip"), - log.String("log.logger", "testing"), - ) - }, func(t *testing.T, format string, args ...interface{}) { - t.Helper() - t.Skipf(format, args) - }) -} - -func patchWithArgs(patchValue **mpatch.Patch, method interface{}, - spanFunc func(test *Test, args ...interface{}), - oFunc func(t *testing.T, args ...interface{})) { - - lPatch, err := mpatch.PatchMethod(method, func(t *testing.T, args ...interface{}) { - if t == nil { - instrumentation.Logger().Println("testing.T is nil") - return - } - t.Helper() - test := GetTest(t) - if test == nil { - instrumentation.Logger().Printf("test struct for %v doesn't exist\n", t.Name()) - return - } - if test.span != nil { - spanFunc(test, args...) - } - mu := reflection.GetTestMutex(test.t) - if mu != nil { - mu.Lock() - (*patchValue).Unpatch() - mu.Unlock() - oFunc(t, args...) - mu.Lock() - (*patchValue).Patch() - mu.Unlock() - } else { - (*patchValue).Unpatch() - oFunc(t, args...) - (*patchValue).Patch() + var err error + llogPatch, err = mpatch.PatchMethod(llog, func(t *testing.T, s string) { + pc, _, _, ok := runtime.Caller(1) + if ok { + name := runtime.FuncForPC(pc).Name() + test := GetTest(t) + if test != nil && test.span != nil { + if strings.HasSuffix(name, ".Error") || strings.HasSuffix(name, ".Errorf") { + test.span.LogFields( + log.String(tags.EventType, tags.LogEvent), + log.String(tags.EventMessage, s), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.LogEventLevel, tags.LogLevel_ERROR), + log.String("log.internal_level", "Error"), + log.String("log.logger", "testing"), + ) + } else if strings.HasSuffix(name, ".Fatal") || strings.HasSuffix(name, ".Fatalf") { + test.span.LogFields( + log.String(tags.EventType, tags.EventTestFailure), + log.String(tags.EventMessage, s), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String("log.internal_level", "Fatal"), + log.String("log.logger", "testing"), + ) + } else if strings.HasSuffix(name, ".Log") || strings.HasSuffix(name, ".Logf") { + test.span.LogFields( + log.String(tags.EventType, tags.LogEvent), + log.String(tags.EventMessage, s), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.LogEventLevel, tags.LogLevel_INFO), + log.String("log.internal_level", "Log"), + log.String("log.logger", "testing"), + ) + } else if strings.HasSuffix(name, ".Skip") || strings.HasSuffix(name, ".Skipf") { + test.span.LogFields( + log.String(tags.EventType, tags.EventTestSkip), + log.String(tags.EventMessage, s), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String("log.internal_level", "Skip"), + log.String("log.logger", "testing"), + ) + } + } } + llogdepth(t, s, 3) }) logOnError(err) - *patchValue = lPatch } -func patchWithFormatAndArgs(patchValue **mpatch.Patch, method interface{}, - spanFunc func(test *Test, format string, args ...interface{}), - oFunc func(t *testing.T, format string, args ...interface{})) { - - lPatch, err := mpatch.PatchMethod(method, func(t *testing.T, format string, args ...interface{}) { - if t == nil { - instrumentation.Logger().Println("testing.T is nil") - return - } - t.Helper() - test := GetTest(t) - if test == nil { - instrumentation.Logger().Printf("test struct for %v doesn't exist\n", t.Name()) - return - } - if test.span != nil { - spanFunc(test, format, args...) - } - mu := reflection.GetTestMutex(test.t) - if mu != nil { - mu.Lock() - (*patchValue).Unpatch() - mu.Unlock() - oFunc(t, format, args...) - mu.Lock() - (*patchValue).Patch() - mu.Unlock() - } else { - (*patchValue).Unpatch() - oFunc(t, format, args...) - (*patchValue).Patch() - } - }) - logOnError(err) - *patchValue = lPatch +func UnpatchTestingLogger() { + patchLock.Lock() + defer patchLock.Unlock() + if llogPatch != nil { + logOnError(llogPatch.Unpatch()) + } } func logOnError(err error) { diff --git a/instrumentation/testing/tb.go b/instrumentation/testing/tb.go index f5af9f26..4a0af3e7 100644 --- a/instrumentation/testing/tb.go +++ b/instrumentation/testing/tb.go @@ -3,7 +3,9 @@ package testing import ( "fmt" "github.com/opentracing/opentracing-go/log" + "go.undefinedlabs.com/scopeagent/reflection" "path/filepath" + "runtime" "go.undefinedlabs.com/scopeagent/errors" "go.undefinedlabs.com/scopeagent/instrumentation" @@ -160,6 +162,10 @@ func (test *Test) Skipped() bool { // Deprecated: use `testing.T.Helper` instead func (test *Test) Helper() { + pc, _, _, _ := runtime.Caller(1) + reflection.AddToHelpersMap(test.t, []string{ + runtime.FuncForPC(pc).Name(), + }) test.t.Helper() } diff --git a/instrumentation/testing/testing_test.go b/instrumentation/testing/testing_test.go index 40f7748d..8fc1dab2 100644 --- a/instrumentation/testing/testing_test.go +++ b/instrumentation/testing/testing_test.go @@ -66,21 +66,16 @@ func BenchmarkLoggerPatcher(b *testing.B) { func TestLoggerPatcher(t *testing.T) { tm := time.Now() PatchTestingLogger() - //wg := sync.WaitGroup{} + wg := sync.WaitGroup{} for i := 0; i < 10000; i++ { - //wg.Add(1) + wg.Add(1) go func(x int) { - //defer wg.Done() - //for j:=0; j <100; j++ { + defer wg.Done() t.Log(fmt.Sprintf("Hello world %d", x)) - //t.Logf("Hello world %d", x) - //} }(i) } - //wg.Wait() - <-time.After(200 * time.Millisecond) + wg.Wait() UnpatchTestingLogger() - <-time.After(200 * time.Millisecond) if time.Since(tm) > 2*time.Second { t.Fatal("Test is too slow") } From 16827829223371c34eb02182cb7be7bfd1f36108 Mon Sep 17 00:00:00 2001 From: Daniel Redondo Date: Mon, 1 Jun 2020 00:00:57 +0200 Subject: [PATCH 03/11] remove branch from ITR --- .github/workflows/go.yml | 2 +- go.mod | 1 + 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/.github/workflows/go.yml b/.github/workflows/go.yml index 857d8965..d66faeef 100644 --- a/.github/workflows/go.yml +++ b/.github/workflows/go.yml @@ -31,7 +31,7 @@ jobs: SCOPE_LOGGER_ROOT: /home/runner/.scope-results SCOPE_DEBUG: true SCOPE_RUNNER_ENABLED: true - SCOPE_RUNNER_EXCLUDE_BRANCHES: master + SCOPE_RUNNER_EXCLUDE_BRANCHES: master, seg-fault-fix SCOPE_TESTING_FAIL_RETRIES: 3 SCOPE_TESTING_PANIC_AS_FAIL: true diff --git a/go.mod b/go.mod index 516dc4a2..46d118d7 100644 --- a/go.mod +++ b/go.mod @@ -23,4 +23,5 @@ require ( google.golang.org/grpc v1.29.1 gopkg.in/check.v1 v1.0.0-20200227125254-8fa46927fb4f gopkg.in/tomb.v2 v2.0.0-20161208151619-d5d1b5820637 + honnef.co/go/tools v0.0.0-20190523083050-ea95bdfd59fc // indirect ) From 12a48e348ca7a4c285ea9d9694ef7d312212e10a Mon Sep 17 00:00:00 2001 From: Daniel Redondo Date: Mon, 1 Jun 2020 00:05:37 +0200 Subject: [PATCH 04/11] test log --- instrumentation/nethttp/nethttp_test.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/instrumentation/nethttp/nethttp_test.go b/instrumentation/nethttp/nethttp_test.go index 1efab075..bca8c361 100644 --- a/instrumentation/nethttp/nethttp_test.go +++ b/instrumentation/nethttp/nethttp_test.go @@ -52,6 +52,7 @@ func TestHttpClient(t *testing.T) { "peer.hostname": "www.google.com", "peer.port": "443", }) + t.Log("all ok.") } func TestHttpServer(t *testing.T) { @@ -105,6 +106,7 @@ func TestHttpServer(t *testing.T) { "http.request_payload": "Hello world request", "http.response_payload": "Hello world", }) + t.Log("all ok.") } func checkTags(t *testing.T, tags map[string]interface{}, expected map[string]string) { From 95d2b3a5dfc82a826d768ea2e0ce60b9c3a42f56 Mon Sep 17 00:00:00 2001 From: Daniel Redondo Date: Mon, 1 Jun 2020 00:10:28 +0200 Subject: [PATCH 05/11] changes --- instrumentation/nethttp/nethttp_test.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/instrumentation/nethttp/nethttp_test.go b/instrumentation/nethttp/nethttp_test.go index bca8c361..f89b89e7 100644 --- a/instrumentation/nethttp/nethttp_test.go +++ b/instrumentation/nethttp/nethttp_test.go @@ -3,6 +3,7 @@ package nethttp import ( "bytes" "fmt" + testing2 "go.undefinedlabs.com/scopeagent/instrumentation/testing" "net/http" "net/http/httptest" "os" @@ -20,6 +21,7 @@ func TestMain(m *testing.M) { // Test tracer r = tracer.NewInMemoryRecorder() + testing2.PatchTestingLogger() os.Exit(scopeagent.Run(m, agent.WithRecorders(r))) } From 5d5099caed4a4d848cf4508e95b87409436cb81b Mon Sep 17 00:00:00 2001 From: Daniel Redondo Date: Mon, 1 Jun 2020 09:39:14 +0200 Subject: [PATCH 06/11] fixes testing logger --- instrumentation/testing/logger.go | 301 ++++++++++++++++++++++++------ 1 file changed, 246 insertions(+), 55 deletions(-) diff --git a/instrumentation/testing/logger.go b/instrumentation/testing/logger.go index 0e985347..5f7f0060 100644 --- a/instrumentation/testing/logger.go +++ b/instrumentation/testing/logger.go @@ -1,8 +1,7 @@ package testing import ( - "runtime" - "strings" + "fmt" "sync" "testing" _ "unsafe" @@ -16,73 +15,265 @@ import ( var ( patchLock sync.Mutex - llogPatch *mpatch.Patch + + errorPatch *mpatch.Patch + errorfPatch *mpatch.Patch + fatalPatch *mpatch.Patch + fatalfPatch *mpatch.Patch + logPatch *mpatch.Patch + logfPatch *mpatch.Patch + skipPatch *mpatch.Patch + skipfPatch *mpatch.Patch ) //go:linkname llog testing.(*common).log func llog(t *testing.T, s string) -//go:linkname llogdepth testing.(*common).logDepth -func llogdepth(t *testing.T, s string, depth int) +//go:linkname lError testing.(*common).Error +func lError(t *testing.T, args ...interface{}) + +//go:linkname lErrorf testing.(*common).Errorf +func lErrorf(t *testing.T, format string, args ...interface{}) + +//go:linkname lFatal testing.(*common).Fatal +func lFatal(t *testing.T, args ...interface{}) + +//go:linkname lFatalf testing.(*common).Fatalf +func lFatalf(t *testing.T, format string, args ...interface{}) + +//go:linkname lLog testing.(*common).Log +func lLog(t *testing.T, args ...interface{}) + +//go:linkname lLogf testing.(*common).Logf +func lLogf(t *testing.T, format string, args ...interface{}) + +//go:linkname lSkip testing.(*common).Skip +func lSkip(t *testing.T, args ...interface{}) + +//go:linkname lSkipf testing.(*common).Skipf +func lSkipf(t *testing.T, format string, args ...interface{}) func PatchTestingLogger() { + patchError() + patchErrorf() + patchFatal() + patchFatalf() + patchLog() + patchLogf() + patchSkip() + patchSkipf() +} + +func UnpatchTestingLogger() { patchLock.Lock() defer patchLock.Unlock() - var err error - llogPatch, err = mpatch.PatchMethod(llog, func(t *testing.T, s string) { - pc, _, _, ok := runtime.Caller(1) - if ok { - name := runtime.FuncForPC(pc).Name() - test := GetTest(t) - if test != nil && test.span != nil { - if strings.HasSuffix(name, ".Error") || strings.HasSuffix(name, ".Errorf") { - test.span.LogFields( - log.String(tags.EventType, tags.LogEvent), - log.String(tags.EventMessage, s), - log.String(tags.EventSource, getSourceFileAndNumber()), - log.String(tags.LogEventLevel, tags.LogLevel_ERROR), - log.String("log.internal_level", "Error"), - log.String("log.logger", "testing"), - ) - } else if strings.HasSuffix(name, ".Fatal") || strings.HasSuffix(name, ".Fatalf") { - test.span.LogFields( - log.String(tags.EventType, tags.EventTestFailure), - log.String(tags.EventMessage, s), - log.String(tags.EventSource, getSourceFileAndNumber()), - log.String("log.internal_level", "Fatal"), - log.String("log.logger", "testing"), - ) - } else if strings.HasSuffix(name, ".Log") || strings.HasSuffix(name, ".Logf") { - test.span.LogFields( - log.String(tags.EventType, tags.LogEvent), - log.String(tags.EventMessage, s), - log.String(tags.EventSource, getSourceFileAndNumber()), - log.String(tags.LogEventLevel, tags.LogLevel_INFO), - log.String("log.internal_level", "Log"), - log.String("log.logger", "testing"), - ) - } else if strings.HasSuffix(name, ".Skip") || strings.HasSuffix(name, ".Skipf") { - test.span.LogFields( - log.String(tags.EventType, tags.EventTestSkip), - log.String(tags.EventMessage, s), - log.String(tags.EventSource, getSourceFileAndNumber()), - log.String("log.internal_level", "Skip"), - log.String("log.logger", "testing"), - ) - } - } + + if errorPatch != nil { + logOnError(errorPatch.Unpatch()) + } + if errorfPatch != nil { + logOnError(errorfPatch.Unpatch()) + } + if fatalPatch != nil { + logOnError(fatalPatch.Unpatch()) + } + if fatalfPatch != nil { + logOnError(fatalfPatch.Unpatch()) + } + if logPatch != nil { + logOnError(logPatch.Unpatch()) + } + if logfPatch != nil { + logOnError(logfPatch.Unpatch()) + } + if skipPatch != nil { + logOnError(skipPatch.Unpatch()) + } + if skipfPatch != nil { + logOnError(skipfPatch.Unpatch()) + } +} + +func patchError() { + patchWithArgs(&errorPatch, lError, func(test *Test, args ...interface{}) { + test.t.Helper() + s := fmt.Sprintln(args...) + if test.span != nil { + test.span.LogFields( + log.String(tags.EventType, tags.LogEvent), + log.String(tags.EventMessage, s), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.LogEventLevel, tags.LogLevel_ERROR), + log.String("log.internal_level", "Error"), + log.String("log.logger", "testing"), + ) + } + llog(test.t, s) + test.t.Fail() + }) +} + +func patchErrorf() { + patchWithFormatAndArgs(&errorfPatch, lErrorf, func(test *Test, format string, args ...interface{}) { + test.t.Helper() + s := fmt.Sprintf(format, args...) + if test.span != nil { + test.span.LogFields( + log.String(tags.EventType, tags.LogEvent), + log.String(tags.EventMessage, s), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.LogEventLevel, tags.LogLevel_ERROR), + log.String("log.internal_level", "Error"), + log.String("log.logger", "testing"), + ) + } + llog(test.t, s) + test.t.Fail() + }) +} + +func patchFatal() { + patchWithArgs(&fatalPatch, lFatal, func(test *Test, args ...interface{}) { + test.t.Helper() + s := fmt.Sprintln(args...) + if test.span != nil { + test.span.LogFields( + log.String(tags.EventType, tags.EventTestFailure), + log.String(tags.EventMessage, s), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String("log.internal_level", "Fatal"), + log.String("log.logger", "testing"), + ) } - llogdepth(t, s, 3) + llog(test.t, s) + test.t.FailNow() + }) +} + +func patchFatalf() { + patchWithFormatAndArgs(&fatalfPatch, lFatalf, func(test *Test, format string, args ...interface{}) { + test.t.Helper() + s := fmt.Sprintf(format, args...) + if test.span != nil { + test.span.LogFields( + log.String(tags.EventType, tags.EventTestFailure), + log.String(tags.EventMessage, s), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String("log.internal_level", "Fatal"), + log.String("log.logger", "testing"), + ) + } + llog(test.t, s) + test.t.FailNow() + }) +} + +func patchLog() { + patchWithArgs(&logPatch, lLog, func(test *Test, args ...interface{}) { + test.t.Helper() + s := fmt.Sprintln(args...) + if test.span != nil { + test.span.LogFields( + log.String(tags.EventType, tags.LogEvent), + log.String(tags.EventMessage, s), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.LogEventLevel, tags.LogLevel_INFO), + log.String("log.internal_level", "Log"), + log.String("log.logger", "testing"), + ) + } + llog(test.t, s) + }) +} + +func patchLogf() { + patchWithFormatAndArgs(&logfPatch, lLogf, func(test *Test, format string, args ...interface{}) { + test.t.Helper() + s := fmt.Sprintf(format, args...) + if test.span != nil { + test.span.LogFields( + log.String(tags.EventType, tags.LogEvent), + log.String(tags.EventMessage, s), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.LogEventLevel, tags.LogLevel_INFO), + log.String("log.internal_level", "Log"), + log.String("log.logger", "testing"), + ) + } + llog(test.t, s) + }) +} + +func patchSkip() { + patchWithArgs(&skipPatch, lSkip, func(test *Test, args ...interface{}) { + test.t.Helper() + s := fmt.Sprintln(args...) + if test.span != nil { + test.span.LogFields( + log.String(tags.EventType, tags.EventTestSkip), + log.String(tags.EventMessage, s), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String("log.internal_level", "Skip"), + log.String("log.logger", "testing"), + ) + } + llog(test.t, s) + test.t.SkipNow() + }) +} + +func patchSkipf() { + patchWithFormatAndArgs(&skipfPatch, lSkipf, func(test *Test, format string, args ...interface{}) { + test.t.Helper() + s := fmt.Sprintf(format, args...) + if test.span != nil { + test.span.LogFields( + log.String(tags.EventType, tags.EventTestSkip), + log.String(tags.EventMessage, s), + log.String(tags.EventSource, getSourceFileAndNumber()), + log.String("log.internal_level", "Skip"), + log.String("log.logger", "testing"), + ) + } + llog(test.t, s) + test.t.SkipNow() + }) +} + +func patchWithArgs(patchValue **mpatch.Patch, method interface{}, methodBody func(test *Test, args ...interface{})) { + lPatch, err := mpatch.PatchMethod(method, func(t *testing.T, args ...interface{}) { + if t == nil { + instrumentation.Logger().Println("testing.T is nil") + return + } + t.Helper() + test := GetTest(t) + if test == nil { + instrumentation.Logger().Printf("test struct for %v doesn't exist\n", t.Name()) + return + } + methodBody(test, args...) }) logOnError(err) + *patchValue = lPatch } -func UnpatchTestingLogger() { - patchLock.Lock() - defer patchLock.Unlock() - if llogPatch != nil { - logOnError(llogPatch.Unpatch()) - } +func patchWithFormatAndArgs(patchValue **mpatch.Patch, method interface{}, methodBody func(test *Test, format string, args ...interface{})) { + lPatch, err := mpatch.PatchMethod(method, func(t *testing.T, format string, args ...interface{}) { + if t == nil { + instrumentation.Logger().Println("testing.T is nil") + return + } + t.Helper() + test := GetTest(t) + if test == nil { + instrumentation.Logger().Printf("test struct for %v doesn't exist\n", t.Name()) + return + } + methodBody(test, format, args...) + }) + logOnError(err) + *patchValue = lPatch } func logOnError(err error) { From d325654674a69b2ba7b2b92f9df3402427d83738 Mon Sep 17 00:00:00 2001 From: Daniel Redondo Date: Mon, 1 Jun 2020 09:43:39 +0200 Subject: [PATCH 07/11] fix test --- instrumentation/testing/testing_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/instrumentation/testing/testing_test.go b/instrumentation/testing/testing_test.go index 8fc1dab2..d9dae4d5 100644 --- a/instrumentation/testing/testing_test.go +++ b/instrumentation/testing/testing_test.go @@ -67,7 +67,7 @@ func TestLoggerPatcher(t *testing.T) { tm := time.Now() PatchTestingLogger() wg := sync.WaitGroup{} - for i := 0; i < 10000; i++ { + for i := 0; i < 1000; i++ { wg.Add(1) go func(x int) { defer wg.Done() From c5835d32773e6b315a99dbaf25458d9bb111fc8d Mon Sep 17 00:00:00 2001 From: Daniel Redondo Date: Mon, 1 Jun 2020 09:48:30 +0200 Subject: [PATCH 08/11] fixes log event source --- instrumentation/testing/logger.go | 16 ++++++++-------- instrumentation/testing/tb.go | 25 +++++++++++++------------ 2 files changed, 21 insertions(+), 20 deletions(-) diff --git a/instrumentation/testing/logger.go b/instrumentation/testing/logger.go index 5f7f0060..d03d34b3 100644 --- a/instrumentation/testing/logger.go +++ b/instrumentation/testing/logger.go @@ -102,7 +102,7 @@ func patchError() { test.span.LogFields( log.String(tags.EventType, tags.LogEvent), log.String(tags.EventMessage, s), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(2)), log.String(tags.LogEventLevel, tags.LogLevel_ERROR), log.String("log.internal_level", "Error"), log.String("log.logger", "testing"), @@ -121,7 +121,7 @@ func patchErrorf() { test.span.LogFields( log.String(tags.EventType, tags.LogEvent), log.String(tags.EventMessage, s), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(2)), log.String(tags.LogEventLevel, tags.LogLevel_ERROR), log.String("log.internal_level", "Error"), log.String("log.logger", "testing"), @@ -140,7 +140,7 @@ func patchFatal() { test.span.LogFields( log.String(tags.EventType, tags.EventTestFailure), log.String(tags.EventMessage, s), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(2)), log.String("log.internal_level", "Fatal"), log.String("log.logger", "testing"), ) @@ -158,7 +158,7 @@ func patchFatalf() { test.span.LogFields( log.String(tags.EventType, tags.EventTestFailure), log.String(tags.EventMessage, s), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(2)), log.String("log.internal_level", "Fatal"), log.String("log.logger", "testing"), ) @@ -176,7 +176,7 @@ func patchLog() { test.span.LogFields( log.String(tags.EventType, tags.LogEvent), log.String(tags.EventMessage, s), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(2)), log.String(tags.LogEventLevel, tags.LogLevel_INFO), log.String("log.internal_level", "Log"), log.String("log.logger", "testing"), @@ -194,7 +194,7 @@ func patchLogf() { test.span.LogFields( log.String(tags.EventType, tags.LogEvent), log.String(tags.EventMessage, s), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(2)), log.String(tags.LogEventLevel, tags.LogLevel_INFO), log.String("log.internal_level", "Log"), log.String("log.logger", "testing"), @@ -212,7 +212,7 @@ func patchSkip() { test.span.LogFields( log.String(tags.EventType, tags.EventTestSkip), log.String(tags.EventMessage, s), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(2)), log.String("log.internal_level", "Skip"), log.String("log.logger", "testing"), ) @@ -230,7 +230,7 @@ func patchSkipf() { test.span.LogFields( log.String(tags.EventType, tags.EventTestSkip), log.String(tags.EventMessage, s), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(2)), log.String("log.internal_level", "Skip"), log.String("log.logger", "testing"), ) diff --git a/instrumentation/testing/tb.go b/instrumentation/testing/tb.go index 4a0af3e7..a1b00e93 100644 --- a/instrumentation/testing/tb.go +++ b/instrumentation/testing/tb.go @@ -2,13 +2,14 @@ package testing import ( "fmt" - "github.com/opentracing/opentracing-go/log" - "go.undefinedlabs.com/scopeagent/reflection" "path/filepath" "runtime" + "github.com/opentracing/opentracing-go/log" + "go.undefinedlabs.com/scopeagent/errors" "go.undefinedlabs.com/scopeagent/instrumentation" + "go.undefinedlabs.com/scopeagent/reflection" "go.undefinedlabs.com/scopeagent/tags" ) @@ -22,7 +23,7 @@ func (test *Test) Error(args ...interface{}) { test.span.LogFields( log.String(tags.EventType, tags.LogEvent), log.String(tags.EventMessage, fmt.Sprint(args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(1)), log.String(tags.LogEventLevel, tags.LogLevel_ERROR), log.String("log.internal_level", "Error"), log.String("log.logger", "testing"), @@ -37,7 +38,7 @@ func (test *Test) Errorf(format string, args ...interface{}) { test.span.LogFields( log.String(tags.EventType, tags.LogEvent), log.String(tags.EventMessage, fmt.Sprintf(format, args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(1)), log.String(tags.LogEventLevel, tags.LogLevel_ERROR), log.String("log.internal_level", "Error"), log.String("log.logger", "testing"), @@ -67,7 +68,7 @@ func (test *Test) Fatal(args ...interface{}) { test.span.LogFields( log.String(tags.EventType, tags.EventTestFailure), log.String(tags.EventMessage, fmt.Sprint(args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(1)), log.String("log.internal_level", "Fatal"), log.String("log.logger", "testing"), ) @@ -81,7 +82,7 @@ func (test *Test) Fatalf(format string, args ...interface{}) { test.span.LogFields( log.String(tags.EventType, tags.EventTestFailure), log.String(tags.EventMessage, fmt.Sprintf(format, args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(1)), log.String("log.internal_level", "Fatal"), log.String("log.logger", "testing"), ) @@ -95,7 +96,7 @@ func (test *Test) Log(args ...interface{}) { test.span.LogFields( log.String(tags.EventType, tags.LogEvent), log.String(tags.EventMessage, fmt.Sprint(args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(1)), log.String(tags.LogEventLevel, tags.LogLevel_INFO), log.String("log.internal_level", "Log"), log.String("log.logger", "testing"), @@ -110,7 +111,7 @@ func (test *Test) Logf(format string, args ...interface{}) { test.span.LogFields( log.String(tags.EventType, tags.LogEvent), log.String(tags.EventMessage, fmt.Sprintf(format, args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(1)), log.String(tags.LogEventLevel, tags.LogLevel_INFO), log.String("log.internal_level", "Log"), log.String("log.logger", "testing"), @@ -129,7 +130,7 @@ func (test *Test) Skip(args ...interface{}) { test.span.LogFields( log.String(tags.EventType, tags.EventTestSkip), log.String(tags.EventMessage, fmt.Sprint(args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(1)), log.String("log.internal_level", "Skip"), log.String("log.logger", "testing"), ) @@ -148,7 +149,7 @@ func (test *Test) Skipf(format string, args ...interface{}) { test.span.LogFields( log.String(tags.EventType, tags.EventTestSkip), log.String(tags.EventMessage, fmt.Sprintf(format, args...)), - log.String(tags.EventSource, getSourceFileAndNumber()), + log.String(tags.EventSource, getSourceFileAndNumber(1)), log.String("log.internal_level", "Skip"), log.String("log.logger", "testing"), ) @@ -174,9 +175,9 @@ func (test *Test) LogPanic(recoverData interface{}, skipFrames int) { errors.LogPanic(test.ctx, recoverData, skipFrames+1) } -func getSourceFileAndNumber() string { +func getSourceFileAndNumber(skip int) string { var source string - if _, file, line, ok := instrumentation.GetCallerInsideSourceRoot(2); ok == true { + if _, file, line, ok := instrumentation.GetCallerInsideSourceRoot(1 + skip); ok == true { file = filepath.Clean(file) source = fmt.Sprintf("%s:%d", file, line) } From 8196350c4a8b1b896f1ee43b12680ddf7ed52011 Mon Sep 17 00:00:00 2001 From: Daniel Redondo Date: Mon, 1 Jun 2020 09:59:22 +0200 Subject: [PATCH 09/11] fixes windows event source --- instrumentation/tracer.go | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/instrumentation/tracer.go b/instrumentation/tracer.go index 20b18989..f26d2016 100644 --- a/instrumentation/tracer.go +++ b/instrumentation/tracer.go @@ -51,7 +51,10 @@ func Logger() *log.Logger { func SetSourceRoot(root string) { m.Lock() defer m.Unlock() - + // In windows the debug symbols and source root can be in different cases + if runtime.GOOS == "windows" { + root = strings.ToLower(root) + } sourceRoot = root } @@ -78,6 +81,7 @@ func GetRemoteConfiguration() map[string]interface{} { //go:noinline func GetCallerInsideSourceRoot(skip int) (pc uintptr, file string, line int, ok bool) { + isWindows := runtime.GOOS == "windows" pcs := make([]uintptr, 64) count := runtime.Callers(skip+2, pcs) pcs = pcs[:count] @@ -86,6 +90,10 @@ func GetCallerInsideSourceRoot(skip int) (pc uintptr, file string, line int, ok frame, more := frames.Next() file := filepath.Clean(frame.File) dir := filepath.Dir(file) + // In windows the debug symbols and source root can be in different cases + if isWindows { + dir = strings.ToLower(dir) + } if strings.Index(dir, sourceRoot) != -1 { return frame.PC, file, frame.Line, true } From 3aa574208c2fae971a2220ca7235cb69783919b6 Mon Sep 17 00:00:00 2001 From: Daniel Redondo Date: Mon, 1 Jun 2020 10:05:39 +0200 Subject: [PATCH 10/11] format changes --- go.mod | 1 - instrumentation/nethttp/nethttp_test.go | 5 ++--- 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/go.mod b/go.mod index 46d118d7..516dc4a2 100644 --- a/go.mod +++ b/go.mod @@ -23,5 +23,4 @@ require ( google.golang.org/grpc v1.29.1 gopkg.in/check.v1 v1.0.0-20200227125254-8fa46927fb4f gopkg.in/tomb.v2 v2.0.0-20161208151619-d5d1b5820637 - honnef.co/go/tools v0.0.0-20190523083050-ea95bdfd59fc // indirect ) diff --git a/instrumentation/nethttp/nethttp_test.go b/instrumentation/nethttp/nethttp_test.go index f89b89e7..856d3df1 100644 --- a/instrumentation/nethttp/nethttp_test.go +++ b/instrumentation/nethttp/nethttp_test.go @@ -3,7 +3,6 @@ package nethttp import ( "bytes" "fmt" - testing2 "go.undefinedlabs.com/scopeagent/instrumentation/testing" "net/http" "net/http/httptest" "os" @@ -11,6 +10,7 @@ import ( "go.undefinedlabs.com/scopeagent" "go.undefinedlabs.com/scopeagent/agent" + testing2 "go.undefinedlabs.com/scopeagent/instrumentation/testing" "go.undefinedlabs.com/scopeagent/tracer" ) @@ -54,7 +54,6 @@ func TestHttpClient(t *testing.T) { "peer.hostname": "www.google.com", "peer.port": "443", }) - t.Log("all ok.") } func TestHttpServer(t *testing.T) { @@ -108,7 +107,6 @@ func TestHttpServer(t *testing.T) { "http.request_payload": "Hello world request", "http.response_payload": "Hello world", }) - t.Log("all ok.") } func checkTags(t *testing.T, tags map[string]interface{}, expected map[string]string) { @@ -121,6 +119,7 @@ func checkTags(t *testing.T, tags map[string]interface{}, expected map[string]st } } } + t.Log("all tags ok.") } func checkTag(tags map[string]interface{}, key string, expectedValue string) (bool, string) { From e00117fd8e92f836c959d48e81ed4422c8815d67 Mon Sep 17 00:00:00 2001 From: Daniel Redondo Date: Tue, 2 Jun 2020 09:37:04 +0200 Subject: [PATCH 11/11] remove branch from the workflow runner exclude branches --- .github/workflows/go.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/go.yml b/.github/workflows/go.yml index d66faeef..857d8965 100644 --- a/.github/workflows/go.yml +++ b/.github/workflows/go.yml @@ -31,7 +31,7 @@ jobs: SCOPE_LOGGER_ROOT: /home/runner/.scope-results SCOPE_DEBUG: true SCOPE_RUNNER_ENABLED: true - SCOPE_RUNNER_EXCLUDE_BRANCHES: master, seg-fault-fix + SCOPE_RUNNER_EXCLUDE_BRANCHES: master SCOPE_TESTING_FAIL_RETRIES: 3 SCOPE_TESTING_PANIC_AS_FAIL: true