https://github.com/python/cpython/commit/544a47212b92f52ceffbd50275c6b0c57a446a98 commit: 544a47212b92f52ceffbd50275c6b0c57a446a98 branch: 3.13 author: Miss Islington (bot) <[email protected]> committer: serhiy-storchaka <[email protected]> date: 2024-06-24T07:14:26Z summary:
[3.13] gh-120683: Fix an error in logging.LogRecord timestamp (GH-120709) (GH-120933) 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). (cherry picked from commit 1500a23f33f5a6d052ff1ef6383d9839928b8ff1) Co-authored-by: Serhiy Storchaka <[email protected]> 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 504862ad53395e..c78e76d16ae5cf 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -4648,13 +4648,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]
