From 3545ae0e336910f1f24a438e99de8014b4cd72b6 Mon Sep 17 00:00:00 2001 From: ktong Date: Sun, 18 Feb 2024 14:25:22 -0800 Subject: [PATCH] add handler for GCP Cloud Logging --- CHANGELOG.md | 1 + README.md | 1 + gcp/handler.go | 249 ++++++++++++++++++++++++++++++++++++++ gcp/handler_test.go | 124 +++++++++++++++++++ gcp/option.go | 70 +++++++++++ gcp/option_test.go | 61 ++++++++++ internal/assert/assert.go | 19 --- 7 files changed, 506 insertions(+), 19 deletions(-) create mode 100644 gcp/handler.go create mode 100644 gcp/handler_test.go create mode 100644 gcp/option.go create mode 100644 gcp/option_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index ab6485c..490a970 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 (#6). 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..d88f82d --- /dev/null +++ b/gcp/handler.go @@ -0,0 +1,249 @@ +// 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.project != "" || option.service != "" { + handler = logHandler{ + handler: handler, + project: option.project, contextProvider: option.contextProvider, + service: option.service, version: option.version, + } + } + + 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 ( + logHandler struct { + handler slog.Handler + groups []group + + project string + contextProvider func(context.Context) TraceContext + + service string + version string + } + group struct { + name string + attrs []slog.Attr + } +) + +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 + handler := h.handler + + if len(h.groups) > 0 { + var attr slog.Attr + for i := len(h.groups) - 1; i >= 0; i-- { + grp := h.groups[i] + attrs := make([]any, 0, len(grp.attrs)+1) + attrs = append(attrs, attr) + for _, attr := range grp.attrs { + attrs = append(attrs, attr) + } + attr = slog.Group(grp.name, attrs...) + } + handler = handler.WithAttrs([]slog.Attr{attr}) + } + + // [Associate logs] with a trace and span. + // + // [Associate logs]: https://cloud.google.com/trace/docs/trace-log-integration + if h.project != "" { + const sampled = 0x1 + + 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), + }) + } + } + + // Format log to report [error events]. + // + // [error events]: https://cloud.google.com/error-reporting/docs/formatting-error-messages + if record.Level >= slog.LevelError && h.service != "" { + 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.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 logHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(h.groups) == 0 { + h.handler = h.handler.WithAttrs(attrs) + + return h + } + + h.groups = slices.Clone(h.groups) + h.groups[len(h.groups)-1].attrs = slices.Clone(h.groups[len(h.groups)-1].attrs) + h.groups[len(h.groups)-1].attrs = append(h.groups[len(h.groups)-1].attrs, attrs...) + + return h +} + +func (h logHandler) WithGroup(name string) slog.Handler { + h.groups = slices.Clone(h.groups) + h.groups = append(h.groups, group{name: name}) + + return h +} 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..ba0146a --- /dev/null +++ b/gcp/option.go @@ -0,0 +1,70 @@ +// 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.project = project + options.contextProvider = contextProvider + } +} + +type TraceContext interface { + TraceID() [16]byte + SpanID() [8]byte + TraceFlags() byte +} + +func WithErrorReporting(service, version string) Option { + if service == "" { + panic("cannot add error information with empty service") + } + + return func(options *options) { + options.service = service + options.version = version + } +} + +type ( + // Option configures the Handler with specific options. + Option func(*options) + options struct { + writer io.Writer + level slog.Leveler + + // For trace. + project string + contextProvider func(context.Context) TraceContext + + // For error reporting. + service string + version string + } +) diff --git a/gcp/option_test.go b/gcp/option_test.go new file mode 100644 index 0000000..873a61e --- /dev/null +++ b/gcp/option_test.go @@ -0,0 +1,61 @@ +// 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 ( + "context" + "testing" + + "github.com/nil-go/sloth/gcp" + "github.com/nil-go/sloth/internal/assert" +) + +func Test_panic(t *testing.T) { + t.Parallel() + + testcases := []struct { + description string + option func() gcp.Option + err string + }{ + { + description: "project is empty", + option: func() gcp.Option { + return gcp.WithTrace("", func(context.Context) gcp.TraceContext { + return traceContext{} + }) + }, + err: "cannot add trace information with empty project", + }, + { + description: "context provider is nil", + option: func() gcp.Option { + return gcp.WithTrace("test", nil) + }, + err: "cannot add trace information with nil context provider", + }, + { + description: "service is empty", + option: func() gcp.Option { + return gcp.WithErrorReporting("", "dev") + }, + err: "cannot add error information with empty service", + }, + } + + for _, testcase := range testcases { + testcase := testcase + + t.Run(testcase.description, func(t *testing.T) { + t.Parallel() + + defer func() { + assert.Equal(t, testcase.err, recover().(string)) + }() + + testcase.option() + t.Fail() + }) + } +} 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") - } -}