diff --git a/v2/log/log.go b/v2/log/log.go index 39dc6db08a3e43e140ccedac7a10daa03a1caff4..7a51623bea9c333e28305a34149f4fe8009b567f 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 afe2dfc1395a8b76bca1b1183bb5b9514f98fc90..0338d83ccfc87ed5126673618be79e43a21490b8 100644 --- a/v2/log/log_test.go +++ b/v2/log/log_test.go @@ -1,42 +1,104 @@ -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") +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) + 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") + + records := readLogFile(t, testFile) + require.Equal(t, logRecord{ + Msg: "canonical_log", + Level: "INFO", + Time: clockFunc(), + Hello: "world", + Howdy: "world", + }, records[1]) + }) +} + +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 ce7f80b146c51d8a23667cf0d8ddcf1d6da02c27..ecae58cc48b9d28d2f011e1eb9c36ac4fad6f023 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 20ee92b00274ca9aff5f522e373329592e975be4..5831d2170b2a9c007ce717801019f1c65eb8e878 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") +}