feat(promslog): implement reserved keys, rename duplicates

This commit adds support for "reserved" keys, where upon detecting a
duplicate log attribute key, it will rename the key to prevent
collisions/issues with core slog attribute keys in use.

The reserved keys are:
- `level`
- `source` (for standard slog style)
- `caller` (for legacy go-kit style)
- `time`   (for standard slog style)
- `ts`     (for legacy go-kit style)

By supporting reserved keys, we allow users of the library to use these
keys for their own supplemental log attributes.

Fixes: prometheus#745

Example test output:
```
=== RUN   TestReservedKeys/slog_log_style
time=2025-01-13T18:32:46.508Z level=INFO source=slog_test.go:212 msg="reserved keys test for slog_log_style" logged_level="surprise! I'm a string" logged_source="surprise! I'm a string" logged_time="surprise! I'm a string"

=== RUN   TestReservedKeys/go-kit_log_style
ts=2025-01-13T18:32:46.508Z level=info caller=slog_test.go:212 msg="reserved keys test for go-kit_log_style" logged_level="surprise! I'm a string" logged_caller="surprise! I'm a string" logged_ts="surprise! I'm a string"
```

Note: this implementation only technically removes duplicates of our
core reserved keys. If a user adds multiple instances of a reserved key,
the rest get renamed to `logged_$key`, which means there could be
duplicate attributes with `logged_$key`. This is mostly to simplify
implementation so we don't need to bother reference counting in the
replace attr function to do things like `logged_$key1`, `logged_$key2`,
etc.

Signed-off-by: TJ Hoplock <[email protected]>

promslog/slog.go

