Skip to content

Commit

Permalink
pass through log with invalid trace context (#28)
Browse files Browse the repository at this point in the history
  • Loading branch information
@ktong
ktong authored Mar 11, 2024
1 parent f0d7bcf commit ddaf185
Show file tree
Hide file tree
Showing 6 changed files with 82 additions and 53 deletions.
5 changes: 5 additions & 0 deletions CHANGELOG.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,11 @@ to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).

## [Unreleased]

## [0.2.3] - 2024-03-11

### Fixed
- Pass through log with invalid trace context (#28).

## [0.2.2] - 2024-02-26

### Removed
Expand Down
26 changes: 17 additions & 9 deletions gcp/handler.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -181,6 +181,7 @@ type (
handler slog.Handler

contextProvider func(context.Context) (traceID [16]byte, spanID [8]byte, traceFlags byte)
hasTrace bool

service string
version string
Expand All @@ -198,23 +199,27 @@ func (h logHandler) Enabled(ctx context.Context, level slog.Level) bool {
return h.handler.Enabled(ctx, level)
}

func (h logHandler) Handle(ctx context.Context, record slog.Record) error { //nolint:funlen
func (h logHandler) Handle(ctx context.Context, record slog.Record) error { //nolint:cyclop,funlen
var attrs []slog.Attr

// Associate logs with a trace and span.
//
// See: https://cloud.google.com/trace/docs/trace-log-integration
if h.contextProvider != nil {
if !h.hasTrace && h.contextProvider != nil { //nolint:nestif
var found bool
record.Attrs(func(attr slog.Attr) bool {
if attr.Key == TraceKey {
found = true
// Only search for trace attributes if there are no groups.
if len(h.groups) == 0 {
record.Attrs(func(attr slog.Attr) bool {
if attr.Key == TraceKey {
found = true

return false
}
return false
}

return true
})
}

return true
})
if !found {
if traceID, spanID, traceFlags := h.contextProvider(ctx); traceID != [16]byte{} {
attrs = append(attrs,
Expand Down Expand Up @@ -347,6 +352,9 @@ func stack(message string, callers []uintptr) string {
func (h logHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
if len(h.groups) == 0 {
h.handler = h.handler.WithAttrs(attrs)
if slices.ContainsFunc(attrs, func(attr slog.Attr) bool { return attr.Key == TraceKey }) {
h.hasTrace = true
}

return h
}
Expand Down
53 changes: 27 additions & 26 deletions gcp/handler_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -32,12 +32,13 @@ func TestHandler(t *testing.T) {

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",
"trace_id", "4bf92f3577b34da6a3ce929d0e0e4736",
"span_id", "00f067aa0ba902b7",
"trace_flags", "01"),
))
attrs := []slog.Attr{
slog.String("a", "A"),
slog.String("trace_id", "4bf92f3577b34da6a3ce929d0e0e4736"),
slog.String("span_id", "00f067aa0ba902b7"),
slog.String("trace_flags", "01"),
}
assert.NoError(t, handler.WithAttrs(attrs).Handle(ctx, record(slog.LevelInfo, "info")))
}
gHandler := handler.WithGroup("g")
if handler.Enabled(ctx, slog.LevelWarn) {
Expand Down Expand Up @@ -101,18 +102,18 @@ 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":36},"message":"info","a":"A","trace_id":"4bf92f3577b34da6a3ce929d0e0e4736","span_id":"00f067aa0ba902b7","trace_flags":"01"}
{"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":45},"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":53},"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":41},"message":"info","a":"A","trace_id":"4bf92f3577b34da6a3ce929d0e0e4736","span_id":"00f067aa0ba902b7","trace_flags":"01"}
{"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":46},"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":54},"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":45},"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":53},"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":46},"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":54},"message":"error","g":{"h":{"b":"B"}}}
`,
},
{
Expand All @@ -121,9 +122,9 @@ func testcases() []struct {
gcp.WithErrorReporting("test", "dev"),
},
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":36},"message":"info","a":"A","trace_id":"4bf92f3577b34da6a3ce929d0e0e4736","span_id":"00f067aa0ba902b7","trace_flags":"01"}
{"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":45},"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":53},"message":"error","context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":53,"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/handler_test.go:53"g":{"h":{"b":"B","error":"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":41},"message":"info","a":"A","trace_id":"4bf92f3577b34da6a3ce929d0e0e4736","span_id":"00f067aa0ba902b7","trace_flags":"01"}
{"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":46},"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":54},"message":"error","context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":54,"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/handler_test.go:54"g":{"h":{"b":"B","error":"an error"}}}
`,
},
{
Expand All @@ -138,9 +139,9 @@ 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":36},"message":"info","a":"A","trace_id":"4bf92f3577b34da6a3ce929d0e0e4736","span_id":"00f067aa0ba902b7","trace_flags":"01"}
{"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":45},"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":53},"message":"error","context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":53,"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/handler_test.go:135"g":{"h":{"b":"B","error":"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":41},"message":"info","a":"A","trace_id":"4bf92f3577b34da6a3ce929d0e0e4736","span_id":"00f067aa0ba902b7","trace_flags":"01"}
{"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":46},"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":54},"message":"error","context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":54,"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/handler_test.go:136"g":{"h":{"b":"B","error":"an error"}}}
`,
},
{
Expand All @@ -149,19 +150,19 @@ func testcases() []struct {
gcp.WithErrorReporting("test", "dev"),
},
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":36},"message":"info","a":"A","trace_id":"4bf92f3577b34da6a3ce929d0e0e4736","span_id":"00f067aa0ba902b7","trace_flags":"01"}
{"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":45},"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":53},"message":"error","context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":53,"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/handler_test.go:74"g":{"h":{"b":"B","error":"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":41},"message":"info","a":"A","trace_id":"4bf92f3577b34da6a3ce929d0e0e4736","span_id":"00f067aa0ba902b7","trace_flags":"01"}
{"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":46},"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":54},"message":"error","context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":54,"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/handler_test.go:75"g":{"h":{"b":"B","error":"an error"}}}
`,
},
{
description: "with trace",
opts: []gcp.Option{
gcp.WithTrace("test"),
},
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":36},"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":45},"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":53},"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":41},"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":46},"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":54},"message":"error","g":{"h":{"b":"B"}}}
`,
},
{
Expand All @@ -174,9 +175,9 @@ func testcases() []struct {
1
}),
},
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":36},"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":45},"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":53},"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"}}}
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":41},"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":46},"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":54},"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 Down
3 changes: 1 addition & 2 deletions otel/event.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -56,8 +56,6 @@ func (e eventHandler) Handle(ctx context.Context, record slog.Record) {
span := trace.SpanFromContext(ctx)
switch {
case record.Level >= slog.LevelError:
span.SetStatus(codes.Error, record.Message)

var err error
for _, e := range errs {
err = errors.Join(err, e)
Expand All @@ -68,6 +66,7 @@ func (e eventHandler) Handle(ctx context.Context, record slog.Record) {
err = fmt.Errorf("%s: %w", record.Message, err)
}
span.RecordError(err, trace.WithTimestamp(record.Time), trace.WithAttributes(attrs...))
span.SetStatus(codes.Error, record.Message)
default:
for k, v := range errs {
attrs = append(attrs, attribute.String(e.prefix+k, v.Error()))
Expand Down
20 changes: 8 additions & 12 deletions otel/handler.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -82,29 +82,25 @@ func (h Handler) Enabled(ctx context.Context, level slog.Level) bool {
}

func (h Handler) Handle(ctx context.Context, record slog.Record) error {
var attrs []slog.Attr

handler := h.handler
if spanContext := trace.SpanContextFromContext(ctx); spanContext.IsValid() {
tid := spanContext.TraceID()
sid := spanContext.SpanID()
flags := spanContext.TraceFlags()
attrs = append(attrs,
handler = handler.WithAttrs([]slog.Attr{
slog.String(TraceKey, hex.EncodeToString(tid[:])),
slog.String(SpanKey, hex.EncodeToString(sid[:])),
slog.String(TraceFlagsKey, hex.EncodeToString([]byte{byte(flags)})),
)
}
})

if h.recordEvent && h.eventHandler.Enabled(ctx) {
h.eventHandler.Handle(ctx, record)
if !h.passThrough {
return nil
if h.recordEvent && h.eventHandler.Enabled(ctx) {
h.eventHandler.Handle(ctx, record)
if !h.passThrough {
return nil
}
}
}

// Have to add the attributes to the handler before adding the group.
// Otherwise, the attributes are added to the group.
handler := h.handler.WithAttrs(attrs)
for _, group := range h.groups {
handler = handler.WithGroup(group.name).WithAttrs(group.attrs)
}
Expand Down
Loading

0 comments on commit ddaf185

Please sign in to comment.