Skip to content

Commit

Permalink
use Callers instead of debug.Stack()
Browse files Browse the repository at this point in the history
  • Loading branch information
@ktong
ktong committed Feb 25, 2024
1 parent ad447ce commit ebf3359
Show file tree
Hide file tree
Showing 2 changed files with 71 additions and 63 deletions.
88 changes: 47 additions & 41 deletions gcp/handler.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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 {
Expand All @@ -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(
Expand All @@ -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)),
})
}

Expand All @@ -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))
Expand All @@ -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 {
Expand Down
46 changes: 24 additions & 22 deletions gcp/handler_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
})
Expand All @@ -79,17 +78,17 @@ 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"}}}
`,
},
{
description: "with level",
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"}}}
`,
},
{
Expand All @@ -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"}}}
`,
},
{
Expand All @@ -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"}}}
`,
},
{
Expand All @@ -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"}}}
`,
},
{
Expand All @@ -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"}}}
`,
},
}
Expand All @@ -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{}
Expand Down

0 comments on commit ebf3359

Please sign in to comment.