From 3ccfdbee91b6f80596815140a1296064662b3280 Mon Sep 17 00:00:00 2001 From: Kuisong Tong Date: Wed, 21 Feb 2024 08:53:42 -0800 Subject: [PATCH] add handler for GCP Cloud Logging (#6) --- .github/workflows/lint.yml | 2 +- CHANGELOG.md | 1 + README.md | 3 +- gcp/handler.go | 275 +++++++++++++++++++++++++++++++++++++ gcp/handler_test.go | 124 +++++++++++++++++ gcp/option.go | 88 ++++++++++++ gcp/option_test.go | 61 ++++++++ internal/assert/assert.go | 19 --- sampling/handler.go | 2 +- 9 files changed, 553 insertions(+), 22 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/.github/workflows/lint.yml b/.github/workflows/lint.yml index 422a085..4bb1e3b 100644 --- a/.github/workflows/lint.yml +++ b/.github/workflows/lint.yml @@ -19,7 +19,7 @@ jobs: - uses: actions/setup-go@v5 with: go-version: 'stable' - cache-dependency-path: "**/go.sum" + cache: false - name: Lint uses: golangci/golangci-lint-action@v4 with: 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..3f1126b 100644 --- a/README.md +++ b/README.md @@ -1,4 +1,4 @@ -# :water_buffalo: An opinionated minimalist Go application framework +# Opinionated Go slog handlers ![Go Version](https://img.shields.io/github/go-mod/go-version/nil-go/sloth) [![Go Reference](https://pkg.go.dev/badge/github.com/nil-go/sloth.svg)](https://pkg.go.dev/github.com/nil-go/sloth) @@ -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..4ae1815 --- /dev/null +++ b/gcp/handler.go @@ -0,0 +1,275 @@ +// Copyright (c) 2024 The sloth authors +// Use of this source code is governed by a MIT license found in the LICENSE file. + +/* +Package gcp provides a handler for emitting log records to [GCP Cloud Logging]. + +The handler formats records to match [GCP Cloud Logging JSON schema]. +It also integrates logs with [GCP Cloud Trace] and [GCP Error Reporting] if enabled. + +[GCP Cloud Logging]: https://cloud.google.com/logging +[GCP Cloud Logging JSON schema]: https://cloud.google.com/logging/docs/agent/logging/configuration#special-fields +[GCP Cloud Trace]: https://cloud.google.com/trace +[GCP Error Reporting]: https://cloud.google.com/error-reporting +*/ +package gcp + +import ( + "bytes" + "context" + "encoding/hex" + "log/slog" + "os" + "runtime" + "runtime/debug" + "slices" + "strconv" + "strings" +) + +// New creates a new Handler with the given Option(s). +// The handler formats records to match [GCP Cloud Logging JSON schema]. +// +// [GCP Cloud Logging JSON schema]: https://cloud.google.com/logging/docs/agent/logging/configuration#special-fields +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. + // + // See: 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. + // + // See: 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. + // + // See: 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:cyclop,funlen + handler := h.handler + + if len(h.groups) > 0 { + var ( + attr slog.Attr + hasAttr bool + ) + for i := len(h.groups) - 1; i >= 0; i-- { + grp := h.groups[i] + + attrs := make([]any, 0, len(grp.attrs)+1) + if hasAttr { + attrs = append(attrs, attr) + } + for _, attr := range grp.attrs { + attrs = append(attrs, attr) + } + if len(attrs) > 0 { + attr = slog.Group(grp.name, attrs...) + hasAttr = true + } + } + if hasAttr { + handler = handler.WithAttrs([]slog.Attr{attr}) + } + } + + // Associate logs with a trace and span. + // + // See: 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. + // + // 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() + 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..49d850d --- /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":{"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"}}} +`, + }, + { + 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":{"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`, + }, + { + 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} +`, + }, + } + + 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.WithGroup("h").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..b20b6fd --- /dev/null +++ b/gcp/option.go @@ -0,0 +1,88 @@ +// 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" +) + +// WithLevel provides the minimum record level that will be logged. +// The handler discards records with lower levels. +// +// If Level is nil, the handler assumes LevelInfo. +func WithLevel(level slog.Leveler) Option { + return func(options *options) { + options.level = level + } +} + +// WithWriter provides the writer to which the handler writes. +// +// If Writer is nil, the handler assumes os.Stderr. +func WithWriter(writer io.Writer) Option { + return func(options *options) { + options.writer = writer + } +} + +// WithTrace enables [trace information] added to the log for [GCP Cloud Trace] integration. +// +// [trace information]: https://cloud.google.com/trace/docs/trace-log-integration +// [GCP Cloud Trace]: https://cloud.google.com/trace +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 + } +} + +// TraceContext providers the [W3C Trace Context]. +// +// [W3C Trace Context]: https://www.w3.org/TR/trace-context/#trace-id +type TraceContext interface { + TraceID() [16]byte + SpanID() [8]byte + TraceFlags() byte +} + +// WithErrorReporting enables logs reported as [error events] to [GCP Error Reporting]. +// +// [error events]: https://cloud.google.com/error-reporting/docs/formatting-error-messages +// [GCP Error Reporting]: https://cloud.google.com/error-reporting +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..8c12fbf --- /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 TestOption_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") - } -} diff --git a/sampling/handler.go b/sampling/handler.go index ba0c6f5..2d9e9bd 100644 --- a/sampling/handler.go +++ b/sampling/handler.go @@ -2,7 +2,7 @@ // Use of this source code is governed by a MIT license found in the LICENSE file. /* -package sampling provides a handler for sampling records at request level. +Package sampling provides a handler for sampling records at request level. It discards records with lower than the minimum level if request is unsampled. For example, if the minimum level is slog.LevelError, it logs records with slog.LevelError and above regardless,