Skip to content

Commit

Permalink
all stack in error
Browse files Browse the repository at this point in the history
  • Loading branch information
@ktong
ktong committed Feb 24, 2024
1 parent d9ad8d8 commit d3a8f4c
Show file tree
Hide file tree
Showing 4 changed files with 171 additions and 54 deletions.
4 changes: 4 additions & 0 deletions CHANGELOG.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,10 @@ to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).

## [Unreleased]

### Add

- Add gcp.WithCallers to retrieve stack trace from error (#14).

## [0.1.1] - 2024-02-23

### Changed
Expand Down
68 changes: 58 additions & 10 deletions gcp/handler.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@ import (
"bytes"
"context"
"encoding/hex"
"errors"
"log/slog"
"os"
"runtime"
Expand Down Expand Up @@ -50,10 +51,22 @@ func New(opts ...Option) slog.Handler {
},
)
if option.project != "" || option.service != "" {
if option.callers == nil {
option.callers = func(err error) []uintptr {
var callers interface{ Callers() []uintptr }
if errors.As(err, &callers) {
return callers.Callers()
}

return nil
}
}

handler = logHandler{
handler: handler,
project: option.project, contextProvider: option.contextProvider,
service: option.service, version: option.version,
callers: option.callers,
}
}

Expand Down Expand Up @@ -128,6 +141,7 @@ type (

service string
version string
callers func(error) []uintptr
}
group struct {
name string
Expand Down Expand Up @@ -191,6 +205,27 @@ 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.Any().(error); ok {
callers = h.callers(err)

return false
}

return true
})

if len(callers) > 0 {
stackFromCallers(&stackTrace, callers)
} else {
stack(&stackTrace, firstFrame)
}

handler = handler.WithAttrs(
[]slog.Attr{
{
Expand All @@ -213,7 +248,7 @@ func (h logHandler) Handle(ctx context.Context, record slog.Record) error { //no
slog.String("version", h.version),
),
},
slog.String("stack_trace", stack(record.Message, firstFrame)),
slog.String("stack_trace", stackTrace.String()),
})
}

Expand All @@ -224,22 +259,37 @@ func (h logHandler) Handle(ctx context.Context, record slog.Record) error { //no
return handler.Handle(ctx, record)
}

