Logging's msecs doesn't handle "100ms" well.

[dougthor42]

Bug report

LogRecord.msecs returns an incorrect value when timestamp (self.ct) value has exactly 100ms.

One liner check:

assert int((1677793338.100_000_0 - int(1677793338.100_000_0)) * 1000) + 0.0 == 100.0

The issue is binary representation of "0.1" / floating point error:

>>> # Definition of LogRecord.msecs:
>>> # https://github.com/python/cpython/blob/12011dd8bafa6867f2b4a8a9e8e54cb0fbf006e4/Lib/logging/__init__.py#L343
>>> # int((ct - int(ct)) * 1000) + 0.0
>>> ct = 1677793338.100_000_0
>>> ct
1677793338.1
>>> ct - int(ct)
0.09999990463256836
>>> _ * 1000
99.99990463256836
>>> int(_)
99
>>> _ + 0.0
99.0

Your environment

• CPython versions tested on:
  • 3.10.9
  • 3.11.2
• Operating system and architecture:
  • Custom company OS based on Debian Testing
  • 64-bit

Discussion

I think switching to time.time_ns when setting the creation time might be one solution.

Linked PRs

• gh-102402: Fix floating point math issue by using time.time_ns() in logging.LogRecord #102412
• gh-102402: Fix logging test_relativeCreated_has_higher_precision() leak #117985
• gh-102402: Make test_relativeCreated_has_higher_precision less implementation dependent #118062

[vacosti]

I agree with @dougthor42 about the proposed solution, since time library itself suggests to "use time_ns() to avoid the precision loss caused by the float type".

[dougthor42]

I hope to find some time this weekend to implement a fix.