From 58d94e28823f9129ae614d9ddcf3170f0f932610 Mon Sep 17 00:00:00 2001 From: TJ Hoplock Date: Mon, 13 Jan 2025 13:39:15 -0500 Subject: [PATCH 1/2] 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: #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 --- promslog/slog.go | 97 +++++++++++++++++++++++++++++++++---------- promslog/slog_test.go | 39 +++++++++++++++++ 2 files changed, 115 insertions(+), 21 deletions(-) diff --git a/promslog/slog.go b/promslog/slog.go index 6e8fbabc..11c33fb6 100644 --- a/promslog/slog.go +++ b/promslog/slog.go @@ -25,6 +25,7 @@ import ( "path/filepath" "strconv" "strings" + "time" ) type LogStyle string @@ -32,6 +33,8 @@ 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: } diff --git a/promslog/slog_test.go b/promslog/slog_test.go index fc824e04..7d814b89 100644 --- a/promslog/slog_test.go +++ b/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()) + }) + } +} From 3a12c6e123e9847679bf15e5ac21f9cc9f5004d9 Mon Sep 17 00:00:00 2001 From: TJ Hoplock Date: Mon, 13 Jan 2025 15:48:24 -0500 Subject: [PATCH 2/2] test(promslog): make linter happy Signed-off-by: TJ Hoplock --- promslog/slog_test.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/promslog/slog_test.go b/promslog/slog_test.go index 7d814b89..6da14d98 100644 --- a/promslog/slog_test.go +++ b/promslog/slog_test.go @@ -218,9 +218,9 @@ func TestReservedKeys(t *testing.T) { ) 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") + require.Containsf(t, output, fmt.Sprintf("%s%s=\"%s\"", reservedKeyPrefix, tc.levelKey, reservedKeyTestVal), "Expected duplicate level key to be renamed") + require.Containsf(t, output, fmt.Sprintf("%s%s=\"%s\"", reservedKeyPrefix, tc.sourceKey, reservedKeyTestVal), "Expected duplicate source key to be renamed") + require.Containsf(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())