diff --git a/CHANGELOG.md b/CHANGELOG.md index ab6485c..3b91568 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,3 +10,4 @@ to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). ### Added - Add sampling handler for sampling records at request level (#3). +- Add handler to emit JSON logs to GCP Cloud Logging (#5). diff --git a/README.md b/README.md index ec53cf6..a0578de 100644 --- a/README.md +++ b/README.md @@ -9,3 +9,4 @@ Sloth provides opinionated slog handlers for major Cloud providers. It providers following slog handlers: - [`sampling`](sampling) provides a slog handler for sampling records at request level. +- [`gcp`](gcp) provides a slog handler for emitting JSON logs to GCP Cloud Logging. diff --git a/gcp/handler.go b/gcp/handler.go new file mode 100644 index 0000000..8ef7d17 --- /dev/null +++ b/gcp/handler.go @@ -0,0 +1,300 @@ +// Copyright (c) 2024 The sloth authors +// Use of this source code is governed by a MIT license found in the LICENSE file. + +package gcp + +import ( + "bytes" + "context" + "encoding/hex" + "log/slog" + "os" + "runtime" + "runtime/debug" + "slices" + "strconv" + "strings" +) + +func New(opts ...Option) slog.Handler { + option := &options{} + for _, opt := range opts { + opt(option) + } + if option.writer == nil { + option.writer = os.Stderr + } + + var handler slog.Handler + handler = slog.NewJSONHandler( + option.writer, + &slog.HandlerOptions{ + AddSource: true, + Level: option.level, + ReplaceAttr: replaceAttr(), + }, + ) + if option.trace != nil { + option.trace.handler = handler + handler = *option.trace + } + if option.errorReporting != nil { + option.errorReporting.handler = handler + handler = *option.errorReporting + } + + return handler +} + +func replaceAttr() func([]string, slog.Attr) slog.Attr { + // Replace attributes to match GCP Cloud Logging format. + // + // [attributes]: https://cloud.google.com/logging/docs/agent/logging/configuration#special-fields + replacer := map[string]func(slog.Attr) slog.Attr{ + // Maps the slog levels to the correct [severity] for GCP Cloud Logging. + // + // [severity]: https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#LogSeverity + slog.LevelKey: func(attr slog.Attr) slog.Attr { + var severity string + if level, ok := attr.Value.Any().(slog.Level); ok { + switch { + case level >= slog.LevelError: + severity = "ERROR" + case level >= slog.LevelWarn: + severity = "WARNING" + case level >= slog.LevelInfo: + severity = "INFO" + default: + severity = "DEBUG" + } + } + + return slog.String("severity", severity) + }, + slog.SourceKey: func(attr slog.Attr) slog.Attr { + attr.Key = "logging.googleapis.com/sourceLocation" + + return attr + }, + slog.MessageKey: func(attr slog.Attr) slog.Attr { + attr.Key = "message" + + return attr + }, + // Format event [timestamp] according to GCP JSON formats. + // + // [timestamp]: https://cloud.google.com/logging/docs/agent/logging/configuration#timestamp-processing + slog.TimeKey: func(attr slog.Attr) slog.Attr { + time := attr.Value.Time() + + return slog.Group("timestamp", + slog.Int64("seconds", time.Unix()), + slog.Int64("nanos", int64(time.Nanosecond())), + ) + }, + } + + return func(groups []string, attr slog.Attr) slog.Attr { + if len(groups) > 0 { + return attr + } + + if replace, ok := replacer[attr.Key]; ok { + return replace(attr) + } + + return attr + } +} + +type TraceContext interface { + TraceID() [16]byte + SpanID() [8]byte + TraceFlags() byte +} + +type traceHandler struct { + handler slog.Handler + groupAttrs groupAttrs + + project string + contextProvider func(context.Context) TraceContext +} + +func (h traceHandler) Enabled(ctx context.Context, level slog.Level) bool { + return h.handler.Enabled(ctx, level) +} + +func (h traceHandler) Handle(ctx context.Context, record slog.Record) error { + const sampled = 0x1 + + handler := h.handler.WithAttrs([]slog.Attr{h.groupAttrs.attr()}) + if traceContext := h.contextProvider(ctx); traceContext.TraceID() != [16]byte{} { + traceID := traceContext.TraceID() + spanID := traceContext.SpanID() + traceFlags := traceContext.TraceFlags() + 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), + }) + } + for _, group := range h.groupAttrs.groups { + handler = handler.WithGroup(group.name) + } + + return handler.Handle(ctx, record) +} + +func (h traceHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(h.groupAttrs.groups) == 0 { + h.handler = h.handler.WithAttrs(attrs) + } else { + h.groupAttrs = h.groupAttrs.withAttrs(attrs) + } + + return h +} + +func (h traceHandler) WithGroup(name string) slog.Handler { + h.groupAttrs = h.groupAttrs.withGroup(name) + + return h +} + +type errorReportingHandler struct { + handler slog.Handler + groupAttrs groupAttrs + + service string + version string +} + +func (h errorReportingHandler) Enabled(ctx context.Context, level slog.Level) bool { + return h.handler.Enabled(ctx, level) +} + +func (h errorReportingHandler) Handle(ctx context.Context, record slog.Record) error { + // Format log to report [error events]. + // + // [error events]: https://cloud.google.com/error-reporting/docs/formatting-error-messages + handler := h.handler.WithAttrs([]slog.Attr{h.groupAttrs.attr()}) + if record.Level >= slog.LevelError { + firstFrame, _ := runtime.CallersFrames([]uintptr{record.PC}).Next() + handler = handler.WithAttrs( + []slog.Attr{ + slog.Group("context", + slog.Group("reportLocation", + slog.String("filePath", firstFrame.File), + slog.Int("lineNumber", firstFrame.Line), + slog.String("functionName", firstFrame.Function), + ), + ), + slog.Group("serviceContext", + slog.String("service", h.service), + slog.String("version", h.version), + ), + slog.String("stack_trace", stack(record.Message, firstFrame)), + }) + } + for _, group := range h.groupAttrs.groups { + handler = handler.WithGroup(group.name) + } + + return handler.Handle(ctx, record) +} + +func stack(message string, firstFrame runtime.Frame) string { + stackTrace := &strings.Builder{} + stackTrace.WriteString(message) + stackTrace.WriteString("\n\n") + + 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() + } + + // 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 { + break + } + if fileLine, err = frames.ReadBytes('\n'); err != nil { + break + } + if bytes.Contains(functionLine, firstFuncLine) && bytes.Contains(fileLine, firstFileLine) { + stackTrace.Write(functionLine) + stackTrace.Write(fileLine) + _, _ = frames.WriteTo(stackTrace) + + break + } + } + + return stackTrace.String() +} + +func (h errorReportingHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(h.groupAttrs.groups) == 0 { + h.handler = h.handler.WithAttrs(attrs) + } else { + h.groupAttrs = h.groupAttrs.withAttrs(attrs) + } + + return h +} + +func (h errorReportingHandler) WithGroup(name string) slog.Handler { + h.groupAttrs = h.groupAttrs.withGroup(name) + + return h +} + +type ( + groupAttrs struct { + groups []group + } + + group struct { + name string + attrs []slog.Attr + } +) + +func (g groupAttrs) withAttrs(attrs []slog.Attr) groupAttrs { + g.groups = slices.Clone(g.groups) + if len(g.groups) == 0 { + g.groups = append(g.groups, group{}) + } + g.groups[len(g.groups)-1].attrs = slices.Concat(g.groups[len(g.groups)-1].attrs, attrs) + + return g +} + +func (g groupAttrs) withGroup(name string) groupAttrs { + g.groups = slices.Clone(g.groups) + g.groups = append(g.groups, group{name: name}) + + return g +} + +func (g groupAttrs) attr() slog.Attr { + var attr slog.Attr + for i := len(g.groups) - 1; i >= 0; i-- { + group := g.groups[i] + attrs := make([]any, 0, len(group.attrs)+1) + attrs = append(attrs, attr) + for _, attr := range group.attrs { + attrs = append(attrs, attr) + } + attr = slog.Group(group.name, attrs...) + } + + return attr +} diff --git a/gcp/handler_test.go b/gcp/handler_test.go new file mode 100644 index 0000000..8edb1b2 --- /dev/null +++ b/gcp/handler_test.go @@ -0,0 +1,124 @@ +// Copyright (c) 2024 The sloth authors +// Use of this source code is governed by a MIT license found in the LICENSE file. + +package gcp_test + +import ( + "bytes" + "context" + "encoding/hex" + "log/slog" + "os" + "runtime" + "strings" + "testing" + "time" + + "github.com/nil-go/sloth/gcp" + "github.com/nil-go/sloth/internal/assert" +) + +//nolint:lll +func TestHandler(t *testing.T) { + t.Parallel() + + testcases := []struct { + description string + opts []gcp.Option + 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":{"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":{"b":"B"}} +`, + }, + { + description: "with error reporting", + 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":{"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`, + }, + { + 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":{"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))...) + + 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.WithAttrs([]slog.Attr{slog.String("b", "B")}). + Handle(ctx, record(slog.LevelError, "error"))) + } + + 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) + }) + } +} + +func record(level slog.Level, message string) slog.Record { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + + return slog.NewRecord(time.Unix(100, 1000), level, message, pcs[0]) +} + +type traceContext struct{} + +func (traceContext) TraceID() [16]byte { + b, _ := hex.DecodeString("4bf92f3577b34da6a3ce929d0e0e4736") + + return [16]byte(b) +} + +func (traceContext) SpanID() [8]byte { + b, _ := hex.DecodeString("00f067aa0ba902b7") + + return [8]byte(b) +} + +func (traceContext) TraceFlags() byte { + return 1 +} diff --git a/gcp/option.go b/gcp/option.go new file mode 100644 index 0000000..babc25c --- /dev/null +++ b/gcp/option.go @@ -0,0 +1,63 @@ +// Copyright (c) 2024 The sloth authors +// Use of this source code is governed by a MIT license found in the LICENSE file. + +package gcp + +import ( + "context" + "io" + "log/slog" +) + +func WithLevel(level slog.Leveler) Option { + return func(options *options) { + options.level = level + } +} + +func WithWriter(writer io.Writer) Option { + return func(options *options) { + options.writer = writer + } +} + +func WithTrace(project string, contextProvider func(context.Context) TraceContext) Option { + if project == "" { + panic("cannot add trace information with empty project") + } + if contextProvider == nil { + panic("cannot add trace information with nil context provider") + } + + return func(options *options) { + options.trace = &traceHandler{ + project: project, + contextProvider: contextProvider, + } + } +} + +func WithErrorReporting(service, version string) Option { + if service == "" { + panic("cannot add error information with empty service") + } + + return func(options *options) { + options.errorReporting = &errorReportingHandler{ + service: service, + version: version, + } + } +} + +type ( + // Option configures the Handler with specific options. + Option func(*options) + options struct { + writer io.Writer + level slog.Leveler + + trace *traceHandler + errorReporting *errorReportingHandler + } +) diff --git a/internal/assert/assert.go b/internal/assert/assert.go index b8db2e1..42178ec 100644 --- a/internal/assert/assert.go +++ b/internal/assert/assert.go @@ -23,22 +23,3 @@ func NoError(tb testing.TB, err error) { tb.Errorf("unexpected error: %v", err) } } - -func EqualError(tb testing.TB, err error, message string) { - tb.Helper() - - switch { - case err == nil: - tb.Errorf("expected: %v; actual: ", message) - case err.Error() != message: - tb.Errorf("expected: %v; actual: %v", message, err.Error()) - } -} - -func True(tb testing.TB, value bool) { - tb.Helper() - - if !value { - tb.Errorf("expected True") - } -}