From b841e4d9f9ac3d1baa87ec4bb2ec3757a6d6daed Mon Sep 17 00:00:00 2001 From: e_forbes Date: Thu, 6 Nov 2025 12:10:23 +0000 Subject: [PATCH 01/12] Introduces the v2 log package to Labkit This commit creates a new v2 package under which the new v2-versions of packages will reside. We've opted for this approach of a v2 directory as opposed to tagging to enable us to support both v1 and v2 without a complex tagging/release setup. The intention is that this will be an interim state which will allow us to migrate all internal services over to the new v2 packages whilst preserving backward compatibility. This commit also demonstrates the level of documentation that I'd like to see new packages and features have. --- v2/log/README.md | 55 +++++++++++++++++++++++++++++ v2/log/log.go | 88 ++++++++++++++++++++++++++++++++++++++++++++++ v2/log/log_test.go | 60 +++++++++++++++++++++++++++++++ 3 files changed, 203 insertions(+) create mode 100644 v2/log/README.md create mode 100644 v2/log/log.go create mode 100644 v2/log/log_test.go diff --git a/v2/log/README.md b/v2/log/README.md new file mode 100644 index 0000000..f7b061e --- /dev/null +++ b/v2/log/README.md @@ -0,0 +1,55 @@ +# 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 +if len(logRecorder.Records) != 1 { + t.Fatalf("expected 1 log record; got %d", len(logRecorder.Records)) +} + +// As well as the shape of individual log lines +if logRecorder.Records[0].Message != "panic recovered" { + t.Fatalf("expected panic recovered message") +} +``` + +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 +} +``` + diff --git a/v2/log/log.go b/v2/log/log.go new file mode 100644 index 0000000..ea1e312 --- /dev/null +++ b/v2/log/log.go @@ -0,0 +1,88 @@ +package log + +import ( + "context" + "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( + slog.NewJSONHandler( + os.Stdout, + nil, + ), + ) +} + +// 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{} + 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 +} + +// 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(_ context.Context, r slog.Record) error { + 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 { + // For testing purposes, we can return the same handler + // In a production implementation, you'd want to preserve group context + return h +} diff --git a/v2/log/log_test.go b/v2/log/log_test.go new file mode 100644 index 0000000..4b5531d --- /dev/null +++ b/v2/log/log_test.go @@ -0,0 +1,60 @@ +package log + +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"), + }) +} -- GitLab From b177950542f455e36068a421fac3a4e1497e0858 Mon Sep 17 00:00:00 2001 From: e_forbes Date: Tue, 25 Nov 2025 13:53:41 +0000 Subject: [PATCH 02/12] Updates ot the README --- v2/log/README.md | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/v2/log/README.md b/v2/log/README.md index f7b061e..4b810af 100644 --- a/v2/log/README.md +++ b/v2/log/README.md @@ -32,14 +32,12 @@ logger, logRecorder := log.NewWithRecorder() // We can then perform assertions on things like how many log lines // have been emitted -if len(logRecorder.Records) != 1 { - t.Fatalf("expected 1 log record; got %d", len(logRecorder.Records)) -} +assert.Len(t, recorder.Records, 1) // As well as the shape of individual log lines -if logRecorder.Records[0].Message != "panic recovered" { - t.Fatalf("expected panic recovered message") -} +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`: -- GitLab From 2c93ba976893ba35401d990211b680c3e1f4d2ed Mon Sep 17 00:00:00 2001 From: e_forbes Date: Tue, 25 Nov 2025 13:56:30 +0000 Subject: [PATCH 03/12] Updates to the comments --- v2/log/log.go | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/v2/log/log.go b/v2/log/log.go index ea1e312..ff71a64 100644 --- a/v2/log/log.go +++ b/v2/log/log.go @@ -52,8 +52,8 @@ func (h *LogRecorder) Enabled(context.Context, slog.Level) bool { } // 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. +// This enables us to assert that logs are correctly emitted +// from user-space code. func (h *LogRecorder) Handle(_ context.Context, r slog.Record) error { attrs := []slog.Attr{} attrs = append(attrs, h.Attrs...) @@ -72,6 +72,7 @@ func (h *LogRecorder) Handle(_ context.Context, r slog.Record) error { // 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...) @@ -80,9 +81,10 @@ func (h *LogRecorder) WithAttrs(attrs []slog.Attr) slog.Handler { // 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 { - // For testing purposes, we can return the same handler - // In a production implementation, you'd want to preserve group context + // currently a noop, but could be extended in the future to + // allow for tests based on WithGroup functionality. return h } -- GitLab From 5e8c785d27a73391ae281e8efc0b8355fc614c66 Mon Sep 17 00:00:00 2001 From: GitLab Renovate Bot Date: Thu, 6 Nov 2025 11:54:32 +0000 Subject: [PATCH 04/12] chore(deps): update pre-commit hook gitlab-com/gl-infra/common-ci-tasks to v3 --- .gitlab-ci.yml | 4 ++-- .pre-commit-config.yaml | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml index fdfecde..e2a0e30 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 10fc2d9..fa0cdaf 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 -- GitLab From 0437709b3fed702d3ce789239b1fc85a13cd16e6 Mon Sep 17 00:00:00 2001 From: e_forbes Date: Tue, 25 Nov 2025 12:05:49 +0000 Subject: [PATCH 05/12] Experimental meta package --- v2/log/README.md | 20 +++++++++++++++++ v2/log/context.go | 38 ++++++++++++++++++++++++++++++++ v2/log/context_test.go | 50 ++++++++++++++++++++++++++++++++++++++++++ v2/meta/context.go | 45 +++++++++++++++++++++++++++++++++++++ 4 files changed, 153 insertions(+) create mode 100644 v2/log/context.go create mode 100644 v2/log/context_test.go create mode 100644 v2/meta/context.go diff --git a/v2/log/README.md b/v2/log/README.md index 4b810af..bf7deb2 100644 --- a/v2/log/README.md +++ b/v2/log/README.md @@ -51,3 +51,23 @@ type testRecord struct { } ``` +## 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 := log.ContextLogger(ctx) + +logger.Info("hello world") +// emitted log line will contain the correlationID +``` diff --git a/v2/log/context.go b/v2/log/context.go new file mode 100644 index 0000000..9498b9b --- /dev/null +++ b/v2/log/context.go @@ -0,0 +1,38 @@ +package log + +import ( + "context" + "log/slog" + + "gitlab.com/gitlab-org/labkit/fields" + "gitlab.com/gitlab-org/labkit/v2/meta" +) + +// ContextLogger returns a new slog.ContextLogger that includes +// correlation_id from the context as a field. +func ContextLogger(ctx context.Context) *slog.Logger { + logger := New() + return createChildLoggerFromContext(ctx, logger) +} + +// ContextLoggerWithRecorder - a Helper function that allows you to do +// some assertions on the contextual logs being emitted. +func ContextLoggerWithRecorder(ctx context.Context) (*slog.Logger, *LogRecorder) { + logger, recorder := NewWithRecorder() + return createChildLoggerFromContext(ctx, logger), recorder +} + +// createChildLoggerFromContext - creates a child logger that is enriched with +// all of the good things pushed into the context that need to be emitted +// for every log line. +func createChildLoggerFromContext(ctx context.Context, logger *slog.Logger) *slog.Logger { + correlationID := meta.CorrelationID(ctx) + logger = logger.With(fields.CorrelationID, correlationID) + + fields := meta.MetaFields(ctx) + for key, val := range fields { + logger.With(slog.Attr{Key: "meta." + key, Value: slog.AnyValue(val)}) + } + + return logger +} diff --git a/v2/log/context_test.go b/v2/log/context_test.go new file mode 100644 index 0000000..fbb803e --- /dev/null +++ b/v2/log/context_test.go @@ -0,0 +1,50 @@ +package log + +import ( + "context" + "log/slog" + "testing" + + "github.com/stretchr/testify/assert" + "gitlab.com/gitlab-org/labkit/fields" + "gitlab.com/gitlab-org/labkit/v2/meta" +) + +func TestLogger(t *testing.T) { + t.Run("logs with correlation id", func(t *testing.T) { + ctx := meta.WithCorrelationID(context.Background(), "1234567890") + logger, recorder := ContextLoggerWithRecorder(ctx) + logger.Info("test message") + + assert.Equal(t, "test message", recorder.Records[0].Message) + assert.Equal(t, slog.LevelInfo, recorder.Records[0].Level) + assert.Contains(t, recorder.Records[0].Attrs, slog.Attr{ + Key: fields.CorrelationID, + Value: slog.AnyValue(meta.CorrelationID(ctx)), + }) + + childLogger := logger.With("hello", "on") + childLogger.Info("testing again") + }) + + t.Run("logs all meta fields from the context", func(t *testing.T) { + ctx := meta.WithCorrelationID(context.Background(), "1234567890") + ctx = meta.WithMetaField(ctx, fields.GitLabUserID, "123456") + + logger, recorder := ContextLoggerWithRecorder(ctx) + logger.Info("test message") + assert.Equal(t, "test message", recorder.Records[0].Message) + assert.Equal(t, slog.LevelInfo, recorder.Records[0].Level) + assert.Contains(t, recorder.Records[0].Attrs, slog.Attr{ + Key: fields.CorrelationID, + Value: slog.AnyValue("1234567890"), + }) + assert.Contains(t, recorder.Records[0].Attrs, slog.Attr{ + Key: "meta." + fields.GitLabUserID, + Value: slog.AnyValue("123456"), + }) + + childLogger := logger.With("hello", "on") + childLogger.Info("testing again") + }) +} diff --git a/v2/meta/context.go b/v2/meta/context.go new file mode 100644 index 0000000..bf49236 --- /dev/null +++ b/v2/meta/context.go @@ -0,0 +1,45 @@ +package meta + +import ( + "context" +) + +// ContextKey is an alias for string type +type FieldKey string + +const ( + MetaFieldsKey FieldKey = "meta" + CorrelationIDKey FieldKey = "correlation_id" +) + +type Fields map[string]any + +func WithMetaField(ctx context.Context, fieldName string, fieldValue any) context.Context { + fields, ok := ctx.Value(MetaFields).(Fields) + if !ok || fields == nil { + fields = make(Fields) + } + + fields[fieldName] = fieldValue + return context.WithValue(ctx, MetaFieldsKey, fields) +} + +func MetaFields(ctx context.Context) Fields { + if fields, ok := ctx.Value(MetaFieldsKey).(Fields); ok { + return fields + } + return make(Fields) +} + +func WithCorrelationID(ctx context.Context, correlationID string) context.Context { + return context.WithValue(ctx, CorrelationIDKey, correlationID) +} + +func CorrelationID(ctx context.Context) string { + if val := ctx.Value(CorrelationIDKey); val != nil { + if idStr, ok := val.(string); ok { + return idStr + } + } + return "" +} -- GitLab From 1ec863aab36c3e5c4f07513ab3e637da8eaf6136 Mon Sep 17 00:00:00 2001 From: e_forbes Date: Tue, 25 Nov 2025 12:19:15 +0000 Subject: [PATCH 06/12] Fixup and adds test --- v2/meta/context.go | 43 ++++++++++++++++++++++++++++++----------- v2/meta/context_test.go | 39 +++++++++++++++++++++++++++++++++++++ 2 files changed, 71 insertions(+), 11 deletions(-) create mode 100644 v2/meta/context_test.go diff --git a/v2/meta/context.go b/v2/meta/context.go index bf49236..700b5b2 100644 --- a/v2/meta/context.go +++ b/v2/meta/context.go @@ -8,33 +8,54 @@ import ( type FieldKey string const ( - MetaFieldsKey FieldKey = "meta" + // 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" ) -type Fields map[string]any +type fields map[string]any +// WithMetaField - allows us to enrich the map of meta.* fields we wish to +// emit in our observability setup. func WithMetaField(ctx context.Context, fieldName string, fieldValue any) context.Context { - fields, ok := ctx.Value(MetaFields).(Fields) - if !ok || fields == nil { - fields = make(Fields) + metaFieldsMap, ok := ctx.Value(MetaFieldsKey).(fields) + if !ok || metaFieldsMap == nil { + metaFieldsMap = make(fields) } - fields[fieldName] = fieldValue - return context.WithValue(ctx, MetaFieldsKey, fields) + metaFieldsMap[fieldName] = fieldValue + return context.WithValue(ctx, MetaFieldsKey, metaFieldsMap) } -func MetaFields(ctx context.Context) Fields { - if fields, ok := ctx.Value(MetaFieldsKey).(Fields); ok { - return 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 make(Fields) + return make(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 { diff --git a/v2/meta/context_test.go b/v2/meta/context_test.go new file mode 100644 index 0000000..4a0a46c --- /dev/null +++ b/v2/meta/context_test.go @@ -0,0 +1,39 @@ +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 = WithMetaField(ctx, "user_id", "123") + ctx = WithMetaField(ctx, "project_id", 456) + + fields := MetaFields(ctx) + t.Logf("%+v", fields) + + assert.Equal(t, len(fields), 2, "Expected 2 meta fields") + + assert.Contains(t, fields, "user_id") + assert.Equal(t, fields["user_id"], "123") + + assert.Contains(t, fields, "project_id") + assert.Equal(t, fields["project_id"], 456) + + // Test that adding a field with the same name overwrites the previous one + ctx = WithMetaField(ctx, "user_id", "789") + fields = MetaFields(ctx) + + assert.Contains(t, fields, "user_id") + assert.Equal(t, fields["user_id"], "789") + + // Test with an empty context + emptyCtx := context.Background() + assert.Empty(t, MetaFields(emptyCtx)) + + }) +} -- GitLab From 84ae5e33221381c89d6023ebd8168723094bfc89 Mon Sep 17 00:00:00 2001 From: e_forbes Date: Tue, 25 Nov 2025 13:17:01 +0000 Subject: [PATCH 07/12] Fixup linting --- v2/log/context.go | 2 +- v2/meta/context.go | 3 +-- v2/meta/context_test.go | 1 - 3 files changed, 2 insertions(+), 4 deletions(-) diff --git a/v2/log/context.go b/v2/log/context.go index 9498b9b..95e105e 100644 --- a/v2/log/context.go +++ b/v2/log/context.go @@ -31,7 +31,7 @@ func createChildLoggerFromContext(ctx context.Context, logger *slog.Logger) *slo fields := meta.MetaFields(ctx) for key, val := range fields { - logger.With(slog.Attr{Key: "meta." + key, Value: slog.AnyValue(val)}) + logger.With("meta."+key, val) } return logger diff --git a/v2/meta/context.go b/v2/meta/context.go index 700b5b2..8964429 100644 --- a/v2/meta/context.go +++ b/v2/meta/context.go @@ -4,7 +4,6 @@ import ( "context" ) -// ContextKey is an alias for string type type FieldKey string const ( @@ -49,7 +48,7 @@ func MetaFields(ctx context.Context) fields { return make(fields) } -// WithCorrelationID - enriches the context with the correlationID +// WithCorrelationID - enriches the context with the correlationID. func WithCorrelationID(ctx context.Context, correlationID string) context.Context { return context.WithValue(ctx, CorrelationIDKey, correlationID) } diff --git a/v2/meta/context_test.go b/v2/meta/context_test.go index 4a0a46c..a545ab9 100644 --- a/v2/meta/context_test.go +++ b/v2/meta/context_test.go @@ -34,6 +34,5 @@ func TestMeta(t *testing.T) { // Test with an empty context emptyCtx := context.Background() assert.Empty(t, MetaFields(emptyCtx)) - }) } -- GitLab From 26519e83abc79f7e5f8c4ebe13142b00bc35e538 Mon Sep 17 00:00:00 2001 From: e_forbes Date: Tue, 25 Nov 2025 17:36:29 +0000 Subject: [PATCH 08/12] Migrates to an opinionated approach at fields in the context --- v2/log/README.md | 10 ++++++++++ v2/log/context.go | 37 +++++++++++++++++++++++++++++++++++-- v2/log/context_test.go | 8 +++++--- v2/log/log_test.go | 16 ++++++++++++++++ v2/meta/context.go | 23 +++++++++++------------ v2/meta/context_test.go | 22 ++++------------------ 6 files changed, 81 insertions(+), 35 deletions(-) diff --git a/v2/log/README.md b/v2/log/README.md index bf7deb2..20e36c6 100644 --- a/v2/log/README.md +++ b/v2/log/README.md @@ -71,3 +71,13 @@ logger := log.ContextLogger(ctx) logger.Info("hello world") // emitted log line will contain the correlationID ``` + +## Canonical Logger + +```go +// pass this logger along the request lifecycle +logger := logger.With(slog.String("field", "value")) + +// +logger.Info("canonical log") +``` diff --git a/v2/log/context.go b/v2/log/context.go index 95e105e..fb08da5 100644 --- a/v2/log/context.go +++ b/v2/log/context.go @@ -3,14 +3,24 @@ package log import ( "context" "log/slog" + "reflect" "gitlab.com/gitlab-org/labkit/fields" "gitlab.com/gitlab-org/labkit/v2/meta" ) +// loggerKey - the key for the +// logger stored in context. +type loggerKey struct{} + // ContextLogger returns a new slog.ContextLogger that includes // correlation_id from the context as a field. func ContextLogger(ctx context.Context) *slog.Logger { + // If we have a logger already stored in Context, we + // should explicitly return this. + if logger, ok := ctx.Value(loggerKey{}).(*slog.Logger); ok { + return logger + } logger := New() return createChildLoggerFromContext(ctx, logger) } @@ -30,9 +40,32 @@ func createChildLoggerFromContext(ctx context.Context, logger *slog.Logger) *slo logger = logger.With(fields.CorrelationID, correlationID) fields := meta.MetaFields(ctx) - for key, val := range fields { - logger.With("meta."+key, val) + val := reflect.ValueOf(fields) + t := reflect.TypeOf(fields) + + for i := 0; i < val.NumField(); i++ { + field := t.Field(i) + value := val.Field(i) + + if tag, ok := field.Tag.Lookup("field"); ok { + logger.With(tag, value.Interface()) + } } return logger } + +// 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 WithField(ctx context.Context, fieldName string, fieldVal any) context.Context { + logger := ContextLogger(ctx) + return context.WithValue(ctx, loggerKey{}, logger.With(fieldName, fieldVal)) +} + +// WithLogger - allows you to explicitly set the logger stored within +// the context and returns a new context. +func WithLogger(ctx context.Context, logger *slog.Logger) context.Context { + return context.WithValue(ctx, loggerKey{}, logger) +} diff --git a/v2/log/context_test.go b/v2/log/context_test.go index fbb803e..bf6b86b 100644 --- a/v2/log/context_test.go +++ b/v2/log/context_test.go @@ -29,7 +29,9 @@ func TestLogger(t *testing.T) { t.Run("logs all meta fields from the context", func(t *testing.T) { ctx := meta.WithCorrelationID(context.Background(), "1234567890") - ctx = meta.WithMetaField(ctx, fields.GitLabUserID, "123456") + ctx = meta.WithMetaFields(ctx, meta.Fields{ + RemoteIP: "1.1.1.1", + }) logger, recorder := ContextLoggerWithRecorder(ctx) logger.Info("test message") @@ -40,8 +42,8 @@ func TestLogger(t *testing.T) { Value: slog.AnyValue("1234567890"), }) assert.Contains(t, recorder.Records[0].Attrs, slog.Attr{ - Key: "meta." + fields.GitLabUserID, - Value: slog.AnyValue("123456"), + Key: "meta.remote_ip", + Value: slog.AnyValue("1.1.1.1"), }) childLogger := logger.With("hello", "on") diff --git a/v2/log/log_test.go b/v2/log/log_test.go index 4b5531d..aaa10e3 100644 --- a/v2/log/log_test.go +++ b/v2/log/log_test.go @@ -1,6 +1,7 @@ package log import ( + "context" "log/slog" "testing" @@ -58,3 +59,18 @@ func TestWithAttrs(t *testing.T) { Value: slog.AnyValue("value"), }) } + +func TestCanonicalLoggingExample(t *testing.T) { + logger, recorder := NewWithRecorder() + + ctx := WithLogger(context.Background(), logger) + ctx = WithField(ctx, "field1", true) + ctx = WithField(ctx, "field2", false) + ctx = WithField(ctx, "field3", 1) + logger = ContextLogger(ctx) + + logger.Info("canonical_log") + + assert.Equal(t, 1, len(recorder.Records)) + assert.Equal(t, 3, len(recorder.Attrs)) +} diff --git a/v2/meta/context.go b/v2/meta/context.go index 8964429..31242c7 100644 --- a/v2/meta/context.go +++ b/v2/meta/context.go @@ -22,18 +22,16 @@ const ( MetaFieldsKey FieldKey = "meta" ) -type fields map[string]any +// Fields - this is a strongly typed representation of all of +// the various meta fields that we wish to support +type Fields struct { + 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 WithMetaField(ctx context.Context, fieldName string, fieldValue any) context.Context { - metaFieldsMap, ok := ctx.Value(MetaFieldsKey).(fields) - if !ok || metaFieldsMap == nil { - metaFieldsMap = make(fields) - } - - metaFieldsMap[fieldName] = fieldValue - return context.WithValue(ctx, MetaFieldsKey, metaFieldsMap) +func WithMetaFields(ctx context.Context, fields Fields) context.Context { + return context.WithValue(ctx, MetaFieldsKey, fields) } // MetaFields - returns all of the meta fields currently @@ -41,11 +39,12 @@ func WithMetaField(ctx context.Context, fieldName string, fieldValue any) contex // 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 { +func MetaFields(ctx context.Context) Fields { + // TODO: reflective mapping of the fields struct to log fields + if metaFieldsMap, ok := ctx.Value(MetaFieldsKey).(Fields); ok { return metaFieldsMap } - return make(fields) + return Fields{} } // WithCorrelationID - enriches the context with the correlationID. diff --git a/v2/meta/context_test.go b/v2/meta/context_test.go index a545ab9..a273824 100644 --- a/v2/meta/context_test.go +++ b/v2/meta/context_test.go @@ -10,26 +10,12 @@ import ( 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 = WithMetaField(ctx, "user_id", "123") - ctx = WithMetaField(ctx, "project_id", 456) - + ctx = WithMetaFields(ctx, Fields{ + RemoteIP: "1.1.1.1", + }) fields := MetaFields(ctx) - t.Logf("%+v", fields) - - assert.Equal(t, len(fields), 2, "Expected 2 meta fields") - - assert.Contains(t, fields, "user_id") - assert.Equal(t, fields["user_id"], "123") - - assert.Contains(t, fields, "project_id") - assert.Equal(t, fields["project_id"], 456) - - // Test that adding a field with the same name overwrites the previous one - ctx = WithMetaField(ctx, "user_id", "789") - fields = MetaFields(ctx) - assert.Contains(t, fields, "user_id") - assert.Equal(t, fields["user_id"], "789") + assert.Equal(t, "1.1.1.1", fields.RemoteIP) // Test with an empty context emptyCtx := context.Background() -- GitLab From 4dafec89250ef631374e0503ad1f8859685dfd57 Mon Sep 17 00:00:00 2001 From: e_forbes Date: Tue, 25 Nov 2025 17:46:08 +0000 Subject: [PATCH 09/12] Improves documentation around canonical logging --- v2/log/README.md | 24 ++++++++++++++++++++---- v2/log/log_test.go | 4 +--- v2/meta/context.go | 2 ++ 3 files changed, 23 insertions(+), 7 deletions(-) diff --git a/v2/log/README.md b/v2/log/README.md index 20e36c6..c974fa0 100644 --- a/v2/log/README.md +++ b/v2/log/README.md @@ -74,10 +74,26 @@ logger.Info("hello world") ## 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 -logger := logger.With(slog.String("field", "value")) - -// -logger.Info("canonical log") +ctx := WithLogger(context.Background(), logger) +ctx = WithField(ctx, "field1", true) +ctx = WithField(ctx, "field2", false) +ctx = WithField(ctx, "field3", 1) + +// at the point at which you need to emit the +// final log line, you can opt for the verbose +// approach +logger = ContextLogger(ctx) +logger.Info("canonical_log") + +// or the inline approach: +log.ContextLogger(ctx).Info("canonical_log") ``` diff --git a/v2/log/log_test.go b/v2/log/log_test.go index aaa10e3..73d8a30 100644 --- a/v2/log/log_test.go +++ b/v2/log/log_test.go @@ -67,9 +67,7 @@ func TestCanonicalLoggingExample(t *testing.T) { ctx = WithField(ctx, "field1", true) ctx = WithField(ctx, "field2", false) ctx = WithField(ctx, "field3", 1) - logger = ContextLogger(ctx) - - logger.Info("canonical_log") + ContextLogger(ctx).Info("canonical_log") assert.Equal(t, 1, len(recorder.Records)) assert.Equal(t, 3, len(recorder.Attrs)) diff --git a/v2/meta/context.go b/v2/meta/context.go index 31242c7..1d8e07b 100644 --- a/v2/meta/context.go +++ b/v2/meta/context.go @@ -25,6 +25,8 @@ const ( // 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"` } -- GitLab From 397ce197ddf00b3ddca28fc91eadd1c1e07abde4 Mon Sep 17 00:00:00 2001 From: e_forbes Date: Tue, 25 Nov 2025 17:46:58 +0000 Subject: [PATCH 10/12] Linting issues --- v2/log/context.go | 2 +- v2/meta/context.go | 3 +-- 2 files changed, 2 insertions(+), 3 deletions(-) diff --git a/v2/log/context.go b/v2/log/context.go index fb08da5..c405847 100644 --- a/v2/log/context.go +++ b/v2/log/context.go @@ -43,7 +43,7 @@ func createChildLoggerFromContext(ctx context.Context, logger *slog.Logger) *slo val := reflect.ValueOf(fields) t := reflect.TypeOf(fields) - for i := 0; i < val.NumField(); i++ { + for i := range val.NumField() { field := t.Field(i) value := val.Field(i) diff --git a/v2/meta/context.go b/v2/meta/context.go index 1d8e07b..bc03810 100644 --- a/v2/meta/context.go +++ b/v2/meta/context.go @@ -23,7 +23,7 @@ const ( ) // Fields - this is a strongly typed representation of all of -// the various meta fields that we wish to support +// 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. @@ -42,7 +42,6 @@ func WithMetaFields(ctx context.Context, fields Fields) context.Context { // between parts of your application. This is explicitly for // capturing observability focused meta fields. func MetaFields(ctx context.Context) Fields { - // TODO: reflective mapping of the fields struct to log fields if metaFieldsMap, ok := ctx.Value(MetaFieldsKey).(Fields); ok { return metaFieldsMap } -- GitLab From ecf1d8a6d30171d2f11574da3a579ead99164c3f Mon Sep 17 00:00:00 2001 From: e_forbes Date: Wed, 26 Nov 2025 10:00:26 +0000 Subject: [PATCH 11/12] Migrates the log testing functionality into a separate logtest package --- v2/log/context.go | 11 +---- v2/log/context_test.go | 7 +-- v2/log/log.go | 70 ---------------------------- v2/log/log_test.go | 69 ++++------------------------ v2/testing/logtest/log.go | 84 ++++++++++++++++++++++++++++++++++ v2/testing/logtest/log_test.go | 60 ++++++++++++++++++++++++ 6 files changed, 159 insertions(+), 142 deletions(-) create mode 100644 v2/testing/logtest/log.go create mode 100644 v2/testing/logtest/log_test.go diff --git a/v2/log/context.go b/v2/log/context.go index c405847..857dc85 100644 --- a/v2/log/context.go +++ b/v2/log/context.go @@ -22,20 +22,13 @@ func ContextLogger(ctx context.Context) *slog.Logger { return logger } logger := New() - return createChildLoggerFromContext(ctx, logger) -} - -// ContextLoggerWithRecorder - a Helper function that allows you to do -// some assertions on the contextual logs being emitted. -func ContextLoggerWithRecorder(ctx context.Context) (*slog.Logger, *LogRecorder) { - logger, recorder := NewWithRecorder() - return createChildLoggerFromContext(ctx, logger), recorder + return CreateChildLoggerFromContext(ctx, logger) } // createChildLoggerFromContext - creates a child logger that is enriched with // all of the good things pushed into the context that need to be emitted // for every log line. -func createChildLoggerFromContext(ctx context.Context, logger *slog.Logger) *slog.Logger { +func CreateChildLoggerFromContext(ctx context.Context, logger *slog.Logger) *slog.Logger { correlationID := meta.CorrelationID(ctx) logger = logger.With(fields.CorrelationID, correlationID) diff --git a/v2/log/context_test.go b/v2/log/context_test.go index bf6b86b..c2f80fd 100644 --- a/v2/log/context_test.go +++ b/v2/log/context_test.go @@ -1,4 +1,4 @@ -package log +package log_test import ( "context" @@ -8,12 +8,13 @@ import ( "github.com/stretchr/testify/assert" "gitlab.com/gitlab-org/labkit/fields" "gitlab.com/gitlab-org/labkit/v2/meta" + "gitlab.com/gitlab-org/labkit/v2/testing/logtest" ) func TestLogger(t *testing.T) { t.Run("logs with correlation id", func(t *testing.T) { ctx := meta.WithCorrelationID(context.Background(), "1234567890") - logger, recorder := ContextLoggerWithRecorder(ctx) + logger, recorder := logtest.ContextLoggerWithRecorder(ctx) logger.Info("test message") assert.Equal(t, "test message", recorder.Records[0].Message) @@ -33,7 +34,7 @@ func TestLogger(t *testing.T) { RemoteIP: "1.1.1.1", }) - logger, recorder := ContextLoggerWithRecorder(ctx) + logger, recorder := logtest.ContextLoggerWithRecorder(ctx) logger.Info("test message") assert.Equal(t, "test message", recorder.Records[0].Message) assert.Equal(t, slog.LevelInfo, recorder.Records[0].Level) diff --git a/v2/log/log.go b/v2/log/log.go index ff71a64..5910912 100644 --- a/v2/log/log.go +++ b/v2/log/log.go @@ -1,7 +1,6 @@ package log import ( - "context" "log/slog" "os" ) @@ -19,72 +18,3 @@ func New() *slog.Logger { ), ) } - -// 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{} - 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 -} - -// 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(_ context.Context, r slog.Record) error { - 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/log/log_test.go b/v2/log/log_test.go index 73d8a30..9a81961 100644 --- a/v2/log/log_test.go +++ b/v2/log/log_test.go @@ -1,73 +1,22 @@ -package log +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 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"), - }) -} - func TestCanonicalLoggingExample(t *testing.T) { - logger, recorder := NewWithRecorder() + logger, recorder := logtest.NewWithRecorder() - ctx := WithLogger(context.Background(), logger) - ctx = WithField(ctx, "field1", true) - ctx = WithField(ctx, "field2", false) - ctx = WithField(ctx, "field3", 1) - ContextLogger(ctx).Info("canonical_log") + ctx := log.WithLogger(context.Background(), logger) + ctx = log.WithField(ctx, "field1", true) + ctx = log.WithField(ctx, "field2", false) + ctx = log.WithField(ctx, "field3", 1) + log.ContextLogger(ctx).Info("canonical_log") assert.Equal(t, 1, len(recorder.Records)) assert.Equal(t, 3, len(recorder.Attrs)) diff --git a/v2/testing/logtest/log.go b/v2/testing/logtest/log.go new file mode 100644 index 0000000..3b5040d --- /dev/null +++ b/v2/testing/logtest/log.go @@ -0,0 +1,84 @@ +package logtest + +import ( + "context" + "log/slog" + + "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{} + 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 +} + +// 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(_ context.Context, r slog.Record) error { + 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 +} + +// ContextLoggerWithRecorder - a Helper function that allows you to do +// some assertions on the contextual logs being emitted. +func ContextLoggerWithRecorder(ctx context.Context) (*slog.Logger, *LogRecorder) { + logger, recorder := NewWithRecorder() + return log.CreateChildLoggerFromContext(ctx, logger), recorder +} diff --git a/v2/testing/logtest/log_test.go b/v2/testing/logtest/log_test.go new file mode 100644 index 0000000..7b31385 --- /dev/null +++ b/v2/testing/logtest/log_test.go @@ -0,0 +1,60 @@ +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"), + }) +} -- GitLab From 91adc758389b10617ece92cd27cf4dd7b5ee8a5c Mon Sep 17 00:00:00 2001 From: e_forbes Date: Thu, 27 Nov 2025 09:42:51 +0000 Subject: [PATCH 12/12] Migrates the context logging approach to a custom handler --- v2/log/README.md | 16 +-- v2/log/context.go | 86 +++++++++------- v2/log/context_test.go | 173 +++++++++++++++++++++++++++------ v2/log/log.go | 8 +- v2/log/log_test.go | 12 +-- v2/testing/logtest/log.go | 17 ++-- v2/testing/logtest/log_test.go | 2 + 7 files changed, 218 insertions(+), 96 deletions(-) diff --git a/v2/log/README.md b/v2/log/README.md index c974fa0..3ebaa0d 100644 --- a/v2/log/README.md +++ b/v2/log/README.md @@ -66,9 +66,7 @@ the context and will contain all the necessary fields needed. ctx := meta.WithCorrelationID(context.Background(), "1234567890") // construct a child logger -logger := log.ContextLogger(ctx) - -logger.Info("hello world") +logger.InfoContext(ctx, "hello world") // emitted log line will contain the correlationID ``` @@ -83,17 +81,11 @@ This can be achieved through the use of the ```go // pass this logger along the request lifecycle -ctx := WithLogger(context.Background(), logger) -ctx = WithField(ctx, "field1", true) -ctx = WithField(ctx, "field2", false) -ctx = WithField(ctx, "field3", 1) +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 = ContextLogger(ctx) -logger.Info("canonical_log") - -// or the inline approach: -log.ContextLogger(ctx).Info("canonical_log") +logger.InfoContext(ctx, "canonical_log") ``` diff --git a/v2/log/context.go b/v2/log/context.go index 857dc85..ce1e12d 100644 --- a/v2/log/context.go +++ b/v2/log/context.go @@ -5,60 +5,78 @@ import ( "log/slog" "reflect" - "gitlab.com/gitlab-org/labkit/fields" "gitlab.com/gitlab-org/labkit/v2/meta" ) -// loggerKey - the key for the -// logger stored in context. -type loggerKey struct{} - -// ContextLogger returns a new slog.ContextLogger that includes -// correlation_id from the context as a field. -func ContextLogger(ctx context.Context) *slog.Logger { - // If we have a logger already stored in Context, we - // should explicitly return this. - if logger, ok := ctx.Value(loggerKey{}).(*slog.Logger); ok { - return logger +// 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, } - logger := New() - return CreateChildLoggerFromContext(ctx, logger) } -// createChildLoggerFromContext - creates a child logger that is enriched with -// all of the good things pushed into the context that need to be emitted -// for every log line. -func CreateChildLoggerFromContext(ctx context.Context, logger *slog.Logger) *slog.Logger { +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) - logger = logger.With(fields.CorrelationID, correlationID) + 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 { - logger.With(tag, value.Interface()) + r.Add(slog.Any(tag, value.Interface())) } } - - return logger + return r } -// 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 WithField(ctx context.Context, fieldName string, fieldVal any) context.Context { - logger := ContextLogger(ctx) - return context.WithValue(ctx, loggerKey{}, logger.With(fieldName, fieldVal)) +func (c *ContextHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + return c.BaseHandler.WithAttrs(attrs) } -// WithLogger - allows you to explicitly set the logger stored within -// the context and returns a new context. -func WithLogger(ctx context.Context, logger *slog.Logger) context.Context { - return context.WithValue(ctx, loggerKey{}, logger) +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 index c2f80fd..e30cd22 100644 --- a/v2/log/context_test.go +++ b/v2/log/context_test.go @@ -7,47 +7,156 @@ import ( "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("logs with correlation id", func(t *testing.T) { - ctx := meta.WithCorrelationID(context.Background(), "1234567890") - logger, recorder := logtest.ContextLoggerWithRecorder(ctx) - logger.Info("test message") - - assert.Equal(t, "test message", recorder.Records[0].Message) - assert.Equal(t, slog.LevelInfo, recorder.Records[0].Level) - assert.Contains(t, recorder.Records[0].Attrs, slog.Attr{ - Key: fields.CorrelationID, - Value: slog.AnyValue(meta.CorrelationID(ctx)), - }) + 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") + }) +} - childLogger := logger.With("hello", "on") - childLogger.Info("testing again") +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("logs all meta fields from the context", func(t *testing.T) { - ctx := meta.WithCorrelationID(context.Background(), "1234567890") - ctx = meta.WithMetaFields(ctx, meta.Fields{ - RemoteIP: "1.1.1.1", - }) + 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")) - logger, recorder := logtest.ContextLoggerWithRecorder(ctx) - logger.Info("test message") - assert.Equal(t, "test message", recorder.Records[0].Message) - assert.Equal(t, slog.LevelInfo, recorder.Records[0].Level) - assert.Contains(t, recorder.Records[0].Attrs, slog.Attr{ - Key: fields.CorrelationID, - Value: slog.AnyValue("1234567890"), - }) - assert.Contains(t, recorder.Records[0].Attrs, slog.Attr{ - Key: "meta.remote_ip", - Value: slog.AnyValue("1.1.1.1"), - }) + 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")) - childLogger := logger.With("hello", "on") - childLogger.Info("testing again") + 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 index 5910912..00aa96d 100644 --- a/v2/log/log.go +++ b/v2/log/log.go @@ -12,9 +12,11 @@ import ( // setup. func New() *slog.Logger { return slog.New( - slog.NewJSONHandler( - os.Stdout, - nil, + NewContextHandler( + slog.NewJSONHandler( + os.Stdout, + nil, + ), ), ) } diff --git a/v2/log/log_test.go b/v2/log/log_test.go index 9a81961..cc14305 100644 --- a/v2/log/log_test.go +++ b/v2/log/log_test.go @@ -2,6 +2,7 @@ package log_test import ( "context" + "log/slog" "testing" "github.com/stretchr/testify/assert" @@ -12,12 +13,11 @@ import ( func TestCanonicalLoggingExample(t *testing.T) { logger, recorder := logtest.NewWithRecorder() - ctx := log.WithLogger(context.Background(), logger) - ctx = log.WithField(ctx, "field1", true) - ctx = log.WithField(ctx, "field2", false) - ctx = log.WithField(ctx, "field3", 1) - log.ContextLogger(ctx).Info("canonical_log") + 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)) - assert.Equal(t, 3, len(recorder.Attrs)) + record := recorder.Records[0] + assert.Equal(t, 4, len(record.Attrs)) } diff --git a/v2/testing/logtest/log.go b/v2/testing/logtest/log.go index 3b5040d..3b8cb5f 100644 --- a/v2/testing/logtest/log.go +++ b/v2/testing/logtest/log.go @@ -3,6 +3,7 @@ package logtest import ( "context" "log/slog" + "os" "gitlab.com/gitlab-org/labkit/v2/log" ) @@ -13,7 +14,9 @@ import ( // a standard slogger, and then perform assertions that // their code is instrumented properly. func NewWithRecorder() (*slog.Logger, *LogRecorder) { - recorder := &LogRecorder{} + recorder := &LogRecorder{ + baseRecorder: log.NewContextHandler(slog.NewJSONHandler(os.Stdout, nil)), + } return slog.New(recorder), recorder } @@ -23,6 +26,8 @@ func NewWithRecorder() (*slog.Logger, *LogRecorder) { type LogRecorder struct { Attrs []slog.Attr Records []testRecord + + baseRecorder slog.Handler } // testRecord - a representation of a single log message. @@ -41,7 +46,8 @@ func (h *LogRecorder) Enabled(context.Context, slog.Level) bool { // 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(_ context.Context, r slog.Record) error { +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 { @@ -75,10 +81,3 @@ func (h *LogRecorder) WithGroup(name string) slog.Handler { // allow for tests based on WithGroup functionality. return h } - -// ContextLoggerWithRecorder - a Helper function that allows you to do -// some assertions on the contextual logs being emitted. -func ContextLoggerWithRecorder(ctx context.Context) (*slog.Logger, *LogRecorder) { - logger, recorder := NewWithRecorder() - return log.CreateChildLoggerFromContext(ctx, logger), recorder -} diff --git a/v2/testing/logtest/log_test.go b/v2/testing/logtest/log_test.go index 7b31385..7e0fe2e 100644 --- a/v2/testing/logtest/log_test.go +++ b/v2/testing/logtest/log_test.go @@ -57,4 +57,6 @@ func TestWithAttrs(t *testing.T) { Key: "key", Value: slog.AnyValue("value"), }) + + t.Logf("%+v\n", record) } -- GitLab