feat: standardises the v2 log setup to emit UTC-based timezones (d45b7071) · Commits · GitLab.org / labkit

v2/log/context_test.go

+3 −3

Original line number	Diff line number	Diff line
		@@ -92,7 +92,7 @@ func TestContextHandler(t *testing.T) {
		slog.String("request_id", "req-456"),
		)

		logger, recorder := logtest.NewWithRecorder()
		logger, recorder := logtest.NewWithRecorder(nil)
		logger.InfoContext(ctx, "processing request")

		records := recorder.Records()
		@@ -105,7 +105,7 @@ func TestContextHandler(t *testing.T) {
		t.Run("handles empty context", func(t *testing.T) {
		ctx := context.Background()

		logger, recorder := logtest.NewWithRecorder()
		logger, recorder := logtest.NewWithRecorder(nil)
		logger.InfoContext(ctx, "simple log message")

		assert.Len(t, recorder.Records(), 1)
		@@ -118,7 +118,7 @@ func TestContextHandler(t *testing.T) {
		ctx = log.WithFields(ctx, slog.String("step", "2"))
		ctx = log.WithFields(ctx, slog.String("step", "3"))

		logger, recorder := logtest.NewWithRecorder()
		logger, recorder := logtest.NewWithRecorder(nil)
		logger.InfoContext(ctx, "multi-step process")

		record := recorder.Records()[0]

v2/log/log.go

+54 −43

Original line number	Diff line number	Diff line
		@@ -4,46 +4,18 @@ 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
		}

		// Option is a function that modifies the logger configuration.
		type Option func(*Config)

		// WithWriter sets the output writer for the logger.
		func WithWriter(w io.Writer) Option {
		return func(c *Config) {
		c.Writer = w
		}
		}

		// 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) {
		c.UseTextFormat = true
		}
		}

		// WithBaseHandler allows providing a custom base handler
		// This bypasses the default JSON/Text handler creation.
		func WithBaseHandler(handler slog.Handler) Option {
		return func(c *Config) {
		c.BaseHandler = handler
		}
		Clock TimeFunc
		}

		// New - a handy wrapper that configures the slog.Logger in a consistent
		@@ -51,26 +23,65 @@ func WithBaseHandler(handler slog.Handler) Option {
		// 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(opts ...Option) *slog.Logger {
		func New() *slog.Logger {
		return NewWithConfig(nil)
		}

		// NewWithConfig - a constructor that allows you to
		// overwrite some of the core constructs within the
		// Logger for your own nefarious purposes.
		func NewWithConfig(cfg Config) slog.Logger {
		config := &Config{
		Writer: os.Stdout,
		HandlerOpts: nil,
		Writer: os.Stderr,
		UseTextFormat: false,
		// Clock intentially nil by default - uses record's original timestamp
		}
		if cfg != nil {
		if cfg.Writer != nil {
		config.Writer = cfg.Writer
		}
		if cfg.UseTextFormat {
		config.UseTextFormat = cfg.UseTextFormat
		}

		for _, opt := range opts {
		opt(config)
		if cfg.Clock != nil {
		config.Clock = cfg.Clock
		}
		}

		var baseHandler slog.Handler
		switch {
		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 && len(groups) == 0 {
		if a.Value.Kind() == slog.KindTime {
		t := a.Value.Time()
		if clockFunc != nil {
		t = clockFunc()
		}
		a.Value = slog.AnyValue(t.UTC().Format(time.RFC3339))
		}
		}
		return a
		}
		return opts
		}

v2/log/log_test.go

+114 −20

Original line number	Diff line number	Diff line
		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"
		"github.com/stretchr/testify/require"
		)

		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()))
		records := recorder.Records()
		assert.Equal(t, 2, len(records[0].Attrs))
		type logRecord struct {
		Msg string `json:"msg"`
		Level string `json:"level"`
		Time time.Time `json:"time"`
		Hello string `json:"hello"`
		Howdy string `json:"howdy"`
		}

		func TestFileWriting(t *testing.T) {
		f, err := os.Create("test.out")
		testFile := "test.out"
		ensureFileDoesNotExist(t, testFile)
		t.Cleanup(func() { os.Remove(testFile) })
		f, err := os.Create(testFile)
		assert.Nil(t, err)
		logger := log.New(log.WithWriter(f))
		defer f.Close()

		clockFunc := func() time.Time { return time.Date(2023, 1, 1, 0, 0, 0, 0, time.UTC) }
		logger := NewWithConfig(&Config{
		Writer: f,
		Clock: clockFunc,
		})

		t.Run("test file writing works", func(t *testing.T) {
		logger.Info("hello")
		require.NoError(t, f.Sync())

		records := readLogFile(t, testFile)
		require.Equal(t, logRecord{
		Msg: "hello",
		Level: "INFO",
		Time: clockFunc(),
		}, records[0])
		})

		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")
		require.NoError(t, f.Sync())

		records := readLogFile(t, testFile)
		require.Equal(t, logRecord{
		Msg: "canonical_log",
		Level: "INFO",
		Time: clockFunc(),
		Hello: "world",
		Howdy: "world",
		}, records[1])
		})
		}

		func TestDefaultClockUsesRecordTimestamp(t *testing.T) {
		testFile := "test_no_clock.out"
		ensureFileDoesNotExist(t, testFile)
		t.Cleanup(func() { os.Remove(testFile) })

		f, err := os.Create(testFile)
		require.NoError(t, err)
		defer f.Close()

		// No Clock provided - should use record's original timestamp
		logger := NewWithConfig(&Config{
		Writer: f,
		})

		before := time.Now().UTC()
		logger.Info("test message")
		require.NoError(t, f.Sync())
		after := time.Now().UTC()

		f.Close()
		contents, err := os.ReadFile("test.out")
		records := readLogFile(t, testFile)
		require.Len(t, records, 1)

		// Timestamp should be between before and after (no drift)
		require.False(t, records[0].Time.Before(before.Truncate(time.Second)),
		"timestamp %v should not be before %v", records[0].Time, before)
		require.False(t, records[0].Time.After(after.Add(time.Second)),
		"timestamp %v should not be after %v", records[0].Time, after)

		// Should be in UTC
		require.Equal(t, time.UTC, records[0].Time.Location())
		}

		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 := NewWithConfig(&Config{
		Writer: io.Discard,
		})
		logger.Info("oh no")
		}

