fix(promslog): always print time.Duration values as go duration strings #798
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
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 <t.hoplock@gmail.com>
Addresses PR feedback Signed-off-by: TJ Hoplock <t.hoplock@gmail.com>
Contributor
Author
|
Tests improved: # before patch
~/go/src/github.com/prometheus/common (fix/promslog-consistent-duration-formatting [ U ]) -> go test -v -race ./promslog -run TestDurationValues
=== RUN TestDurationValues
=== RUN TestDurationValues/logfmt_duration_testing
=== RUN TestDurationValues/json_duration_testing
slog_test.go:122:
Error Trace: /home/tjhop/go/src/github.com/prometheus/common/promslog/slog_test.go:122
Error: "{\"time\":\"2025-07-01T15:31:37.545281226-04:00\",\"level\":\"INFO\",\"source\":\"slog_test.go:121\",\"msg\":\"duration testing\",\"duration_raw\":90000000000,\"duration_string\":\"1m30s\"}\n" does not contain "\"duration_raw\":\"1m30s\""
Test: TestDurationValues/json_duration_testing
--- FAIL: TestDurationValues (0.00s)
--- PASS: TestDurationValues/logfmt_duration_testing (0.00s)
--- FAIL: TestDurationValues/json_duration_testing (0.00s)
FAIL
FAIL github.com/prometheus/common/promslog 0.015s
FAIL# after patch
~/go/src/github.com/prometheus/common (fix/promslog-consistent-duration-formatting [ U ]) -> go test -v -race ./promslog -run TestDurationValues
=== RUN TestDurationValues
=== RUN TestDurationValues/logfmt_duration_testing
=== RUN TestDurationValues/json_duration_testing
--- PASS: TestDurationValues (0.00s)
--- PASS: TestDurationValues/logfmt_duration_testing (0.00s)
--- PASS: TestDurationValues/json_duration_testing (0.00s)
PASS
ok github.com/prometheus/common/promslog 1.015s |
machine424
approved these changes
Jul 2, 2025
Member
machine424
left a comment
There was a problem hiding this comment.
lgtm, thanks.
Some nits to isolate the subtests and test both fields:
diff --git a/promslog/slog_test.go b/promslog/slog_test.go
index 2efb82d..5ffe3cf 100644
--- a/promslog/slog_test.go
+++ b/promslog/slog_test.go
@@ -96,27 +96,25 @@ 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"},
+ "logfmt_duration_testing": {logFormat: "logfmt", want: "duration_raw=1m30s duration_string=1m30s"},
+ "json_duration_testing": {logFormat: "json", want: "\"duration_raw\":\"1m30s\",\"duration_string\":\"1m30s\""},
}
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)Signed-off-by: TJ Hoplock <t.hoplock@gmail.com>
machine424
reviewed
Jul 3, 2025
Signed-off-by: TJ Hoplock <t.hoplock@gmail.com>
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
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:
After:
Signed-off-by: TJ Hoplock t.hoplock@gmail.com