Bug report

Bug description:

The change made in#102412 introduces floating-point issues that in corner cases can cause log timestamps to be wrong by up to 999ms. This is much worse than the bug it was trying to fix (#102402). For example:

importloggingimporttimefromunittestimportmockdeffake_time_ns():return1718710000_000_000_000-1deffake_time():returnfake_time_ns()/1e9logging.basicConfig(level=logging.INFO,format="%(asctime)s %(message)s")withmock.patch("time.time_ns",fake_time_ns),mock.patch("time.time",fake_time):logging.info("The time is now")

when run with TZ=utc will output

2024-06-18 11:26:40,999 The time is now

The correct time (modulo any timezone shifts) is 11:26:40 (minus 1 nanosecond).

This occurs because when converting thetime_ns result to a floating-point timestamp to store inself.created, the result is rounded, while the millisecond calculation truncates. This will affect roughly 1 in 8 million timestamps.

I don't think this can happen prior to#102412, although it depends onFormatter.converter to take the floor of the given value. A custom converter that went viadatetime.fromtimestamp could go wrong, because that rounds to thenearest microsecond, but the defaulttime.localtime converter takes the floor.

gh-102402 points out that representing time as floating-point seconds can't exactly represent decimal fractions, but it's not clear to me why that's considered an issue. In generaltime_ns() has two advantages:

1. It's higher precision (although not necessarily higher accuracy); but the overheads of processing and formatting a log message are higher than the precision oftime.time() anyway, and the provided formatting code only handles millisecond precision.
2. It allows calculations to be performed in integer arithmetic, avoiding corner cases such aslogging Formatter behavior when using msecs and braces : '{' #89047. However, we're stuck withLogRecord.created being a float for compatibility reasons, and as shown above, mixing integer and float arithmetic leads to inconsistent results.

So my recommendation is to revert#102412. If that's not considered acceptable, then this corner case can be detected by checking forint(self.created) != ct // 1_000_000_000 and adjustedself.msecs to compensate.

CPython versions tested on:

3.13

Operating systems tested on:

Linux

Linked PRs

• gh-120683: Fix an error in logging.LogRecord timestamp #120709
• [3.13] gh-120683: Fix an error in logging.LogRecord timestamp (GH-120709) #120933