From f58d2639faa4deb194fdf457f6c370e176f288b1 Mon Sep 17 00:00:00 2001 From: TJ Hoplock Date: Mon, 30 Jun 2025 22:38:30 -0400 Subject: [PATCH 1/4] fix(promslog): always print time.Duration values as go duration strings Addresses: prometheus/prometheus#16766 As brought up in the linked issue, it seems that upstream slog handles time.Duration values in a sub-optimal way in the JSON handler. To improve handling of duration values in a consistent way across the ecosystem, we should ensure that duration values are handled the same way across all supported log formats (json and logfmt). This change ensures that any key containing a value that is a time.Duration is reformatted as a boring string value, explicitly formatted as a Go duration string (ie, "1d2h3m") by calling the `String()` method on the duration. Example test output pre/post patch: Before: ``` ~/go/src/github.com/prometheus/common (main [ U ]) -> go test -v -race ./promslog -run TestDurationValues === RUN TestDurationValues time=2025-06-30T22:11:01.682-04:00 level=INFO source=slog_test.go:108 msg="duration testing" duration_raw=1m30s duration_string=1m30s {"time":"2025-06-30T22:11:01.683153372-04:00","level":"INFO","source":"slog_test.go:123","msg":"duration testing","duration_raw":90000000000,"duration_string":"1m30s"} slog_test.go:128: Error Trace: /home/tjhop/go/src/github.com/prometheus/common/promslog/slog_test.go:128 Error: "{\"time\":\"2025-06-30T22:11:01.683153372-04:00\",\"level\":\"INFO\",\"source\":\"slog_test.go:123\",\"msg\":\"duration testing\",\"duration_raw\":90000000000,\"duration_string\":\"1m30s\"}\n" should not contain "\"duration_raw\":90000000000" Test: TestDurationValues Messages: Expected duration to be output as Go duration string "1m30s", got "90000000000" --- FAIL: TestDurationValues (0.00s) FAIL FAIL github.com/prometheus/common/promslog 0.018s FAIL ``` After: ``` ~/go/src/github.com/prometheus/common (main [ U ]) -> go test -v -race ./promslog -run TestDurationValues === RUN TestDurationValues time=2025-06-30T22:13:03.714-04:00 level=INFO source=slog_test.go:108 msg="duration testing" duration_raw=1m30s duration_string=1m30s {"time":"2025-06-30T22:13:03.714880745-04:00","level":"INFO","source":"slog_test.go:123","msg":"duration testing","duration_raw":"1m30s","duration_string":"1m30s"} --- PASS: TestDurationValues (0.00s) PASS ok github.com/prometheus/common/promslog 1.014s ``` Signed-off-by: TJ Hoplock --- promslog/slog.go | 14 ++++++++++++++ promslog/slog_test.go | 36 ++++++++++++++++++++++++++++++++++++ 2 files changed, 50 insertions(+) diff --git a/promslog/slog.go b/promslog/slog.go index 8da43aef5..02370f175 100644 --- a/promslog/slog.go +++ b/promslog/slog.go @@ -197,6 +197,13 @@ func newGoKitStyleReplaceAttrFunc(lvl *Level) func(groups []string, a slog.Attr) } default: } + + // Ensure time.Duration values are _always_ formatted as a Go + // duration string (ie, "1d2h3m"). + if v, ok := a.Value.Any().(time.Duration); ok { + a.Value = slog.StringValue(v.String()) + } + return a } } @@ -238,6 +245,13 @@ func defaultReplaceAttr(_ []string, a slog.Attr) slog.Attr { } default: } + + // Ensure time.Duration values are _always_ formatted as a Go duration + // string (ie, "1d2h3m"). + if v, ok := a.Value.Any().(time.Duration); ok { + a.Value = slog.StringValue(v.String()) + } + return a } diff --git a/promslog/slog_test.go b/promslog/slog_test.go index ea4e176c2..4ced0189c 100644 --- a/promslog/slog_test.go +++ b/promslog/slog_test.go @@ -21,6 +21,7 @@ import ( "regexp" "strings" "testing" + "time" "github.com/stretchr/testify/require" "gopkg.in/yaml.v2" @@ -94,6 +95,41 @@ func getLogEntryLevelCounts(s string, re *regexp.Regexp) map[string]int { return counters } +func TestDurationValues(t *testing.T) { + var ( + buf bytes.Buffer + output string + dur, _ = time.ParseDuration("1m30s") + config = &Config{Writer: &buf} + ) + + // Test logfmt. + logger := New(config) + logger.Info("duration testing", slog.Duration("duration_raw", dur), slog.String("duration_string", dur.String())) + output = buf.String() + // Print logs for humans to see, if needed. + fmt.Println(output) + + require.NotContainsf(t, output, "duration_raw=\"90000000000\"", "Expected duration to be output as Go duration string \"1m30s\", got \"90000000000\"") + + buf.Reset() + + // Test json. + jsonFmt := NewFormat() + _ = jsonFmt.Set("json") + config.Format = jsonFmt + + logger = New(config) + logger.Info("duration testing", "duration_raw", dur, "duration_string", dur.String()) + output = buf.String() + // Print logs for humans to see, if needed. + fmt.Println(output) + + require.NotContainsf(t, output, "\"duration_raw\":90000000000", "Expected duration to be output as Go duration string \"1m30s\", got \"90000000000\"") + + buf.Reset() +} + func TestDynamicLevels(t *testing.T) { var buf bytes.Buffer wantedLevelCounts := map[string]int{"info": 1, "debug": 1} From 2d8aa43f0dedf9d831c2e87a0d999f635f755f70 Mon Sep 17 00:00:00 2001 From: TJ Hoplock Date: Tue, 1 Jul 2025 15:32:45 -0400 Subject: [PATCH 2/4] test(promslog): improve duration tests, convert to table driven suite Addresses PR feedback Signed-off-by: TJ Hoplock --- promslog/slog_test.go | 46 +++++++++++++++++++------------------------ 1 file changed, 20 insertions(+), 26 deletions(-) diff --git a/promslog/slog_test.go b/promslog/slog_test.go index 4ced0189c..2efb82d59 100644 --- a/promslog/slog_test.go +++ b/promslog/slog_test.go @@ -98,36 +98,30 @@ func getLogEntryLevelCounts(s string, re *regexp.Regexp) map[string]int { func TestDurationValues(t *testing.T) { var ( buf bytes.Buffer - output string dur, _ = time.ParseDuration("1m30s") - config = &Config{Writer: &buf} + config = &Config{ + Writer: &buf, + Format: NewFormat(), + } ) - // Test logfmt. - logger := New(config) - logger.Info("duration testing", slog.Duration("duration_raw", dur), slog.String("duration_string", dur.String())) - output = buf.String() - // Print logs for humans to see, if needed. - fmt.Println(output) - - require.NotContainsf(t, output, "duration_raw=\"90000000000\"", "Expected duration to be output as Go duration string \"1m30s\", got \"90000000000\"") - - buf.Reset() - - // Test json. - jsonFmt := NewFormat() - _ = jsonFmt.Set("json") - config.Format = jsonFmt - - logger = New(config) - logger.Info("duration testing", "duration_raw", dur, "duration_string", dur.String()) - output = buf.String() - // Print logs for humans to see, if needed. - fmt.Println(output) - - require.NotContainsf(t, output, "\"duration_raw\":90000000000", "Expected duration to be output as Go duration string \"1m30s\", got \"90000000000\"") + tests := map[string]struct { + want string + logFormat string + }{ + "logfmt_duration_testing": {want: "duration_raw=1m30s", logFormat: "logfmt"}, + "json_duration_testing": {want: "\"duration_raw\":\"1m30s\"", logFormat: "json"}, + } - buf.Reset() + for name, tc := range tests { + t.Run(name, func(t *testing.T) { + buf.Reset() + _ = config.Format.Set(tc.logFormat) + logger := New(config) + logger.Info("duration testing", "duration_raw", dur, "duration_string", dur.String()) + require.Contains(t, buf.String(), tc.want) + }) + } } func TestDynamicLevels(t *testing.T) { From 417afd78f2df3eb8332acdec4cdf7b0883d1dd3c Mon Sep 17 00:00:00 2001 From: TJ Hoplock Date: Wed, 2 Jul 2025 15:18:19 -0400 Subject: [PATCH 3/4] test(promslog): refactor duration tests Signed-off-by: TJ Hoplock --- promslog/slog_test.go | 20 +++++++++----------- 1 file changed, 9 insertions(+), 11 deletions(-) diff --git a/promslog/slog_test.go b/promslog/slog_test.go index 2efb82d59..8a0cd935c 100644 --- a/promslog/slog_test.go +++ b/promslog/slog_test.go @@ -96,18 +96,12 @@ func getLogEntryLevelCounts(s string, re *regexp.Regexp) map[string]int { } func TestDurationValues(t *testing.T) { - var ( - buf bytes.Buffer - dur, _ = time.ParseDuration("1m30s") - config = &Config{ - Writer: &buf, - Format: NewFormat(), - } - ) + dur, err := time.ParseDuration("1m30s") + require.NoError(t, err) tests := map[string]struct { - want string logFormat string + want string }{ "logfmt_duration_testing": {want: "duration_raw=1m30s", logFormat: "logfmt"}, "json_duration_testing": {want: "\"duration_raw\":\"1m30s\"", logFormat: "json"}, @@ -115,8 +109,12 @@ func TestDurationValues(t *testing.T) { for name, tc := range tests { t.Run(name, func(t *testing.T) { - buf.Reset() - _ = config.Format.Set(tc.logFormat) + var buf bytes.Buffer + config := &Config{ + Writer: &buf, + Format: NewFormat(), + } + require.NoError(t, config.Format.Set(tc.logFormat)) logger := New(config) logger.Info("duration testing", "duration_raw", dur, "duration_string", dur.String()) require.Contains(t, buf.String(), tc.want) From 1dc30addc559c21fc008a57008d80cab18ffa8f6 Mon Sep 17 00:00:00 2001 From: TJ Hoplock Date: Thu, 3 Jul 2025 12:21:01 -0400 Subject: [PATCH 4/4] test(promslog): more specific string check for duration testing Signed-off-by: TJ Hoplock --- promslog/slog_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/promslog/slog_test.go b/promslog/slog_test.go index 8a0cd935c..91e79a9fb 100644 --- a/promslog/slog_test.go +++ b/promslog/slog_test.go @@ -103,8 +103,8 @@ func TestDurationValues(t *testing.T) { logFormat string want string }{ - "logfmt_duration_testing": {want: "duration_raw=1m30s", logFormat: "logfmt"}, - "json_duration_testing": {want: "\"duration_raw\":\"1m30s\"", logFormat: "json"}, + "logfmt_duration_testing": {want: "duration_raw=1m30s duration_string=1m30s", logFormat: "logfmt"}, + "json_duration_testing": {want: "\"duration_raw\":\"1m30s\",\"duration_string\":\"1m30s\"", logFormat: "json"}, } for name, tc := range tests {