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

Do not truncate Logger timestamps #5871

Closed
wants to merge 4 commits into from
Closed

Do not truncate Logger timestamps #5871

wants to merge 4 commits into from

Conversation

binarylogic
Copy link
Contributor

Is there any reason why the precision on Logger timestamps is being truncated? If so, can this be commented / documented somewhere?

A few reasons we should not do this:

  1. We're seeing log messages share the same timestamp, thus presenting them out of order in external logging systems.
  2. The syslog specification allows up to a microsecond precision: https://tools.ietf.org/html/rfc5424
  3. The backend should be solely responsible for removing precision.

Thanks for taking a look!

end

@doc """
Formats time as chardata.
"""
def format_time({hh, mi, ss, ms}) do
[pad2(hh), ?:, pad2(mi), ?:, pad2(ss), ?., pad3(ms)]
Copy link
Member

Choose a reason for hiding this comment

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

In order to not change the output currently logged, let's make this be:

[pad2(hh), ?:, pad2(mi), ?:, pad2(ss), ?., ms |> div(1000) |> pad3()]

If you want to log with higher precision, then you can always call your own format_time function.

This way you get higher precision in the backend but remove the precision only when formatting, as you mentioned.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Sure, makes sense. I'll update.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Ok, all set.

@fishcakez
Copy link
Member

This would be a breaking change, so would have to be opt-in. I would rather we support an option to use a date time struct.

@josevalim
Copy link
Member

@fishcakez you are right. We are changing the meaning of the tuple element. I think having an option for using time structs is likely the way to go here.

@binarylogic
Copy link
Contributor Author

Sure, do you mind explaining why this is breaking? And does this mean Elixir is locked in at millisecond precision for logging, by default?

@fishcakez
Copy link
Member

do you mind explaining why this is breaking?

We support custom formatting functions, and these receive the timestamp tuple, which is currently milliseconds. See Logger.Formatter.compile({module, function}). Therefore we can't change the timestamp to be microseconds, instead of milliseconds.

And does this mean Elixir is locked in at millisecond precision for logging, by default?

Yes

@binarylogic
Copy link
Contributor Author

Thanks. I'll update this to take an option.

@josevalim
Copy link
Member

Hi @binarylogic! I am closing this PR as, per the discussion above, it is backwards incompatible. Instead, we should probably move to a NaiveDateTime struct, configured via an option. Thank you!

@josevalim josevalim closed this May 8, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging this pull request may close these issues.

4 participants