@@ -25,13 +25,16 @@ import (
 	"path/filepath"
 	"strconv"
 	"strings"
+	"time"
 )
 
 type LogStyle string
 
 const (
 	SlogStyle  LogStyle = "slog"
 	GoKitStyle LogStyle = "go-kit"
+
+	reservedKeyPrefix = "logged_"
 )
 
 var (
@@ -43,26 +46,51 @@ var (
 	goKitStyleReplaceAttrFunc = func(groups []string, a slog.Attr) slog.Attr {
 		key := a.Key
 		switch key {
-		case slog.TimeKey:
-			a.Key = "ts"
-
-			// This timestamp format differs from RFC3339Nano by using .000 instead
-			// of .999999999 which changes the timestamp from 9 variable to 3 fixed
-			// decimals (.130 instead of .130987456).
-			t := a.Value.Time()
-			a.Value = slog.StringValue(t.UTC().Format("2006-01-02T15:04:05.000Z07:00"))
-		case slog.SourceKey:
-			a.Key = "caller"
-			src, _ := a.Value.Any().(*slog.Source)
+		case slog.TimeKey, "ts":
+			if t, ok := a.Value.Any().(time.Time); ok {
+				a.Key = "ts"
 
-			switch callerAddFunc {
-			case true:
-				a.Value = slog.StringValue(filepath.Base(src.File) + "(" + filepath.Base(src.Function) + "):" + strconv.Itoa(src.Line))
-			default:
-				a.Value = slog.StringValue(filepath.Base(src.File) + ":" + strconv.Itoa(src.Line))
+				// This timestamp format differs from RFC3339Nano by using .000 instead
+				// of .999999999 which changes the timestamp from 9 variable to 3 fixed
+				// decimals (.130 instead of .130987456).
+				a.Value = slog.StringValue(t.UTC().Format("2006-01-02T15:04:05.000Z07:00"))
+			} else {
+				// If we can't cast the any from the value to a
+				// time.Time, it means the caller logged
+				// another attribute with a key of `ts`.
+				// Prevent duplicate keys (necessary for proper
+				// JSON) by renaming the key to `logged_ts`.
+				a.Key = reservedKeyPrefix + key
+			}
+		case slog.SourceKey, "caller":
+			if src, ok := a.Value.Any().(*slog.Source); ok {
+				a.Key = "caller"
+				switch callerAddFunc {
+				case true:
+					a.Value = slog.StringValue(filepath.Base(src.File) + "(" + filepath.Base(src.Function) + "):" + strconv.Itoa(src.Line))
+				default:
+					a.Value = slog.StringValue(filepath.Base(src.File) + ":" + strconv.Itoa(src.Line))
+				}
+			} else {
+				// If we can't cast the any from the value to
+				// an *slog.Source, it means the caller logged
+				// another attribute with a key of `caller`.
+				// Prevent duplicate keys (necessary for proper
+				// JSON) by renaming the key to
+				// `logged_caller`.
+				a.Key = reservedKeyPrefix + key
 			}
 		case slog.LevelKey:
-			a.Value = slog.StringValue(strings.ToLower(a.Value.String()))
+			if lvl, ok := a.Value.Any().(slog.Level); ok {
+				a.Value = slog.StringValue(strings.ToLower(lvl.String()))
+			} else {
+				// If we can't cast the any from the value to
+				// an slog.Level, it means the caller logged
+				// another attribute with a key of `level`.
+				// Prevent duplicate keys (necessary for proper
+				// JSON) by renaming the key to `logged_level`.
+				a.Key = reservedKeyPrefix + key
+			}
 		default:
 		}
 
@@ -72,11 +100,38 @@ var (
 		key := a.Key
 		switch key {
 		case slog.TimeKey:
-			t := a.Value.Time()
-			a.Value = slog.TimeValue(t.UTC())
+			if t, ok := a.Value.Any().(time.Time); ok {
+				a.Value = slog.TimeValue(t.UTC())
+			} else {
+				// If we can't cast the any from the value to a
+				// time.Time, it means the caller logged
+				// another attribute with a key of `time`.
+				// Prevent duplicate keys (necessary for proper
+				// JSON) by renaming the key to `logged_time`.
+				a.Key = reservedKeyPrefix + key
+			}
 		case slog.SourceKey:
-			src, _ := a.Value.Any().(*slog.Source)
-			a.Value = slog.StringValue(filepath.Base(src.File) + ":" + strconv.Itoa(src.Line))
+			if src, ok := a.Value.Any().(*slog.Source); ok {
+				a.Value = slog.StringValue(filepath.Base(src.File) + ":" + strconv.Itoa(src.Line))
+			} else {
+				// If we can't cast the any from the value to
+				// an *slog.Source, it means the caller logged
+				// another attribute with a key of `source`.
+				// Prevent duplicate keys (necessary for proper
+				// JSON) by renaming the key to
+				// `logged_source`.
+				a.Key = reservedKeyPrefix + key
+			}
+		case slog.LevelKey:
+			if _, ok := a.Value.Any().(slog.Level); !ok {
+				// If we can't cast the any from the value to
+				// an slog.Level, it means the caller logged
+				// another attribute with a key of `level`.
+				// Prevent duplicate keys (necessary for proper
+				// JSON) by renaming the key to
+				// `logged_level`.
+				a.Key = reservedKeyPrefix + key
+			}
 		default:
 		}
 

promslog/slog_test.go

@@ -188,3 +188,42 @@ func TestTruncateSourceFileName_GoKitStyle(t *testing.T) {
 		t.Errorf("Expected no directory separators in caller, got: %s", output)
 	}
 }
+
+func TestReservedKeys(t *testing.T) {
+	var buf bytes.Buffer
+	reservedKeyTestVal := "surprise! I'm a string"
+
+	tests := map[string]struct {
+		logStyle  LogStyle
+		levelKey  string
+		sourceKey string
+		timeKey   string
+	}{
+		"slog_log_style":   {logStyle: SlogStyle, levelKey: "level", sourceKey: "source", timeKey: "time"},
+		"go-kit_log_style": {logStyle: GoKitStyle, levelKey: "level", sourceKey: "caller", timeKey: "ts"},
+	}
+
+	for name, tc := range tests {
+		t.Run(name, func(t *testing.T) {
+			buf.Reset() // Ensure buf is reset prior to tests
+			config := &Config{Writer: &buf, Style: tc.logStyle}
+			logger := New(config)
+
+			logger.LogAttrs(context.Background(),
+				slog.LevelInfo,
+				"reserved keys test for "+name,
+				slog.String(tc.levelKey, reservedKeyTestVal),
+				slog.String(tc.sourceKey, reservedKeyTestVal),
+				slog.String(tc.timeKey, reservedKeyTestVal),
+			)
+
+			output := buf.String()
+			require.Contains(t, output, fmt.Sprintf("%s%s=\"%s\"", reservedKeyPrefix, tc.levelKey, reservedKeyTestVal), "Expected duplicate level key to be renamed")
+			require.Contains(t, output, fmt.Sprintf("%s%s=\"%s\"", reservedKeyPrefix, tc.sourceKey, reservedKeyTestVal), "Expected duplicate source key to be renamed")
+			require.Contains(t, output, fmt.Sprintf("%s%s=\"%s\"", reservedKeyPrefix, tc.timeKey, reservedKeyTestVal), "Expected duplicate time key to be renamed")
+
+			// Print logs for humans to see, if needed.
+			fmt.Println(buf.String())
+		})
+	}
+}