Python 3.13.0b2: rounding can cause incorrect log timestamps

[bmerry]

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:

import logging
import time
from unittest import mock

def fake_time_ns():
    return 1718710000_000_000_000 - 1

def fake_time():
    return fake_time_ns() / 1e9

logging.basicConfig(level=logging.INFO, format="%(asctime)s %(message)s")
with mock.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 the time_ns result to a floating-point timestamp to store in self.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 on Formatter.converter to take the floor of the given value. A custom converter that went via datetime.fromtimestamp could go wrong, because that rounds to the nearest microsecond, but the default time.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 general time_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 of time.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 as logging Formatter behavior when using msecs and braces : '{' #89047. However, we're stuck with LogRecord.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 for int(self.created) != ct // 1_000_000_000 and adjusted self.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

[serhiy-storchaka]

Thank you for your report @bmerry. Your analysis is correct, I came to the same solution. #102412 has other advantages (more precise relativeCreated), so it is unlikely to be reverted, but this particular case can be corrected.