[v15] Prevent panic when mis-using the SourceKey in slog

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 == '/' {

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))
+}