From e15b7f3221f0554896a6ba861954ce61ad79d561 Mon Sep 17 00:00:00 2001 From: Justin Hwang Date: Wed, 4 Oct 2023 09:28:43 -0400 Subject: [PATCH 1/3] zapcore: Ignore nil Entry.Time in encoders Per the comment on `Encoder.EncodeEntry`, any fields that are empty including fields on the `Entry` type should be omitted. Omit the `Time` field when we have empty time. This also aligns with slog.Handler contract. Refs #1334 Discovered by #1335 --- exp/zapslog/handler_test.go | 43 ++++++++++++++++++++++++++++++++++++ zapcore/console_encoder.go | 2 +- zapcore/json_encoder.go | 2 +- zapcore/json_encoder_test.go | 14 ++++++++++++ 4 files changed, 59 insertions(+), 2 deletions(-) diff --git a/exp/zapslog/handler_test.go b/exp/zapslog/handler_test.go index 68339df62..6fcd73cfe 100644 --- a/exp/zapslog/handler_test.go +++ b/exp/zapslog/handler_test.go @@ -23,13 +23,17 @@ package zapslog import ( + "bytes" + "encoding/json" "log/slog" "testing" + "testing/slogtest" "time" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest" "go.uber.org/zap/zaptest/observer" ) @@ -189,3 +193,42 @@ func TestAttrKinds(t *testing.T) { }, entry.ContextMap()) } + +func TestSlogtest(t *testing.T) { + t.Skip() // TODO: skip for now until test failures are fixed (#1334) + var buff bytes.Buffer + core := zapcore.NewCore( + zapcore.NewJSONEncoder(zapcore.EncoderConfig{ + TimeKey: slog.TimeKey, + MessageKey: slog.MessageKey, + LevelKey: slog.LevelKey, + EncodeLevel: zapcore.CapitalLevelEncoder, + EncodeTime: zapcore.RFC3339TimeEncoder, + }), + zapcore.AddSync(&buff), + zapcore.DebugLevel, + ) + + // zaptest doesn't expose the underlying core, + // so we'll extract it from the logger. + testCore := zaptest.NewLogger(t).Core() + + handler := NewHandler(zapcore.NewTee(core, testCore)) + err := slogtest.TestHandler( + handler, + func() []map[string]any { + // Parse the newline-delimited JSON in buff. + var entries []map[string]any + + dec := json.NewDecoder(bytes.NewReader(buff.Bytes())) + for dec.More() { + var ent map[string]any + require.NoError(t, dec.Decode(&ent), "Error decoding log message") + entries = append(entries, ent) + } + + return entries + }, + ) + require.NoError(t, err, "Unexpected error from slogtest.TestHandler") +} diff --git a/zapcore/console_encoder.go b/zapcore/console_encoder.go index 8ca0bfaf5..cc2b4e07b 100644 --- a/zapcore/console_encoder.go +++ b/zapcore/console_encoder.go @@ -77,7 +77,7 @@ func (c consoleEncoder) EncodeEntry(ent Entry, fields []Field) (*buffer.Buffer, // If this ever becomes a performance bottleneck, we can implement // ArrayEncoder for our plain-text format. arr := getSliceEncoder() - if c.TimeKey != "" && c.EncodeTime != nil { + if c.TimeKey != "" && c.EncodeTime != nil && !ent.Time.IsZero() { c.EncodeTime(ent.Time, arr) } if c.LevelKey != "" && c.EncodeLevel != nil { diff --git a/zapcore/json_encoder.go b/zapcore/json_encoder.go index c8ab86979..9685169b2 100644 --- a/zapcore/json_encoder.go +++ b/zapcore/json_encoder.go @@ -372,7 +372,7 @@ func (enc *jsonEncoder) EncodeEntry(ent Entry, fields []Field) (*buffer.Buffer, final.AppendString(ent.Level.String()) } } - if final.TimeKey != "" { + if final.TimeKey != "" && !ent.Time.IsZero() { final.AddTime(final.TimeKey, ent.Time) } if ent.LoggerName != "" && final.NameKey != "" { diff --git a/zapcore/json_encoder_test.go b/zapcore/json_encoder_test.go index 4c651cf77..b2150256e 100644 --- a/zapcore/json_encoder_test.go +++ b/zapcore/json_encoder_test.go @@ -109,6 +109,20 @@ func TestJSONEncodeEntry(t *testing.T) { }), }, }, + { + desc: "zero_time_omitted", + expected: `{ + "L": "info", + "N": "name", + "M": "message" + }`, + ent: zapcore.Entry{ + Level: zapcore.InfoLevel, + Time: time.Time{}, + LoggerName: "name", + Message: "message", + }, + }, } enc := zapcore.NewJSONEncoder(zapcore.EncoderConfig{ From 8af313a8c80e9ad9de71b4e57607442e9c8e0aa3 Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Thu, 5 Oct 2023 10:58:12 -0700 Subject: [PATCH 2/3] zapslog: Delete skipped test This work is being tracked in #1334. --- exp/zapslog/handler_test.go | 43 ------------------------------------- 1 file changed, 43 deletions(-) diff --git a/exp/zapslog/handler_test.go b/exp/zapslog/handler_test.go index 6fcd73cfe..68339df62 100644 --- a/exp/zapslog/handler_test.go +++ b/exp/zapslog/handler_test.go @@ -23,17 +23,13 @@ package zapslog import ( - "bytes" - "encoding/json" "log/slog" "testing" - "testing/slogtest" "time" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "go.uber.org/zap/zapcore" - "go.uber.org/zap/zaptest" "go.uber.org/zap/zaptest/observer" ) @@ -193,42 +189,3 @@ func TestAttrKinds(t *testing.T) { }, entry.ContextMap()) } - -func TestSlogtest(t *testing.T) { - t.Skip() // TODO: skip for now until test failures are fixed (#1334) - var buff bytes.Buffer - core := zapcore.NewCore( - zapcore.NewJSONEncoder(zapcore.EncoderConfig{ - TimeKey: slog.TimeKey, - MessageKey: slog.MessageKey, - LevelKey: slog.LevelKey, - EncodeLevel: zapcore.CapitalLevelEncoder, - EncodeTime: zapcore.RFC3339TimeEncoder, - }), - zapcore.AddSync(&buff), - zapcore.DebugLevel, - ) - - // zaptest doesn't expose the underlying core, - // so we'll extract it from the logger. - testCore := zaptest.NewLogger(t).Core() - - handler := NewHandler(zapcore.NewTee(core, testCore)) - err := slogtest.TestHandler( - handler, - func() []map[string]any { - // Parse the newline-delimited JSON in buff. - var entries []map[string]any - - dec := json.NewDecoder(bytes.NewReader(buff.Bytes())) - for dec.More() { - var ent map[string]any - require.NoError(t, dec.Decode(&ent), "Error decoding log message") - entries = append(entries, ent) - } - - return entries - }, - ) - require.NoError(t, err, "Unexpected error from slogtest.TestHandler") -} From f9de9df3aecf48256f955c421cde30403c3b991a Mon Sep 17 00:00:00 2001 From: Abhinav Gupta Date: Thu, 5 Oct 2023 11:03:49 -0700 Subject: [PATCH 3/3] test: Verify console encoder behavior Verifies that the console encoder also skips the time if it's a zero value. --- zapcore/console_encoder_test.go | 45 +++++++++++++++++++++++++++++++++ 1 file changed, 45 insertions(+) diff --git a/zapcore/console_encoder_test.go b/zapcore/console_encoder_test.go index 439b4b885..8b42b6bc0 100644 --- a/zapcore/console_encoder_test.go +++ b/zapcore/console_encoder_test.go @@ -21,6 +21,7 @@ package zapcore_test import ( "testing" + "time" "github.com/stretchr/testify/assert" . "go.uber.org/zap/zapcore" @@ -35,6 +36,50 @@ var testEntry = Entry{ Caller: EntryCaller{Defined: true, File: "foo.go", Line: 42, Function: "foo.Foo"}, } +func TestConsoleEncodeEntry(t *testing.T) { + tests := []struct { + desc string + expected string + ent Entry + fields []Field + }{ + { + desc: "info no fields", + expected: "2018-06-19T16:33:42Z\tinfo\tbob\tlob law\n", + ent: Entry{ + Level: InfoLevel, + Time: time.Date(2018, 6, 19, 16, 33, 42, 99, time.UTC), + LoggerName: "bob", + Message: "lob law", + }, + }, + { + desc: "zero_time_omitted", + expected: "info\tname\tmessage\n", + ent: Entry{ + Level: InfoLevel, + Time: time.Time{}, + LoggerName: "name", + Message: "message", + }, + }, + } + + cfg := testEncoderConfig() + cfg.EncodeTime = RFC3339TimeEncoder + enc := NewConsoleEncoder(cfg) + + for _, tt := range tests { + t.Run(tt.desc, func(t *testing.T) { + buf, err := enc.EncodeEntry(tt.ent, tt.fields) + if assert.NoError(t, err, "Unexpected console encoding error.") { + assert.Equal(t, tt.expected, buf.String(), "Incorrect encoded entry.") + } + buf.Free() + }) + } +} + func TestConsoleSeparator(t *testing.T) { tests := []struct { desc string