Skip to content

gh-120683: Fix an error in logging.LogRecord timestamp #120709

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

Merged
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 4 additions & 1 deletion Lib/logging/__init__.py
Original file line number Diff line number Diff line change
Expand Up @@ -340,11 +340,14 @@ def __init__(self, name, level, pathname, lineno,
self.lineno = lineno
self.funcName = func
self.created = ct / 1e9 # ns to float seconds

# Get the number of whole milliseconds (0-999) in the fractional part of seconds.
# Eg: 1_677_903_920_999_998_503 ns --> 999_998_503 ns--> 999 ms
# Convert to float by adding 0.0 for historical reasons. See gh-89047
self.msecs = (ct % 1_000_000_000) // 1_000_000 + 0.0
if self.msecs == 999.0 and int(self.created) != ct // 1_000_000_000:
# ns -> sec conversion can round up, e.g:
# 1_677_903_920_999_999_900 ns --> 1_677_903_921.0 sec
self.msecs = 0.0

self.relativeCreated = (ct - _startTime) / 1e6
if logThreads:
Expand Down
9 changes: 7 additions & 2 deletions Lib/test/test_logging.py
Original file line number Diff line number Diff line change
Expand Up @@ -4649,13 +4649,18 @@ def test_msecs_has_no_floating_point_precision_loss(self):
(1_677_902_297_100_000_000, 100.0), # exactly 100ms
(1_677_903_920_999_998_503, 999.0), # check truncating doesn't round
(1_677_903_920_000_998_503, 0.0), # check truncating doesn't round
(1_677_903_920_999_999_900, 0.0), # check rounding up
)
for ns, want in tests:
with patch('time.time_ns') as patched_ns:
patched_ns.return_value = ns
record = logging.makeLogRecord({'msg': 'test'})
self.assertEqual(record.msecs, want)
self.assertEqual(record.created, ns / 1e9)
with self.subTest(ns):
self.assertEqual(record.msecs, want)
self.assertEqual(record.created, ns / 1e9)
self.assertAlmostEqual(record.created - int(record.created),
record.msecs / 1e3,
delta=1e-3)

def test_relativeCreated_has_higher_precision(self):
# See issue gh-102402.
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,4 @@
Fix an error in :class:`logging.LogRecord`, when the integer part of the
timestamp is rounded up, while the millisecond calculation truncates,
causing the log timestamp to be wrong by up to 999 ms (affected roughly 1 in
8 million timestamps).
Loading