diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml index fdfecde77af39960b9436d0253c9610b60d1cb70..e2a0e30120a71853f8ce49eda795110d446e911c 100644 --- a/.gitlab-ci.yml +++ b/.gitlab-ci.yml @@ -24,13 +24,13 @@ include: # common to all projects using this template library. # see https://gitlab.com/gitlab-com/gl-infra/common-ci-tasks/-/blob/main/templates/standard.md - project: "gitlab-com/gl-infra/common-ci-tasks" - ref: v2.94 # renovate:managed + ref: v3.0 # renovate:managed file: templates/standard.yml # Runs golang standard tests, including tests, goreleaser, golangci-lint and go-mod-tidy # see https://gitlab.com/gitlab-com/gl-infra/common-ci-tasks/-/blob/main/templates/golang.md - project: 'gitlab-com/gl-infra/common-ci-tasks' - ref: v2.94 # renovate:managed + ref: v3.0 # renovate:managed file: templates/golang.yml - component: "gitlab.com/gitlab-com/gl-infra/common-ci-tasks/danger@v3.0" diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index 10fc2d996b40a0c7a827341c08bf7c12ce350e8b..fa0cdaf7f723e94e8e287b7a5af8b1e163a854a1 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -25,7 +25,7 @@ repos: # Documentation available at # https://gitlab.com/gitlab-com/gl-infra/common-ci-tasks/-/blob/main/docs/pre-commit.md - repo: https://gitlab.com/gitlab-com/gl-infra/common-ci-tasks - rev: v2.94 # renovate:managed + rev: v3.0 # renovate:managed hooks: - id: shellcheck # Run shellcheck for changed Shell files diff --git a/v2/log/README.md b/v2/log/README.md new file mode 100644 index 0000000000000000000000000000000000000000..3ebaa0da07de876ec9e2ac9bb33c2f770f7c5856 --- /dev/null +++ b/v2/log/README.md @@ -0,0 +1,91 @@ +# Log Package + +The log package acts as a helpful abstraction around the `slog` Logger that is built into the +standard library in Go. + +Engineers in GitLab must use this package in order to instantiate loggers for their application to +ensure that there is consistency across all of our services in how we emit logs from our systems. + +## Usage + +```go +// returns a new JSON logger that outputs logs to the stdout +logger := log.New() + +// A standard Info line +logger.Info("some info") +``` + +## Testing Your Observability + +The logs that our systems output represent an often-neglected part of our API. Additional reporting +systems and alerts are typically built on top of log lines and a lack of testing makes these setups +rather fragile in nature. + +It's strongly encouraged that all engineers bake in some form of assertions on the logs that they +rely on for additional observability configuration within their tests. + +```go +// NewWithRecorder returns a logRecorder struct that +// captures all log lines emitted by the `logger` +logger, logRecorder := log.NewWithRecorder() + +// We can then perform assertions on things like how many log lines +// have been emitted +assert.Len(t, recorder.Records, 1) + +// As well as the shape of individual log lines +assert.Equal(t, "test message", recorder.Records[0].Message) +assert.Equal(t, tt.expectedLevel, recorder.Records[0].Level.String()) +assert.Contains(t, recorder.Records[0].Attrs, slog.Attr{Key: "key", Value: slog.AnyValue("value")}) +``` + +These log lines are captured in a `Records` field which is a slice of type `testRecord`: + +```go +// testRecord - a representation of a single log message +type testRecord struct { + Level slog.Level + Message string + Attrs map[string]any +} +``` + +## Context Logger + +There is some important information we need to emit for every log message whenever a request +is processed. This is meta information like correlation_id and perhaps the remote_ip. + +This information is all stored in the context which is enriched at the point at which the +request is being handled. + +The intention then, is that we create a child logger for every request that is stored in +the context and will contain all the necessary fields needed. + +```go +ctx := meta.WithCorrelationID(context.Background(), "1234567890") + +// construct a child logger +logger.InfoContext(ctx, "hello world") +// emitted log line will contain the correlationID +``` + +## Canonical Logger + +Canonical logging is a technique that can be used to help reduce the volume of logs +being emitted from your systems. You are effectively aggregating all of the fields that +you care about through the lifecycle of a request and then logging a single line at the +end of the lifecycle. + +This can be achieved through the use of the + +```go +// pass this logger along the request lifecycle +ctx := context.Background() +ctx = log.WithFields(ctx, slog.String("step", "1")) + +// at the point at which you need to emit the +// final log line, you can opt for the verbose +// approach +logger.InfoContext(ctx, "canonical_log") +``` diff --git a/v2/log/context.go b/v2/log/context.go new file mode 100644 index 0000000000000000000000000000000000000000..ce1e12dee5682adcd075ab016ee1d08a1453b15d --- /dev/null +++ b/v2/log/context.go @@ -0,0 +1,82 @@ +package log + +import ( + "context" + "log/slog" + "reflect" + + "gitlab.com/gitlab-org/labkit/v2/meta" +) + +// loggerKey - a type that uniquely identifies the logger stored in the context. +type logFields struct{} + +// WithField - provides a way to inject more fields into a logger that is then +// persisted in the context. This is useful in situations where they +// need to employ canonical logging in order to limit the number +// of log lines that they emit. +func WithFields(ctx context.Context, attrs ...slog.Attr) context.Context { + existingFields := Fields(ctx) + newFields := make([]slog.Attr, len(existingFields), len(existingFields)+len(attrs)) + copy(newFields, existingFields) + newFields = append(newFields, attrs...) + + return context.WithValue(ctx, logFields{}, newFields) +} + +func Fields(ctx context.Context) []slog.Attr { + if fields, ok := ctx.Value(logFields{}).([]slog.Attr); ok { + return fields + } + return []slog.Attr{} +} + +type ContextHandler struct { + BaseHandler slog.Handler +} + +func NewContextHandler(baseHandler slog.Handler) slog.Handler { + return &ContextHandler{ + BaseHandler: baseHandler, + } +} + +func (c *ContextHandler) Enabled(ctx context.Context, level slog.Level) bool { + return c.BaseHandler.Enabled(ctx, level) +} + +func (c *ContextHandler) Handle(ctx context.Context, r slog.Record) error { + r = EnrichRecordWithMetaData(ctx, r) + return c.BaseHandler.Handle(ctx, r) +} + +func EnrichRecordWithMetaData(ctx context.Context, r slog.Record) slog.Record { + correlationID := meta.CorrelationID(ctx) + r.Add(slog.String("correlation_id", correlationID)) + + contextFields := Fields(ctx) + for _, attr := range contextFields { + r.Add(attr) + } + + fields := meta.MetaFields(ctx) + val := reflect.ValueOf(fields) + t := reflect.TypeOf(fields) + for i := range val.NumField() { + field := t.Field(i) + value := val.Field(i) + + if tag, ok := field.Tag.Lookup("field"); ok { + r.Add(slog.Any(tag, value.Interface())) + } + } + return r +} + +func (c *ContextHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return c.BaseHandler.WithAttrs(attrs) +} + +func (c *ContextHandler) WithGroup(name string) slog.Handler { + return c.BaseHandler.WithGroup(name) +} diff --git a/v2/log/context_test.go b/v2/log/context_test.go new file mode 100644 index 0000000000000000000000000000000000000000..e30cd222a96abc850d57739022a39208b6e4f037 --- /dev/null +++ b/v2/log/context_test.go @@ -0,0 +1,162 @@ +package log_test + +import ( + "context" + "log/slog" + "testing" + + "github.com/stretchr/testify/assert" + "gitlab.com/gitlab-org/labkit/fields" + "gitlab.com/gitlab-org/labkit/v2/log" + "gitlab.com/gitlab-org/labkit/v2/meta" + "gitlab.com/gitlab-org/labkit/v2/testing/logtest" +) + +func TestLogger(t *testing.T) { + t.Run("test context handler", func(t *testing.T) { + ctx := context.Background() + ctx = meta.WithCorrelationID(ctx, "12345") + logger := log.New() + logger.InfoContext(ctx, "hello world") + }) +} + +func TestWithFields(t *testing.T) { + t.Run("adds fields to empty context", func(t *testing.T) { + ctx := context.Background() + ctx = log.WithFields(ctx, slog.String("key1", "value1"), slog.Int("key2", 42)) + + fields := log.Fields(ctx) + assert.Len(t, fields, 2) + assert.Equal(t, "key1", fields[0].Key) + assert.Equal(t, "value1", fields[0].Value.String()) + assert.Equal(t, "key2", fields[1].Key) + assert.Equal(t, int64(42), fields[1].Value.Int64()) + }) + + t.Run("appends fields to existing context", func(t *testing.T) { + ctx := context.Background() + ctx = log.WithFields(ctx, slog.String("key1", "value1")) + ctx = log.WithFields(ctx, slog.String("key2", "value2")) + + fields := log.Fields(ctx) + assert.Len(t, fields, 2) + assert.Equal(t, "key1", fields[0].Key) + assert.Equal(t, "key2", fields[1].Key) + }) + + t.Run("handles multiple fields at once", func(t *testing.T) { + ctx := context.Background() + ctx = log.WithFields(ctx, + slog.String("user", "alice"), + slog.Int("age", 30), + slog.Bool("active", true), + ) + + fields := log.Fields(ctx) + assert.Len(t, fields, 3) + }) + + t.Run("preserves existing fields when adding new ones", func(t *testing.T) { + ctx := context.Background() + ctx = log.WithFields(ctx, slog.String("original", "value")) + + originalFields := log.Fields(ctx) + + ctx = log.WithFields(ctx, slog.String("new", "field")) + + newFields := log.Fields(ctx) + assert.Len(t, newFields, 2) + assert.Equal(t, "original", newFields[0].Key) + + // Verify original slice wasn't modified + assert.Len(t, originalFields, 1) + }) +} + +func TestFields(t *testing.T) { + t.Run("returns empty slice for context without fields", func(t *testing.T) { + ctx := context.Background() + fields := log.Fields(ctx) + + assert.NotNil(t, fields) + assert.Empty(t, fields) + }) + + t.Run("returns fields from context", func(t *testing.T) { + ctx := context.Background() + ctx = log.WithFields(ctx, slog.String("test", "value")) + + fields := log.Fields(ctx) + assert.Len(t, fields, 1) + }) +} + +func TestContextHandler(t *testing.T) { + t.Run("includes correlation ID in log output", func(t *testing.T) { + ctx := context.Background() + ctx = meta.WithCorrelationID(ctx, "test-correlation-123") + + logger, recorder := logtest.NewWithRecorder() + logger.InfoContext(ctx, "test message") + + assert.Len(t, recorder.Records, 1) + record := recorder.Records[0] + assert.Contains(t, record.Attrs, slog.Attr{Key: fields.CorrelationID, Value: slog.AnyValue("test-correlation-123")}) + }) + + t.Run("includes fields from context", func(t *testing.T) { + ctx := context.Background() + ctx = log.WithFields(ctx, + slog.String(fields.GitLabUserID, "user-123"), + slog.String("request_id", "req-456"), + ) + + logger, recorder := logtest.NewWithRecorder() + logger.InfoContext(ctx, "processing request") + + assert.Len(t, recorder.Records, 1) + record := recorder.Records[0] + assert.Contains(t, record.Attrs, slog.Attr{Key: fields.GitLabUserID, Value: slog.AnyValue("user-123")}) + assert.Contains(t, record.Attrs, slog.Attr{Key: "request_id", Value: slog.AnyValue("req-456")}) + }) + + t.Run("combines correlation ID and context fields", func(t *testing.T) { + ctx := context.Background() + ctx = meta.WithCorrelationID(ctx, "correlation-xyz") + ctx = log.WithFields(ctx, + slog.String("action", "create"), + slog.Int("count", 5), + ) + + logger := log.New() + logger.InfoContext(ctx, "operation completed") + }) + + t.Run("handles empty context", func(t *testing.T) { + ctx := context.Background() + + logger, recorder := logtest.NewWithRecorder() + logger.InfoContext(ctx, "simple log message") + + assert.Len(t, recorder.Records, 1) + assert.Equal(t, recorder.Records[0].Message, "simple log message") + }) + + t.Run("fields overwrite each other when the same key is given", func(t *testing.T) { + ctx := context.Background() + ctx = log.WithFields(ctx, slog.String("step", "1")) + ctx = log.WithFields(ctx, slog.String("step", "2")) + ctx = log.WithFields(ctx, slog.String("step", "3")) + + logger, recorder := logtest.NewWithRecorder() + logger.InfoContext(ctx, "multi-step process") + + record := recorder.Records[0] + assert.Equal(t, "multi-step process", record.Message) + assert.Contains(t, record.Attrs, slog.Attr{ + Key: "step", + Value: slog.AnyValue("3"), + }) + }) +} diff --git a/v2/log/log.go b/v2/log/log.go new file mode 100644 index 0000000000000000000000000000000000000000..00aa96d2bd3a76da9211fecd28cd6b929da6e583 --- /dev/null +++ b/v2/log/log.go @@ -0,0 +1,22 @@ +package log + +import ( + "log/slog" + "os" +) + +// New - a handy wrapper that configures the slog.Logger in a consistent +// fashion. +// Engineers should always default to using this constructor to ensure that +// they can take advantage of future global enhancements to our logging +// setup. +func New() *slog.Logger { + return slog.New( + NewContextHandler( + slog.NewJSONHandler( + os.Stdout, + nil, + ), + ), + ) +} diff --git a/v2/log/log_test.go b/v2/log/log_test.go new file mode 100644 index 0000000000000000000000000000000000000000..cc143057220bd3e9be1257074cd22a7895d2ba19 --- /dev/null +++ b/v2/log/log_test.go @@ -0,0 +1,23 @@ +package log_test + +import ( + "context" + "log/slog" + "testing" + + "github.com/stretchr/testify/assert" + "gitlab.com/gitlab-org/labkit/v2/log" + "gitlab.com/gitlab-org/labkit/v2/testing/logtest" +) + +func TestCanonicalLoggingExample(t *testing.T) { + logger, recorder := logtest.NewWithRecorder() + + ctx := log.WithFields(context.Background(), slog.String("hello", "world")) + ctx = log.WithFields(ctx, slog.String("howdy", "world")) + logger.InfoContext(ctx, "canonical_log") + + assert.Equal(t, 1, len(recorder.Records)) + record := recorder.Records[0] + assert.Equal(t, 4, len(record.Attrs)) +} diff --git a/v2/meta/context.go b/v2/meta/context.go new file mode 100644 index 0000000000000000000000000000000000000000..bc038106d035e6eea7a7287b5aec96986e92adef --- /dev/null +++ b/v2/meta/context.go @@ -0,0 +1,65 @@ +package meta + +import ( + "context" +) + +type FieldKey string + +const ( + // CorrelationID - represents the correlationID + // associated with this context. We want to ensure this + // is set as and when the correlation_ID is being declared. + CorrelationIDKey FieldKey = "correlation_id" + + // MetaFieldsKey - This is a mapping of all of the fields that + // we typically want to emit alongside our observability setup. + // Right now, this will be limited to logs-only, but in the future + // it could help enrich spans. + // Given this will likely be very high cardinality data, I highly + // recommend not including it in any metrics being emitted to avoid + // incurring significant cost. + MetaFieldsKey FieldKey = "meta" +) + +// Fields - this is a strongly typed representation of all of +// the various meta fields that we wish to support. +type Fields struct { + // RemoteIP - an example of the kind of meta information + // we want to see transient across all log lines. + RemoteIP string `field:"meta.remote_ip"` +} + +// WithMetaField - allows us to enrich the map of meta.* fields we wish to +// emit in our observability setup. +func WithMetaFields(ctx context.Context, fields Fields) context.Context { + return context.WithValue(ctx, MetaFieldsKey, fields) +} + +// MetaFields - returns all of the meta fields currently +// associated with the context. +// Note: This is not to be used for passing data or business-logic +// between parts of your application. This is explicitly for +// capturing observability focused meta fields. +func MetaFields(ctx context.Context) Fields { + if metaFieldsMap, ok := ctx.Value(MetaFieldsKey).(Fields); ok { + return metaFieldsMap + } + return Fields{} +} + +// WithCorrelationID - enriches the context with the correlationID. +func WithCorrelationID(ctx context.Context, correlationID string) context.Context { + return context.WithValue(ctx, CorrelationIDKey, correlationID) +} + +// CorrelationID - extracts the correlationID from the context or +// returns an empty string if it has not been found. +func CorrelationID(ctx context.Context) string { + if val := ctx.Value(CorrelationIDKey); val != nil { + if idStr, ok := val.(string); ok { + return idStr + } + } + return "" +} diff --git a/v2/meta/context_test.go b/v2/meta/context_test.go new file mode 100644 index 0000000000000000000000000000000000000000..a273824d7a50d4ef7588eacf63bac7cd7ee7f8e0 --- /dev/null +++ b/v2/meta/context_test.go @@ -0,0 +1,24 @@ +package meta + +import ( + "context" + "testing" + + "github.com/stretchr/testify/assert" +) + +func TestMeta(t *testing.T) { + t.Run("test that we can enrich a context with meta fields", func(t *testing.T) { + ctx := context.Background() + ctx = WithMetaFields(ctx, Fields{ + RemoteIP: "1.1.1.1", + }) + fields := MetaFields(ctx) + + assert.Equal(t, "1.1.1.1", fields.RemoteIP) + + // Test with an empty context + emptyCtx := context.Background() + assert.Empty(t, MetaFields(emptyCtx)) + }) +} diff --git a/v2/testing/logtest/log.go b/v2/testing/logtest/log.go new file mode 100644 index 0000000000000000000000000000000000000000..3b8cb5fa2d4924eeea56241d11a3e10ae950c140 --- /dev/null +++ b/v2/testing/logtest/log.go @@ -0,0 +1,83 @@ +package logtest + +import ( + "context" + "log/slog" + "os" + + "gitlab.com/gitlab-org/labkit/v2/log" +) + +// NewWithRecorder - a helper constructor that returns +// an slog Logger that uses the LogRecorder handler. +// This enables engineers to configure their tests with +// a standard slogger, and then perform assertions that +// their code is instrumented properly. +func NewWithRecorder() (*slog.Logger, *LogRecorder) { + recorder := &LogRecorder{ + baseRecorder: log.NewContextHandler(slog.NewJSONHandler(os.Stdout, nil)), + } + return slog.New(recorder), recorder +} + +// LogRecorder - a struct that implements the slog.Handler +// interface and captures all emitted log lines under a +// Records field. +type LogRecorder struct { + Attrs []slog.Attr + Records []testRecord + + baseRecorder slog.Handler +} + +// testRecord - a representation of a single log message. +type testRecord struct { + Level slog.Level + Message string + Attrs []slog.Attr +} + +// Enabled - this handler should always be enabled. +// Warning - this is a test-only handler. +func (h *LogRecorder) Enabled(context.Context, slog.Level) bool { + return true +} + +// Handle - allows us to capture slog.Record's emitted to the log. +// This enables us to assert that logs are correctly emitted +// from user-space code. +func (h *LogRecorder) Handle(ctx context.Context, r slog.Record) error { + r = log.EnrichRecordWithMetaData(ctx, r) + attrs := []slog.Attr{} + attrs = append(attrs, h.Attrs...) + r.Attrs(func(a slog.Attr) bool { + attrs = append(attrs, a) + return true + }) + + h.Records = append(h.Records, testRecord{ + Level: r.Level, + Message: r.Message, + Attrs: attrs, + }) + return nil +} + +// WithAttrs - a method that is necessary to satisfy the slog.Handler +// interface. +// +// Warning - this is a test-only handler. +func (h *LogRecorder) WithAttrs(attrs []slog.Attr) slog.Handler { + h.Attrs = append(attrs, h.Attrs...) + return h +} + +// WithGroup - a method that is necessary to satisfy the slog.Handler +// interface. +// +// Warning - this is a test-only handler. +func (h *LogRecorder) WithGroup(name string) slog.Handler { + // currently a noop, but could be extended in the future to + // allow for tests based on WithGroup functionality. + return h +} diff --git a/v2/testing/logtest/log_test.go b/v2/testing/logtest/log_test.go new file mode 100644 index 0000000000000000000000000000000000000000..7e0fe2e6b1dc1105dc7022155928a2d134b5f939 --- /dev/null +++ b/v2/testing/logtest/log_test.go @@ -0,0 +1,62 @@ +package logtest + +import ( + "log/slog" + "testing" + + "github.com/stretchr/testify/assert" +) + +func TestRecorder(t *testing.T) { + tests := []struct { + name string + logFunc func(*slog.Logger, string, ...any) + expectedLevel string + }{ + { + name: "debug", + logFunc: (*slog.Logger).Debug, + expectedLevel: "DEBUG", + }, + { + name: "info", + logFunc: (*slog.Logger).Info, + expectedLevel: "INFO", + }, + { + name: "warn", + logFunc: (*slog.Logger).Warn, + expectedLevel: "WARN", + }, + { + name: "error", + logFunc: (*slog.Logger).Error, + expectedLevel: "ERROR", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + logger, recorder := NewWithRecorder() + tt.logFunc(logger, "test message", "key", "value") + assert.Len(t, recorder.Records, 1) + assert.Equal(t, "test message", recorder.Records[0].Message) + assert.Equal(t, tt.expectedLevel, recorder.Records[0].Level.String()) + assert.Contains(t, recorder.Records[0].Attrs, slog.Attr{Key: "key", Value: slog.AnyValue("value")}) + }) + } +} + +func TestWithAttrs(t *testing.T) { + logger, recorder := NewWithRecorder() + logger = logger.With("key", "value") + logger.Info("test message") + assert.Equal(t, 1, len(recorder.Attrs)) + record := recorder.Records[0] + assert.Contains(t, record.Attrs, slog.Attr{ + Key: "key", + Value: slog.AnyValue("value"), + }) + + t.Logf("%+v\n", record) +}