[3.13] pythongh-120683: Fix an error in logging.LogRecord timestamp (pythonGH-120709) (pythonGH-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 1500a23)

Co-authored-by: Serhiy Storchaka <[email protected]>

Author: miss-islington

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:

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.

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).