gh-102402: Fix floating point math issue by using time.time_ns() in logging.LogRecord

Lib/logging/__init__.py

@@ -56,7 +56,7 @@
 #
 #_startTime is used as the base when calculating the relative time of events
 #
-_startTime = time.time()
+_startTime = time.time_ns()
 
 #
 #raiseExceptions is used to see if exceptions during handling should be
@@ -300,7 +300,7 @@ def __init__(self, name, level, pathname, lineno,
         """
         Initialize a logging record with interesting information.
         """
-        ct = time.time()
+        ct = time.time_ns()
         self.name = name
         self.msg = msg
         #
@@ -339,9 +339,17 @@ def __init__(self, name, level, pathname, lineno,
         self.stack_info = sinfo
         self.lineno = lineno
         self.funcName = func
-        self.created = ct
-        self.msecs = int((ct - int(ct)) * 1000) + 0.0  # see gh-89047
-        self.relativeCreated = (self.created - _startTime) * 1000
+        self.created = ct / 1e9  # ns to float seconds
+
+        # x // 10**n: Drop the rightmost n digits
+        # (x // 10**n) * 10**n: "Change" the rightmost n digits to 0s.
+        # Eg: 55_123_456_789 --> 123_456_789 --> 123_000_000
+        # Lastly divide by 1e6 to change ns to ms
+        # 123_000_000 --> 123
+        # Convert to float by adding 0.0 for historical reasons.
+        self.msecs = (ct - (ct // 1_000_000_000) * 1_000_000_000) // 1_000_000 + 0.0
+
+        self.relativeCreated = (ct - _startTime) / 1e6
         if logThreads:
             self.thread = threading.get_ident()
             self.threadName = threading.current_thread().name
@@ -572,7 +580,7 @@ class Formatter(object):
     %(lineno)d          Source line number where the logging call was issued
                         (if available)
     %(funcName)s        Function name
-    %(created)f         Time when the LogRecord was created (time.time()
+    %(created)f         Time when the LogRecord was created (time.time_ns() / 1e9
                         return value)
     %(asctime)s         Textual time when the LogRecord was created
     %(msecs)d           Millisecond portion of the creation time

Lib/test/test_logging.py

@@ -58,6 +58,7 @@
 import weakref
 
 from http.server import HTTPServer, BaseHTTPRequestHandler
+from unittest.mock import patch
 from urllib.parse import urlparse, parse_qs
 from socketserver import (ThreadingUDPServer, DatagramRequestHandler,
                           ThreadingTCPServer, StreamRequestHandler)
@@ -4310,6 +4311,20 @@ def test_issue_89047(self):
             s = f.format(r)
             self.assertNotIn('.1000', s)
 
+    def test_issue_102402_100msecs(self):
+        tests = (
+            # (time_ns, expected_msecs_value)
+            (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
+
+        )
+        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)
+
 
 class TestBufferingFormatter(logging.BufferingFormatter):
     def formatHeader(self, records):

Misc/NEWS.d/next/Library/2023-03-03-21-13-08.gh-issue-102402.fpkRO1.rst

@@ -0,0 +1,2 @@
+Adjust ``logging.LogRecord`` to use ``time.time_ns()`` and fix minor bug
+related to floating point math.