Skip to content

Commit

Permalink
support trace information replacement
Browse files Browse the repository at this point in the history
  • Loading branch information
@ktong
ktong committed Feb 25, 2024
1 parent 7fb4e0b commit 5651325
Show file tree
Hide file tree
Showing 3 changed files with 102 additions and 57 deletions.
65 changes: 47 additions & 18 deletions gcp/handler.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -45,7 +45,7 @@ func New(opts ...Option) slog.Handler {
&slog.HandlerOptions{
AddSource: true,
Level: option.level,
ReplaceAttr: replaceAttr(),
ReplaceAttr: replaceAttr(option.project),
},
)
if option.project != "" || option.service != "" {
Expand All @@ -61,17 +61,16 @@ func New(opts ...Option) slog.Handler {
}

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

return handler
}

func replaceAttr() func(groups []string, attr slog.Attr) slog.Attr { //nolint:cyclop
func replaceAttr(project string) func(groups []string, attr slog.Attr) slog.Attr { //nolint:cyclop,funlen
return func(groups []string, attr slog.Attr) slog.Attr {
if len(groups) > 0 {
return attr
Expand Down Expand Up @@ -124,10 +123,31 @@ func replaceAttr() func(groups []string, attr slog.Attr) slog.Attr { //nolint:cy
attr.Key = "message"

return attr
}

default:
return attr
// Associate logs with a trace and span.
//
// See: https://cloud.google.com/trace/docs/trace-log-integration
if project != "" {
switch attr.Key {
case "trace-id":
return slog.String("logging.googleapis.com/trace", "projects/"+project+"/traces/"+attr.Value.String())
case "span-id":
attr.Key = "logging.googleapis.com/spanId"

return attr
case "trace-flags":
var sampled bool
flags, _ := hex.DecodeString(attr.Value.String())
if len(flags) > 0 {
sampled = flags[0]&0x1 == 0x1 //nolint:gomnd
}

return slog.Bool("logging.googleapis.com/trace_sampled", sampled)
}
}

return attr
}
}

Expand All @@ -136,7 +156,6 @@ type (
handler slog.Handler
groups []group

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

service string
Expand All @@ -159,15 +178,25 @@ func (h logHandler) Handle(ctx context.Context, record slog.Record) error { //no
// Associate logs with a trace and span.
//
// See: https://cloud.google.com/trace/docs/trace-log-integration
if h.project != "" && h.contextProvider != nil {
const sampled = 0x1

if traceID, spanID, traceFlags := h.contextProvider(ctx); traceID != [16]byte{} {
handler = handler.WithAttrs([]slog.Attr{
slog.String("logging.googleapis.com/trace", "projects/"+h.project+"/traces/"+hex.EncodeToString(traceID[:])),
slog.String("logging.googleapis.com/spanId", hex.EncodeToString(spanID[:])),
slog.Bool("logging.googleapis.com/trace_sampled", traceFlags&sampled == sampled),
})
if h.contextProvider != nil {
var found bool
record.Attrs(func(attr slog.Attr) bool {
if attr.Key == "trace-id" {
found = true

return false
}

return true
})
if !found {
if traceID, spanID, traceFlags := h.contextProvider(ctx); traceID != [16]byte{} {
handler = handler.WithAttrs([]slog.Attr{
slog.String("trace-id", hex.EncodeToString(traceID[:])),
slog.String("span-id", hex.EncodeToString(spanID[:])),
slog.String("trace-flags", hex.EncodeToString([]byte{traceFlags})),
})
}
}
}

Expand Down
92 changes: 53 additions & 39 deletions gcp/handler_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,11 @@ 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")))
Handle(ctx, record(slog.LevelInfo, "info",
"trace-id", "4bf92f3577b34da6a3ce929d0e0e4736",
"span-id", "00f067aa0ba902b7",
"trace-flags", "01"),
))
}
gHandler := handler.WithGroup("g")
if handler.Enabled(ctx, slog.LevelWarn) {
Expand Down Expand Up @@ -61,6 +65,27 @@ func TestHandler(t *testing.T) {
}
}

type stackError struct {
error
}

func (stackError) Callers() []uintptr {
var pcs [1]uintptr
runtime.Callers(1, pcs[:])

return pcs[:]
}

func record(level slog.Level, message string, attrs ...any) slog.Record {
var pcs [1]uintptr
runtime.Callers(2, pcs[:])

record := slog.NewRecord(time.Unix(100, 1000), level, message, pcs[0])
record.Add(attrs...)

return record
}

//nolint:lll
func testCases() []struct {
description string
Expand All @@ -76,18 +101,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"}
{"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":49},"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":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"}}}
`,
},
{
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":49},"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":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"}}}
`,
},
{
Expand All @@ -96,9 +121,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"}
{"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":49},"message":"error","context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":49,"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:49"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":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"}}}
`,
},
{
Expand All @@ -113,9 +138,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"}
{"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":49},"message":"error","context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":49,"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:110"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":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"}}}
`,
},
{
Expand All @@ -124,46 +149,35 @@ 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"}
{"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":49},"message":"error","context":{"reportLocation":{"filePath":"/handler_test.go","lineNumber":49,"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:156"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":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"}}}
`,
},
{
description: "with trace",
opts: []gcp.Option{
gcp.WithTrace("test"),
gcp.WithTraceContext(func(context.Context) (traceID [16]byte, spanID [8]byte, traceFlags byte) {
},
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"}}}
`,
},
{
description: "with trace context",
opts: []gcp.Option{
gcp.WithTrace("test"),
gcp.WithTraceContext(func(context.Context) ([16]byte, [8]byte, byte) {
return [16]byte{75, 249, 47, 53, 119, 179, 77, 166, 163, 206, 146, 157, 14, 14, 71, 54},
[8]byte{0, 240, 103, 170, 11, 169, 2, 183},
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":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":49},"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":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"}}}
`,
},
}
}

type stackError struct {
error
}

func (stackError) Callers() []uintptr {
var pcs [1]uintptr
runtime.Callers(1, pcs[:])

return pcs[:]
}

func record(level slog.Level, message string, attrs ...any) slog.Record {
var pcs [1]uintptr
runtime.Callers(2, pcs[:])

record := slog.NewRecord(time.Unix(100, 1000), level, message, pcs[0])
record.Add(attrs...)

return record
}
2 changes: 2 additions & 0 deletions gcp/option.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,8 @@ func WithWriter(writer io.Writer) Option {
}

// WithTrace enables [trace information] added to the log for [GCP Cloud Trace] integration.
// The handler use function set in WithTraceContext to get trace information
// if it does not present in record's attributes yet.
//
// [trace information]: https://cloud.google.com/trace/docs/trace-log-integration
// [GCP Cloud Trace]: https://cloud.google.com/trace
Expand Down

0 comments on commit 5651325

Please sign in to comment.