https://github.com/python/cpython/commit/1500a23f33f5a6d052ff1ef6383d9839928b8ff1
commit: 1500a23f33f5a6d052ff1ef6383d9839928b8ff1
branch: main
author: Serhiy Storchaka <[email protected]>
committer: serhiy-storchaka <[email protected]>
date: 2024-06-24T09:50:39+03:00
summary:
gh-120683: Fix an error in logging.LogRecord timestamp (GH-120709)
The integer part of the timestamp can be 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).
files:
A Misc/NEWS.d/next/Library/2024-06-18-19-18-10.gh-issue-120683.xmRez7.rst
M Lib/logging/__init__.py
M Lib/test/test_logging.py
diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py
index 174b37c0ab305b..3f4144226b40ec 100644
--- a/Lib/logging/__init__.py
+++ b/Lib/logging/__init__.py
@@ -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:
diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py
index 5192ce252a4d4c..ddb9481807bb55 100644
--- a/Lib/test/test_logging.py
+++ b/Lib/test/test_logging.py
@@ -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.
diff --git
a/Misc/NEWS.d/next/Library/2024-06-18-19-18-10.gh-issue-120683.xmRez7.rst
b/Misc/NEWS.d/next/Library/2024-06-18-19-18-10.gh-issue-120683.xmRez7.rst
new file mode 100644
index 00000000000000..50fc9279e4bad1
--- /dev/null
+++ b/Misc/NEWS.d/next/Library/2024-06-18-19-18-10.gh-issue-120683.xmRez7.rst
@@ -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).
_______________________________________________
Python-checkins mailing list -- [email protected]
To unsubscribe send an email to [email protected]
https://mail.python.org/mailman3/lists/python-checkins.python.org/
Member address: [email protected]
