Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Log sleep durations more definitively #699

Merged
merged 1 commit into from
Dec 22, 2024

Conversation

brandur
Copy link
Contributor

@brandur brandur commented Dec 21, 2024

While looking into #695 the other day, I was reminded that the handling
of time.Duration in things like logging is potentially not very good.

time.Duration has a good String() override that tends to get used
with text handlers, but for various legacy reasons it doesn't have a
MarshalJSON implementation, so when dumped to JSON it gets put in
nanoseconds, which isn't very readable for human or computer.

This is relevant to use because slog's JSONHandler and TextHandler
will probably be the most common logging instruments for River. e.g.

func main() {
    dur := 500 * time.Millisecond

    loggerText := slog.New(slog.NewTextHandler(os.Stdout, nil))
    loggerText.Info("with text handler", "sleep_duration", dur)

    loggerJSON := slog.New(slog.NewJSONHandler(os.Stdout, nil))
    loggerJSON.Info("with JSON handler", "sleep_duration", dur)
}

time=2024-12-19T21:36:41.948-07:00 level=INFO msg="with text handler" sleep_duration=500ms
{"time":"2024-12-19T21:36:41.949239-07:00","level":"INFO","msg":"with JSONtext handler","sleep_duration":500000000}

Here, change the various places that we log sleep to use a more
definitive value for purposes of the log. In this case a duration string
representation like 10s.

I debated making this a float instead that'd be represented in seconds
because the float would be more parseable for ingestion engines like
Splunk. I went with the former option in the end though because it's
probably better for humans and most other cases, and we could always add
an alternative sleep_seconds field that's a float later if someone
asks for it.

@brandur brandur force-pushed the brandur-sleep-duration-logging branch 2 times, most recently from 7ac139d to 5607ddb Compare December 21, 2024 06:06
@brandur brandur requested a review from bgentry December 21, 2024 06:20
While looking into #695 the other day, I was reminded that the handling
of `time.Duration` in things like logging is potentially not very good.

`time.Duration` has a good `String()` override that tends to get used
with text handlers, but for various legacy reasons it doesn't have a
`MarshalJSON` implementation, so when dumped to JSON it gets put in
nanoseconds, which isn't very readable for human or computer.

This is relevant to use because slog's `JSONHandler` and `TextHandler`
will probably be the most common logging instruments for River. e.g.

    func main() {
        dur := 500 * time.Millisecond

        loggerText := slog.New(slog.NewTextHandler(os.Stdout, nil))
        loggerText.Info("with text handler", "sleep_duration", dur)

        loggerJSON := slog.New(slog.NewJSONHandler(os.Stdout, nil))
        loggerJSON.Info("with JSON handler", "sleep_duration", dur)
    }

    time=2024-12-19T21:36:41.948-07:00 level=INFO msg="with text handler" sleep_duration=500ms
    {"time":"2024-12-19T21:36:41.949239-07:00","level":"INFO","msg":"with JSONtext handler","sleep_duration":500000000}

Here, change the various places that we log sleep to use a more
definitive value for purposes of the log. In this case a duration string
representation like `10s`.

I debated making this a float instead that'd be represented in seconds
because the float would be more parseable for ingestion engines like
Splunk. I went with the former option in the end though because it's
probably better for humans and most other cases, and we could always add
an alternative `sleep_seconds` field that's a float later if someone
asks for it.
@brandur brandur force-pushed the brandur-sleep-duration-logging branch from 5607ddb to 3ace179 Compare December 21, 2024 06:21
@brandur brandur merged commit 45a0964 into master Dec 22, 2024
10 checks passed
@brandur brandur deleted the brandur-sleep-duration-logging branch December 22, 2024 20:34
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants