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 datetime #2191

Open
wants to merge 4 commits into
base: master
Choose a base branch
from

Conversation

geneticdrift
Copy link
Contributor

No description provided.

@@ -129,7 +129,7 @@ handle_status(Client &client, [[maybe_unused]] Request args, Response &r)
COMMAND_STATUS_PLAYLIST ": {}\n"
COMMAND_STATUS_PLAYLIST_LENGTH ": {}\n"
COMMAND_STATUS_MIXRAMPDB ": {}\n"
COMMAND_STATUS_STATE ": {}\n",
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Which commit introduced this bug? This should be mentioned in the commit message so we know whether a backport is necessary.

@MaxKellermann
Copy link
Member

Your commit message doesn't contain an explanation for why you believe this is necessary.
I don't like thread_local. Your commit message doesn't explain why this is necessary.

@geneticdrift
Copy link
Contributor Author

Thanks for the review.

I've added more explanations in the commit messages as well as the commit number.

The logging timestamp format can be made optional by configuration if you prefer.
Personally I find the higher resolution timestamp more helpful in catching issues even when not looking for one specifically. And in cases of user postmortem logs when it's hard to reproduce an issue, so enabling higher resolution after the fact is not always helpful.

@MaxKellermann
Copy link
Member

I think forcing time stamps on stdout is a bad thing because then you have two time stamps on each line when logging to syslog/journald. I hate when programs do that. It's okay to have the feature, but it should be opt-in.

I don't see why the TLS patch is necessary. I try to avoid TLS whenever possible. But let's talk about when this really helps: when two threads want to format a time stamp at exactly the same time. What's the worst that will happen? Both printing the exact time stamp to the buffer, and then both have the same string instead of .... having the same string? Is this worth the trouble? If it's worth it, then it should be a caller-provided buffer, not a TLS buffer.

@geneticdrift
Copy link
Contributor Author

geneticdrift commented Jan 30, 2025

I think forcing time stamps on stdout is a bad thing because then you have two time stamps on each line when logging to syslog/journald.

As far as I can tell, enabling the timestamp in log_init only if use_stdout is true doesn't affect syslog or systemd, unless the command in the systemd unit includes --stderr.
Does this use case, of both --stderr and systemd, need to be supported? If so then I can add an opt-in in the configuration.
(I tested with syslog and systemd user unit, and both did not have double timestamp. The timestamp was only enabled when using --stderr command line option, or when using a log file).

when two threads want to format a time stamp at exactly the same time

Yes, the chance of something bad happening is negligible. But to me it still feels wrong leaving it like than.
I've added passing the buffer from the caller which I think is the better option. You decide.

BTW, why "try to avoid TLS whenever possible"?

(PS. still trying to fix the mingw test build failure (it succeeds locally with the same mingw version).

@MaxKellermann
Copy link
Member

As far as I can tell, enabling the timestamp in log_init only if use_stdout is true doesn't affect syslog or systemd, unless the command in the systemd unit includes --stderr.

You're right, I have merged this commit.

Yes, the chance of something bad happening is negligible.

But what is "something bad"? Is your bad (subjective) feeling the worst that can happen, or do you have something else in mind? Is there a concrete bad consequence for this piece of not-100%-correct code?

I don't think millisecond resolution is necessary or even useful (and it costs screen space), and your code to calculate the milliseconds is rather clumsy; it first converts to double, then does a double-precision float division, then converts back to int.

Having milliseconds resolution in the log gives more
information than just seconds when debugging or analyzing
response time issues or effects of changes in server or
client code.
Log messages are prefixed with a timestamp when
written to a log file or to stdout (but not when
written to syslog or to systemd log).

The default timestamp is in seconds.
It can be configured by setting log_timestamp to
one of: none, minutes, seconds, or milliseconds.

Example:
none:         "message" (without timestamp)
minutes:      "Jan 30 17:11 : message"
seconds:      "Jan 30 17:11:32 : message"
milliseconds: "Jan 30 17:11:32.271 : message"

Having milliseconds resolution in the log gives more
information than just seconds when debugging or analyzing
response time issues or effects of changes in server or
client code.
@geneticdrift
Copy link
Contributor Author

But what is "something bad"? Is your bad (subjective) feeling the worst that can happen, or do you have something else in mind? Is there a concrete bad consequence for this piece of not-100%-correct code?

Nothing concrete just subjective. Except maybe more CPU cache efficient? But again probably negligible.

don't think millisecond resolution is necessary or even useful (and it costs screen space)

I've added a configurable timestamp that can be set to none, minutes, seconds, or milliseconds.

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