From ebf3359e026f02a1f05d69a410b136843ba486dc Mon Sep 17 00:00:00 2001 From: ktong Date: Sat, 24 Feb 2024 17:55:17 -0800 Subject: [PATCH] use Callers instead of debug.Stack() --- gcp/handler.go | 88 ++++++++++++++++++++++++--------------------- gcp/handler_test.go | 46 ++++++++++++------------ 2 files changed, 71 insertions(+), 63 deletions(-) diff --git a/gcp/handler.go b/gcp/handler.go index 107a883..391879a 100644 --- a/gcp/handler.go +++ b/gcp/handler.go @@ -15,14 +15,12 @@ It also integrates logs with [GCP Cloud Trace] and [GCP Error Reporting] if enab package gcp import ( - "bytes" "context" "encoding/hex" "errors" "log/slog" "os" "runtime" - "runtime/debug" "slices" "strconv" "strings" @@ -179,10 +177,6 @@ func (h logHandler) Handle(ctx context.Context, record slog.Record) error { //no // See: https://cloud.google.com/error-reporting/docs/formatting-error-messages if record.Level >= slog.LevelError && h.service != "" { firstFrame, _ := runtime.CallersFrames([]uintptr{record.PC}).Next() - var stackTrace strings.Builder - stackTrace.WriteString(record.Message) - stackTrace.WriteString("\n\n") - var callers []uintptr record.Attrs(func(attr slog.Attr) bool { if err, ok := attr.Value.Resolve().Any().(error); ok { @@ -194,10 +188,8 @@ func (h logHandler) Handle(ctx context.Context, record slog.Record) error { //no return true }) - if len(callers) > 0 { - stackFromCallers(&stackTrace, callers) - } else { - stack(&stackTrace, firstFrame) + if len(callers) == 0 { + callers = loadCallers(firstFrame) } handler = handler.WithAttrs( @@ -222,7 +214,7 @@ func (h logHandler) Handle(ctx context.Context, record slog.Record) error { //no slog.String("version", h.version), ), }, - slog.String("stack_trace", stackTrace.String()), + slog.String("stack_trace", stack(record.Message, callers)), }) } @@ -233,13 +225,54 @@ func (h logHandler) Handle(ctx context.Context, record slog.Record) error { //no return handler.Handle(ctx, record) } -func stackFromCallers(stackTrace *strings.Builder, callers []uintptr) { +func loadCallers(firstFrame runtime.Frame) []uintptr { + var pcs [32]uintptr + count := runtime.Callers(2, pcs[:]) //nolint:gomnd // skip [runtime.Callers, this function] + + // Skip frames before the first frame of the record. + callers := pcs[:count] + frames := runtime.CallersFrames(callers) + for { + frame, more := frames.Next() + if frame.Function == firstFrame.Function && + frame.File == firstFrame.File && + frame.Line == firstFrame.Line { + break + } + callers = callers[1:] + if !more { + break + } + } + + if len(callers) > 0 { + return callers + } + + // If the first frame is not found, all frames prints as stack trace. + return pcs[:count] +} + +func stack(message string, callers []uintptr) string { + var stackTrace strings.Builder + stackTrace.Grow(128 * len(callers)) //nolint:gomnd // It assumes 128 bytes per frame. + + stackTrace.WriteString(message) + stackTrace.WriteString("\n\n") + // Always use 1 as the goroutine number as golang does not prove a way to get the current goroutine number. + // It's meaningless in stace trace since every log may have different goroutine number. + // It has to be a goroutine line to match the stack trace format for Error Reporting. stackTrace.WriteString("goroutine 1 [running]:\n") + frames := runtime.CallersFrames(callers) for { + // Each frame has 2 lines in stack trace. frame, more := frames.Next() + // The first line is the function. stackTrace.WriteString(frame.Function) - stackTrace.WriteString("()\n\t") + stackTrace.WriteString("()\n") + // The second line is the file:line. + stackTrace.WriteString("\t") stackTrace.WriteString(frame.File) stackTrace.WriteString(":") stackTrace.WriteString(strconv.Itoa(frame.Line)) @@ -251,35 +284,8 @@ func stackFromCallers(stackTrace *strings.Builder, callers []uintptr) { break } } -} - -func stack(stackTrace *strings.Builder, firstFrame runtime.Frame) { - frames := bytes.NewBuffer(debug.Stack()) - // Always add the first line (goroutine line) in stack trace. - firstLine, err := frames.ReadBytes('\n') - stackTrace.Write(firstLine) - if err != nil { - return - } - // Each frame has 2 lines in stack trace, first line is the function and second line is the file:#line. - firstFuncLine := []byte(firstFrame.Function) - var functionLine, fileLine []byte - for { - if functionLine, err = frames.ReadBytes('\n'); err != nil { - break - } - if fileLine, err = frames.ReadBytes('\n'); err != nil { - break - } - if bytes.Contains(functionLine, firstFuncLine) { - stackTrace.Write(functionLine) - stackTrace.Write(fileLine) - stackTrace.Write(frames.Bytes()) - - break - } - } + return stackTrace.String() } func (h logHandler) WithAttrs(attrs []slog.Attr) slog.Handler { diff --git a/gcp/handler_test.go b/gcp/handler_test.go index a0a07f0..09f2095 100644 --- a/gcp/handler_test.go +++ b/gcp/handler_test.go @@ -38,25 +38,24 @@ func TestHandler(t *testing.T) { } gHandler := handler.WithGroup("g") if handler.Enabled(ctx, slog.LevelWarn) { - record := record(slog.LevelWarn, "warn") - record.Add("a", "A") - assert.NoError(t, gHandler.WithAttrs([]slog.Attr{slog.String("b", "B")}).Handle(ctx, record)) + assert.NoError(t, gHandler.WithAttrs([]slog.Attr{slog.String("b", "B")}). + Handle(ctx, record(slog.LevelWarn, "warn", "a", "A"))) } if handler.Enabled(ctx, slog.LevelError) { - record := record(slog.LevelError, "error") + var attrs []any if testcase.err != nil { - record.Add("error", testcase.err) + attrs = append(attrs, "error", testcase.err) } assert.NoError(t, gHandler.WithGroup("h").WithAttrs([]slog.Attr{slog.String("b", "B")}). - Handle(ctx, record)) + Handle(ctx, record(slog.LevelError, "error", attrs...))) } path, err := os.Getwd() assert.NoError(t, err) log, after, _ := strings.Cut(buf.String(), "goroutine ") _, after, _ = strings.Cut(after, "[running]:") - before, after, _ := strings.Cut(after, "(") - _, after, _ = strings.Cut(after, `"g":`) + before, after, _ := strings.Cut(after, " +0x") + _, after, _ = strings.Cut(after, ",") log = strings.ReplaceAll(log, path, "") assert.Equal(t, testcase.expected, log+before+after) }) @@ -79,8 +78,8 @@ func testCases() []struct { { description: "default", expected: `{"timestamp":{"seconds":100,"nanos":1000},"severity":"INFO","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":37},"message":"info","a":"A"} -{"timestamp":{"seconds":100,"nanos":1000},"severity":"WARNING","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":41},"message":"warn","g":{"b":"B","a":"A"}} -{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":46},"message":"error","g":{"h":{"b":"B"}}} +{"timestamp":{"seconds":100,"nanos":1000},"severity":"WARNING","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":42},"message":"warn","g":{"b":"B","a":"A"}} +{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":50},"message":"error","g":{"h":{"b":"B"}}} `, }, { @@ -88,8 +87,8 @@ func testCases() []struct { opts: []gcp.Option{ gcp.WithLevel(slog.LevelWarn), }, - expected: `{"timestamp":{"seconds":100,"nanos":1000},"severity":"WARNING","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":41},"message":"warn","g":{"b":"B","a":"A"}} -{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":46},"message":"error","g":{"h":{"b":"B"}}} + expected: `{"timestamp":{"seconds":100,"nanos":1000},"severity":"WARNING","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":42},"message":"warn","g":{"b":"B","a":"A"}} +{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":50},"message":"error","g":{"h":{"b":"B"}}} `, }, { @@ -99,8 +98,8 @@ func testCases() []struct { }, err: errors.New("an error"), expected: `{"timestamp":{"seconds":100,"nanos":1000},"severity":"INFO","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":37},"message":"info","a":"A"} -{"timestamp":{"seconds":100,"nanos":1000},"severity":"WARNING","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":41},"message":"warn","g":{"b":"B","a":"A"}} -{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":46},"message":"error","context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":46,"functionName":"github.com/nil-go/sloth/gcp_test.TestHandler.func1"}},"serviceContext":{"service":"test","version":"dev"},"stack_trace":"error\n\n\ngithub.com/nil-go/sloth/gcp_test.TestHandler.func1{"h":{"b":"B","error":"an error"}}} +{"timestamp":{"seconds":100,"nanos":1000},"severity":"WARNING","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":42},"message":"warn","g":{"b":"B","a":"A"}} +{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":50},"message":"error","context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":50,"functionName":"github.com/nil-go/sloth/gcp_test.TestHandler.func1"}},"serviceContext":{"service":"test","version":"dev"},"stack_trace":"error\n\n\ngithub.com/nil-go/sloth/gcp_test.TestHandler.func1()\n\t/Users/ktong/Development/github/sloth/gcp/handler_test.go:50"g":{"h":{"b":"B","error":"an error"}}} `, }, { @@ -116,8 +115,8 @@ func testCases() []struct { }, err: errors.New("an error"), expected: `{"timestamp":{"seconds":100,"nanos":1000},"severity":"INFO","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":37},"message":"info","a":"A"} -{"timestamp":{"seconds":100,"nanos":1000},"severity":"WARNING","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":41},"message":"warn","g":{"b":"B","a":"A"}} -{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":46},"message":"error","context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":46,"functionName":"github.com/nil-go/sloth/gcp_test.TestHandler.func1"}},"serviceContext":{"service":"test","version":"dev"},"stack_trace":"error\n\n\ngithub.com/nil-go/sloth/gcp_test.testCases.func1{"h":{"b":"B","error":"an error"}}} +{"timestamp":{"seconds":100,"nanos":1000},"severity":"WARNING","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":42},"message":"warn","g":{"b":"B","a":"A"}} +{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":50},"message":"error","context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":50,"functionName":"github.com/nil-go/sloth/gcp_test.TestHandler.func1"}},"serviceContext":{"service":"test","version":"dev"},"stack_trace":"error\n\n\ngithub.com/nil-go/sloth/gcp_test.testCases.func1()\n\t/Users/ktong/Development/github/sloth/gcp/handler_test.go:111"g":{"h":{"b":"B","error":"an error"}}} `, }, { @@ -127,8 +126,8 @@ func testCases() []struct { }, err: stackError{errors.New("an error")}, expected: `{"timestamp":{"seconds":100,"nanos":1000},"severity":"INFO","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":37},"message":"info","a":"A"} -{"timestamp":{"seconds":100,"nanos":1000},"severity":"WARNING","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":41},"message":"warn","g":{"b":"B","a":"A"}} -{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":46},"message":"error","context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":46,"functionName":"github.com/nil-go/sloth/gcp_test.TestHandler.func1"}},"serviceContext":{"service":"test","version":"dev"},"stack_trace":"error\n\n\ngithub.com/nil-go/sloth/gcp_test.stackError.Callers{"h":{"b":"B","error":"an error"}}} +{"timestamp":{"seconds":100,"nanos":1000},"severity":"WARNING","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":42},"message":"warn","g":{"b":"B","a":"A"}} +{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":50},"message":"error","context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":50,"functionName":"github.com/nil-go/sloth/gcp_test.TestHandler.func1"}},"serviceContext":{"service":"test","version":"dev"},"stack_trace":"error\n\n\ngithub.com/nil-go/sloth/gcp_test.stackError.Callers()\n\t/Users/ktong/Development/github/sloth/gcp/handler_test.go:152"g":{"h":{"b":"B","error":"an error"}}} `, }, { @@ -137,8 +136,8 @@ func testCases() []struct { gcp.WithTrace("test", func(context.Context) gcp.TraceContext { return traceContext{} }), }, expected: `{"timestamp":{"seconds":100,"nanos":1000},"severity":"INFO","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":37},"message":"info","a":"A","logging.googleapis.com/trace":"projects/test/traces/4bf92f3577b34da6a3ce929d0e0e4736","logging.googleapis.com/spanId":"00f067aa0ba902b7","logging.googleapis.com/trace_sampled":true} -{"timestamp":{"seconds":100,"nanos":1000},"severity":"WARNING","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":41},"message":"warn","logging.googleapis.com/trace":"projects/test/traces/4bf92f3577b34da6a3ce929d0e0e4736","logging.googleapis.com/spanId":"00f067aa0ba902b7","logging.googleapis.com/trace_sampled":true,"g":{"b":"B","a":"A"}} -{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":46},"message":"error","logging.googleapis.com/trace":"projects/test/traces/4bf92f3577b34da6a3ce929d0e0e4736","logging.googleapis.com/spanId":"00f067aa0ba902b7","logging.googleapis.com/trace_sampled":true,"g":{"h":{"b":"B"}}} +{"timestamp":{"seconds":100,"nanos":1000},"severity":"WARNING","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":42},"message":"warn","logging.googleapis.com/trace":"projects/test/traces/4bf92f3577b34da6a3ce929d0e0e4736","logging.googleapis.com/spanId":"00f067aa0ba902b7","logging.googleapis.com/trace_sampled":true,"g":{"b":"B","a":"A"}} +{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func1","file":"/handler_test.go","line":50},"message":"error","logging.googleapis.com/trace":"projects/test/traces/4bf92f3577b34da6a3ce929d0e0e4736","logging.googleapis.com/spanId":"00f067aa0ba902b7","logging.googleapis.com/trace_sampled":true,"g":{"h":{"b":"B"}}} `, }, } @@ -155,11 +154,14 @@ func (stackError) Callers() []uintptr { return pcs[:] } -func record(level slog.Level, message string) slog.Record { +func record(level slog.Level, message string, attrs ...any) slog.Record { var pcs [1]uintptr runtime.Callers(2, pcs[:]) - return slog.NewRecord(time.Unix(100, 1000), level, message, pcs[0]) + record := slog.NewRecord(time.Unix(100, 1000), level, message, pcs[0]) + record.Add(attrs...) + + return record } type traceContext struct{}