func stack(message string, firstFrame runtime.Frame) string {
var stackTrace strings.Builder
stackTrace.WriteString(message)
stackTrace.WriteString("\n\n")
func stackFromCallers(stackTrace *strings.Builder, callers []uintptr) {
stackTrace.WriteString("goroutine 1 [running]:\n")
frames := runtime.CallersFrames(callers)
for {
frame, more := frames.Next()
stackTrace.WriteString(frame.Function)
stackTrace.WriteString("()\n\t")
stackTrace.WriteString(frame.File)
stackTrace.WriteString(":")
stackTrace.WriteString(strconv.Itoa(frame.Line))
stackTrace.WriteString(" +0x")
stackTrace.WriteString(strconv.FormatUint(uint64(frame.PC-frame.Entry), 16))
stackTrace.WriteString("\n")

if !more {
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 stackTrace.String()
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)
firstFileLine := []byte(firstFrame.File + ":" + strconv.Itoa(firstFrame.Line))
var functionLine, fileLine []byte
for {
if functionLine, err = frames.ReadBytes('\n'); err != nil {
Expand All @@ -248,16 +298,14 @@ func stack(message string, firstFrame runtime.Frame) string {
if fileLine, err = frames.ReadBytes('\n'); err != nil {
break
}
if bytes.Contains(functionLine, firstFuncLine) && bytes.Contains(fileLine, firstFileLine) {
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
143 changes: 99 additions & 44 deletions gcp/handler_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@ import (
"bytes"
"context"
"encoding/hex"
"errors"
"log/slog"
"os"
"runtime"
Expand All @@ -18,84 +19,138 @@ import (
"github.com/nil-go/sloth/internal/assert"
)

//nolint:lll
func TestHandler(t *testing.T) {
t.Parallel()

testcases := []struct {
for _, testcase := range testCases() {
testcase := testcase

t.Run(testcase.description, func(t *testing.T) {
t.Parallel()

buf := &bytes.Buffer{}
handler := gcp.New(append(testcase.opts, gcp.WithWriter(buf))...)

ctx := context.Background()
if handler.Enabled(ctx, slog.LevelInfo) {
assert.NoError(t, handler.WithAttrs([]slog.Attr{slog.String("a", "A")}).
Handle(ctx, record(slog.LevelInfo, "info")))
}
gHandler := handler.WithGroup("g")
if handler.Enabled(ctx, slog.LevelWarn) {
record := record(slog.LevelWarn, "warn")
record.Add("a", "A")
assert.NoError(t, gHandler.Handle(ctx, record))
}
if handler.Enabled(ctx, slog.LevelError) {
record := record(slog.LevelError, "error")
if testcase.err != nil {
record.Add("error", testcase.err)
}
assert.NoError(t, gHandler.WithGroup("h").WithAttrs([]slog.Attr{slog.String("b", "B")}).
Handle(ctx, record))
}

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":`)
log = strings.ReplaceAll(log, path, "")
assert.Equal(t, testcase.expected, log+before+after)
})
}
}

//nolint:lll
func testCases() []struct {
description string
opts []gcp.Option
err error
expected string
} {
return []struct {
description string
opts []gcp.Option
err error
expected string
}{
{
description: "default",
expected: `{"timestamp":{"seconds":100,"nanos":1000},"severity":"INFO","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func2","file":"/handler_test.go","line":79},"message":"info","a":"A"}
{"timestamp":{"seconds":100,"nanos":1000},"severity":"WARNING","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func2","file":"/handler_test.go","line":83},"message":"warn","g":{"a":"A"}}
{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func2","file":"/handler_test.go","line":89},"message":"error","g":{"h":{"b":"B"}}}
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":{"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"}}}
`,
},
{
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.func2","file":"/handler_test.go","line":83},"message":"warn","g":{"a":"A"}}
{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func2","file":"/handler_test.go","line":89},"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":41},"message":"warn","g":{"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"}}}
`,
},
{
description: "with error reporting (original stack)",
opts: []gcp.Option{
gcp.WithErrorReporting("test", "dev"),
},
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":{"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"}},"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`,
},
{
description: "with error reporting (caller stack)",
opts: []gcp.Option{
gcp.WithErrorReporting("test", "dev"),
gcp.WithCallers(func(error) []uintptr {
var pcs [1]uintptr
runtime.Callers(1, pcs[:])

return pcs[:]
}),
},
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":{"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"}},"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":{"error":"an error"}}}
`,
},
{
description: "with error reporting",
description: "with error reporting (error stack)",
opts: []gcp.Option{
gcp.WithErrorReporting("test", "dev"),
},
expected: `{"timestamp":{"seconds":100,"nanos":1000},"severity":"INFO","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func2","file":"/handler_test.go","line":79},"message":"info","a":"A"}
{"timestamp":{"seconds":100,"nanos":1000},"severity":"WARNING","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func2","file":"/handler_test.go","line":83},"message":"warn","g":{"a":"A"}}
{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func2","file":"/handler_test.go","line":89},"message":"error","g":{"h":{"b":"B"}},"context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":89,"functionName":"github.com/nil-go/sloth/gcp_test.TestHandler.func2"}},"serviceContext":{"service":"test","version":"dev"},"stack_trace":"error\n\n`,
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":{"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"}},"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":{"error":"an error"}}}
`,
},
{
description: "with trace",
opts: []gcp.Option{
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.func2","file":"/handler_test.go","line":79},"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.func2","file":"/handler_test.go","line":83},"message":"warn","logging.googleapis.com/trace":"projects/test/traces/4bf92f3577b34da6a3ce929d0e0e4736","logging.googleapis.com/spanId":"00f067aa0ba902b7","logging.googleapis.com/trace_sampled":true,"g":{"a":"A"}}
{"timestamp":{"seconds":100,"nanos":1000},"severity":"ERROR","logging.googleapis.com/sourceLocation":{"function":"github.com/nil-go/sloth/gcp_test.TestHandler.func2","file":"/handler_test.go","line":89},"message":"error","g":{"h":{"b":"B"}},"logging.googleapis.com/trace":"projects/test/traces/4bf92f3577b34da6a3ce929d0e0e4736","logging.googleapis.com/spanId":"00f067aa0ba902b7","logging.googleapis.com/trace_sampled":true}
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":{"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"}},"logging.googleapis.com/trace":"projects/test/traces/4bf92f3577b34da6a3ce929d0e0e4736","logging.googleapis.com/spanId":"00f067aa0ba902b7","logging.googleapis.com/trace_sampled":true}
`,
},
}
}

for _, testcase := range testcases {
testcase := testcase

t.Run(testcase.description, func(t *testing.T) {
t.Parallel()

buf := &bytes.Buffer{}
handler := gcp.New(append(testcase.opts, gcp.WithWriter(buf))...)
type stackError struct {
error
}

ctx := context.Background()
if handler.Enabled(ctx, slog.LevelInfo) {
assert.NoError(t, handler.WithAttrs([]slog.Attr{slog.String("a", "A")}).
Handle(ctx, record(slog.LevelInfo, "info")))
}
gHandler := handler.WithGroup("g")
if handler.Enabled(ctx, slog.LevelWarn) {
record := record(slog.LevelWarn, "warn")
record.Add("a", "A")
assert.NoError(t, gHandler.Handle(ctx, record))
}
if handler.Enabled(ctx, slog.LevelError) {
assert.NoError(t, gHandler.WithGroup("h").WithAttrs([]slog.Attr{slog.String("b", "B")}).
Handle(ctx, record(slog.LevelError, "error")))
}
func (stackError) Callers() []uintptr {
var pcs [1]uintptr
runtime.Callers(1, pcs[:])

path, err := os.Getwd()
assert.NoError(t, err)
log, _, _ := strings.Cut(buf.String(), "goroutine ")
log = strings.ReplaceAll(log, path, "")
assert.Equal(t, testcase.expected, log)
})
}
return pcs[:]
}

func record(level slog.Level, message string) slog.Record {
Expand Down
10 changes: 10 additions & 0 deletions gcp/option.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -70,6 +70,15 @@ func WithErrorReporting(service, version string) Option {
}
}

// WithCallers provides a function to get callers on the calling goroutine's stack.
//
// If Callers is nil, the handler checks method Callers() []uintptr on the error.
func WithCallers(callers func(error) []uintptr) Option {
return func(options *options) {
options.callers = callers
}
}

type (
// Option configures the Handler with specific options.
Option func(*options)
Expand All @@ -84,5 +93,6 @@ type (
// For error reporting.
service string
version string
callers func(error) []uintptr
}
)

0 comments on commit d3a8f4c

Please sign in to comment.