diff --git a/lib/utils/log/slog_handler.go b/lib/utils/log/slog_handler.go index 7f0ef9d41219f..614c48677c7a2 100644 --- a/lib/utils/log/slog_handler.go +++ b/lib/utils/log/slog_handler.go @@ -379,7 +379,7 @@ func (s *SlogTextHandler) Handle(ctx context.Context, r slog.Record) error { Line: f.Line, } - file, line := getCaller(slog.Attr{Key: slog.SourceKey, Value: slog.AnyValue(src)}) + file, line := getCaller(src) *buf = fmt.Appendf(*buf, " %s:%d", file, line) } @@ -495,11 +495,22 @@ func NewSlogJSONHandler(w io.Writer, cfg SlogJSONHandlerConfig) *SlogJSONHandler if !withComponent { return slog.Attr{} } + if a.Value.Kind() != slog.KindString { + return a + } a.Key = componentField case slog.LevelKey: + // The slog.JSONHandler will inject "level" Attr. + // However, this lib's consumer might add an Attr using the same key ("level") and we end up with two records named "level". + // We must check its type before assuming this was injected by the slog.JSONHandler. + lvl, ok := a.Value.Any().(slog.Level) + if !ok { + return a + } + var level string - switch lvl := a.Value.Any().(slog.Level); lvl { + switch lvl { case TraceLevel: level = "trace" case slog.LevelDebug: @@ -522,6 +533,13 @@ func NewSlogJSONHandler(w io.Writer, cfg SlogJSONHandlerConfig) *SlogJSONHandler return slog.Attr{} } + // The slog.JSONHandler will inject "time" Attr. + // However, this lib's consumer might add an Attr using the same key ("time") and we end up with two records named "time". + // We must check its type before assuming this was injected by the slog.JSONHandler. + if a.Value.Kind() != slog.KindTime { + return a + } + t := a.Value.Time() if t.IsZero() { return a @@ -530,13 +548,27 @@ func NewSlogJSONHandler(w io.Writer, cfg SlogJSONHandlerConfig) *SlogJSONHandler a.Key = timestampField a.Value = slog.StringValue(t.Format(time.RFC3339)) case slog.MessageKey: + // The slog.JSONHandler will inject "msg" Attr. + // However, this lib's consumer might add an Attr using the same key ("msg") and we end up with two records named "msg". + // We must check its type before assuming this was injected by the slog.JSONHandler. + if a.Value.Kind() != slog.KindString { + return a + } a.Key = messageField case slog.SourceKey: if !withCaller { return slog.Attr{} } - file, line := getCaller(a) + // The slog.JSONHandler will inject "source" Attr when AddSource is true. + // However, this lib's consumer might add an Attr using the same key ("source") and we end up with two records named "source". + // We must check its type before assuming this was injected by the slog.JSONHandler. + s, ok := a.Value.Any().(*slog.Source) + if !ok { + return a + } + + file, line := getCaller(s) a = slog.String(callerField, fmt.Sprintf("%s:%d", file, line)) } @@ -589,8 +621,7 @@ func (j *SlogJSONHandler) Handle(ctx context.Context, r slog.Record) error { // getCaller retrieves source information from the attribute // and returns the file and line of the caller. The file is // truncated from the absolute path to package/filename. -func getCaller(a slog.Attr) (file string, line int) { - s := a.Value.Any().(*slog.Source) +func getCaller(s *slog.Source) (file string, line int) { count := 0 idx := strings.LastIndexFunc(s.File, func(r rune) bool { if r == '/' { diff --git a/lib/utils/log/slog_handler_test.go b/lib/utils/log/slog_handler_test.go index 39639bd2f3b79..20876b6c4df1c 100644 --- a/lib/utils/log/slog_handler_test.go +++ b/lib/utils/log/slog_handler_test.go @@ -20,6 +20,7 @@ package log import ( "bytes" + "context" "encoding/json" "fmt" "log/slog" @@ -180,3 +181,45 @@ func TestSlogJSONHandler(t *testing.T) { } require.NoError(t, slogtest.TestHandler(h, results)) } + +func TestSlogJSONHandlerReservedKeysOverrideTypeDoesntPanic(t *testing.T) { + ctx := context.Background() + var buf bytes.Buffer + logger := slog.New(NewSlogJSONHandler(&buf, SlogJSONHandlerConfig{Level: slog.LevelDebug})) + + logger.DebugContext(ctx, "Must not panic", "source", "not a slog.Source type", "time", "not a time.Time type", "level", true, "msg", 123) //nolint:sloglint // testing possible panics when using reserved keys + + logRecordMap := make(map[string]any) + require.NoError(t, json.Unmarshal(buf.Bytes(), &logRecordMap)) + + // Builtin fields must be present + require.Contains(t, logRecordMap, "caller") + require.Contains(t, logRecordMap["caller"], "slog_handler_test.go") + + require.Contains(t, logRecordMap, "message") + require.Equal(t, "Must not panic", logRecordMap["message"]) + + require.Contains(t, logRecordMap, "timestamp") + + // Some fields can appear twice in the output + // See https://github.com/golang/go/issues/59365 + // Map does not accept two fields with the same name, so we must compare against the actual output. + + // Level is injected by the handler but was also defined as Attr, so it must appear twice. + require.Contains(t, buf.String(), `"level":true`) + require.Contains(t, buf.String(), `"level":"debug"`) + + // Fields that conflict with built-ins but have a different name, when not using the expected Attr Value's type should be present + + // source was injected but is not of slog.Source type, so, its value must be kept + require.Contains(t, logRecordMap, "source") + require.Equal(t, "not a slog.Source type", logRecordMap["source"]) + + // time was injected but is not of time.Time type, so, its value must be kept + require.Contains(t, logRecordMap, "time") + require.Equal(t, "not a time.Time type", logRecordMap["time"]) + + // msg was injected but is not a string, so, its value must be kept + require.Contains(t, logRecordMap, "msg") + require.InEpsilon(t, float64(123), logRecordMap["msg"], float64(0)) +}