From b5d42ce8d0d02db540ed4dc5ae48c7392e2bb3fc Mon Sep 17 00:00:00 2001 From: e_forbes Date: Wed, 10 Dec 2025 11:52:26 +0000 Subject: [PATCH 1/2] feat: enables timezone specification in the v2 log package When attempting to roll this out to gitlab-shell, we noticed that there was a discrepancy with the timestamp. Firstly, it was in nanosecond format and secondly, it wasn't set by default to UTC. This commit unlocks the ability to control the timezone through the use of an Option function and also ensures that the timestamps follow RFC3339 format which is the default in production today. Users of this lib do have the ability to override how this value is specified should they need additional control. Co-authored-by: Sami Hiltunen --- v2/log/log.go | 39 ++++++++++---- v2/log/log_test.go | 95 +++++++++++++++++++++++++++------- v2/testing/logtest/log.go | 7 +-- v2/testing/logtest/log_test.go | 18 +++++++ 4 files changed, 126 insertions(+), 33 deletions(-) diff --git a/v2/log/log.go b/v2/log/log.go index 39dc6db..7a51623 100644 --- a/v2/log/log.go +++ b/v2/log/log.go @@ -4,14 +4,19 @@ import ( "io" "log/slog" "os" + "time" ) +// timeFunc - exclusively used for testing purposes +// please do not use in production. +type timeFunc func() time.Time + // Config holds the configuration for creating a new logger. type Config struct { Writer io.Writer - HandlerOpts *slog.HandlerOptions UseTextFormat bool BaseHandler slog.Handler + Clock timeFunc } // Option is a function that modifies the logger configuration. @@ -24,13 +29,6 @@ func WithWriter(w io.Writer) Option { } } -// WithHandlerOptions sets the handler options for the logger. -func WithHandlerOptions(opts *slog.HandlerOptions) Option { - return func(c *Config) { - c.HandlerOpts = opts - } -} - // WithTextFormat configures the logger to use text format instead of JSON. func WithTextFormat() Option { return func(c *Config) { @@ -54,8 +52,8 @@ func WithBaseHandler(handler slog.Handler) Option { func New(opts ...Option) *slog.Logger { config := &Config{ Writer: os.Stdout, - HandlerOpts: nil, UseTextFormat: false, + Clock: func() time.Time { return time.Now().UTC() }, } for _, opt := range opts { @@ -67,10 +65,29 @@ func New(opts ...Option) *slog.Logger { case config.BaseHandler != nil: baseHandler = config.BaseHandler case config.UseTextFormat: - baseHandler = slog.NewTextHandler(config.Writer, config.HandlerOpts) + baseHandler = slog.NewTextHandler( + config.Writer, + defaultHandlerOpts( + config.Clock, + )) default: - baseHandler = slog.NewJSONHandler(config.Writer, config.HandlerOpts) + baseHandler = slog.NewJSONHandler( + config.Writer, + defaultHandlerOpts( + config.Clock, + )) } return slog.New(NewContextHandler(baseHandler)) } + +func defaultHandlerOpts(clockFunc timeFunc) *slog.HandlerOptions { + opts := &slog.HandlerOptions{} + opts.ReplaceAttr = func(groups []string, a slog.Attr) slog.Attr { + if a.Key == slog.TimeKey { + a.Value = slog.AnyValue(clockFunc().Format(time.RFC3339)) + } + return a + } + return opts +} diff --git a/v2/log/log_test.go b/v2/log/log_test.go index afe2dfc..db11cbd 100644 --- a/v2/log/log_test.go +++ b/v2/log/log_test.go @@ -1,42 +1,99 @@ -package log_test +package log import ( + "bufio" "context" + "encoding/json" "io" "log/slog" "os" "testing" + "time" "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") +type logRecord struct { + Msg string `json:"msg"` + Level string `json:"level"` + Time time.Time `json:"time"` + Hello string `json:"hello"` + Howdy string `json:"howdy"` +} - assert.Equal(t, 1, len(recorder.Records())) - records := recorder.Records() - assert.Equal(t, 2, len(records[0].Attrs)) +// withClock - enables us to have determinism +// within our tests. +func withClock(timeFunc timeFunc) Option { + return func(c *Config) { + c.Clock = timeFunc + } } func TestFileWriting(t *testing.T) { - f, err := os.Create("test.out") + testFile := "test.out" + ensureFileDoesNotExist(t, testFile) + f, err := os.Create(testFile) assert.Nil(t, err) - logger := log.New(log.WithWriter(f)) - logger.Info("hello") + defer f.Close() + + clockFunc := func() time.Time { return time.Date(2023, 1, 1, 0, 0, 0, 0, time.UTC) } + logger := New(WithWriter(f), withClock(clockFunc)) + + t.Run("test file writing works", func(t *testing.T) { + logger.Info("hello") - f.Close() - contents, err := os.ReadFile("test.out") + records := readLogFile(t, testFile) + assert.Equal(t, "INFO", records[0].Level) + assert.Equal(t, "hello", records[0].Msg) + assert.Equal(t, clockFunc(), records[0].Time) + }) + + t.Run("test canonical logging", func(t *testing.T) { + ctx := WithFields(context.Background(), slog.String("hello", "world")) + ctx = WithFields(ctx, slog.String("howdy", "world")) + logger.InfoContext(ctx, "canonical_log") + + records := readLogFile(t, testFile) + assert.Equal(t, "INFO", records[1].Level) + assert.Equal(t, "canonical_log", records[1].Msg) + assert.Equal(t, clockFunc(), records[1].Time) + assert.Equal(t, "world", records[1].Hello) + assert.Equal(t, "world", records[1].Howdy) + }) +} + +func ensureFileDoesNotExist(t *testing.T, path string) { + t.Helper() + if err := os.Remove(path); err != nil && !os.IsNotExist(err) { + t.Fatalf("failed to remove file %s: %v", path, err) + } +} + +func readLogFile(t *testing.T, filename string) []logRecord { + t.Helper() + + f, err := os.Open(filename) assert.Nil(t, err) - assert.Contains(t, string(contents), `"msg":"hello"`) + defer f.Close() + scanner := bufio.NewScanner(f) + + var records []logRecord + for scanner.Scan() { + var record logRecord + if err := json.Unmarshal(scanner.Bytes(), &record); err != nil { + t.Fail() + continue + } + records = append(records, record) + } + + if err := scanner.Err(); err != nil { + t.Fail() + } + return records } func TestNoopLogging(t *testing.T) { - logger := log.New(log.WithWriter(io.Discard)) + logger := New(WithWriter(io.Discard)) logger.Info("oh no") } diff --git a/v2/testing/logtest/log.go b/v2/testing/logtest/log.go index ce7f80b..ecae58c 100644 --- a/v2/testing/logtest/log.go +++ b/v2/testing/logtest/log.go @@ -3,7 +3,6 @@ package logtest import ( "context" "log/slog" - "os" "sync" "gitlab.com/gitlab-org/labkit/v2/log" @@ -14,9 +13,11 @@ import ( // 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) { +func NewWithRecorder(opts ...log.Option) (*slog.Logger, *LogRecorder) { + logger := log.New(opts...) + recorder := &LogRecorder{ - baseRecorder: log.NewContextHandler(slog.NewJSONHandler(os.Stdout, nil)), + baseRecorder: logger.Handler(), mu: &sync.RWMutex{}, attrs: []slog.Attr{}, records: []testRecord{}, diff --git a/v2/testing/logtest/log_test.go b/v2/testing/logtest/log_test.go index 20ee92b..5831d21 100644 --- a/v2/testing/logtest/log_test.go +++ b/v2/testing/logtest/log_test.go @@ -3,8 +3,10 @@ package logtest import ( "log/slog" "testing" + "time" "github.com/stretchr/testify/assert" + "gitlab.com/gitlab-org/labkit/v2/log" ) func TestRecorder(t *testing.T) { @@ -61,3 +63,19 @@ func TestWithAttrs(t *testing.T) { Value: slog.AnyValue("value"), }) } + +// withClock - enables us to have determinism +// within our tests. +func withClock(timeFunc func() time.Time) log.Option { + return func(c *log.Config) { + c.Clock = timeFunc + } +} + +// This doesn't have any assertions, but rather validates that we +// can overwrite the Clock on the log exposed by the `log` package +// in such a way that we can provide determinism in our tests. +func TestOptionFunction(t *testing.T) { + log := log.New(withClock(func() time.Time { return time.Date(2023, 1, 1, 0, 0, 0, 0, time.UTC) })) + log.Info("hello") +} -- GitLab From 07da0cd1327f86588a3173b4cdc09f538142f6b1 Mon Sep 17 00:00:00 2001 From: e_forbes Date: Thu, 11 Dec 2025 15:44:43 +0000 Subject: [PATCH 2/2] Fixing log assertions --- v2/log/log_test.go | 21 +++++++++++++-------- 1 file changed, 13 insertions(+), 8 deletions(-) diff --git a/v2/log/log_test.go b/v2/log/log_test.go index db11cbd..0338d83 100644 --- a/v2/log/log_test.go +++ b/v2/log/log_test.go @@ -11,6 +11,7 @@ import ( "time" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) type logRecord struct { @@ -43,9 +44,11 @@ func TestFileWriting(t *testing.T) { logger.Info("hello") records := readLogFile(t, testFile) - assert.Equal(t, "INFO", records[0].Level) - assert.Equal(t, "hello", records[0].Msg) - assert.Equal(t, clockFunc(), records[0].Time) + require.Equal(t, logRecord{ + Msg: "hello", + Level: "INFO", + Time: clockFunc(), + }, records[0]) }) t.Run("test canonical logging", func(t *testing.T) { @@ -54,11 +57,13 @@ func TestFileWriting(t *testing.T) { logger.InfoContext(ctx, "canonical_log") records := readLogFile(t, testFile) - assert.Equal(t, "INFO", records[1].Level) - assert.Equal(t, "canonical_log", records[1].Msg) - assert.Equal(t, clockFunc(), records[1].Time) - assert.Equal(t, "world", records[1].Hello) - assert.Equal(t, "world", records[1].Howdy) + require.Equal(t, logRecord{ + Msg: "canonical_log", + Level: "INFO", + Time: clockFunc(), + Hello: "world", + Howdy: "world", + }, records[1]) }) } -- GitLab