v2/testing/logtest/log.go

+4 −3

Original line number	Diff line number	Diff line
		@@ -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(cfg log.Config) (slog.Logger, *LogRecorder) {
		logger := log.NewWithConfig(cfg)

		recorder := &LogRecorder{
		baseRecorder: log.NewContextHandler(slog.NewJSONHandler(os.Stdout, nil)),
		baseRecorder: logger.Handler(),
		mu: &sync.RWMutex{},
		attrs: []slog.Attr{},
		records: []testRecord{},

v2/testing/logtest/log_test.go

+2 −2

Original line number	Diff line number	Diff line
		@@ -37,7 +37,7 @@ func TestRecorder(t *testing.T) {

		for _, tt := range tests {
		t.Run(tt.name, func(t *testing.T) {
		logger, recorder := NewWithRecorder()
		logger, recorder := NewWithRecorder(nil)
		tt.logFunc(logger, "test message", "key", "value")
		records := recorder.Records()
		assert.Len(t, records, 1)
		@@ -49,7 +49,7 @@ func TestRecorder(t *testing.T) {
		}

		func TestWithAttrs(t *testing.T) {
		logger, recorder := NewWithRecorder()
		logger, recorder := NewWithRecorder(nil)
		logger = logger.With("key", "value")
		logger.Info("test message")
		attrs := recorder.Attrs()