From 1316692e8c7c1e1f3b6639e51804f9db5ed892ea Mon Sep 17 00:00:00 2001 From: Douglas Thor Date: Tue, 16 Apr 2024 02:44:57 -0700 Subject: gh-102402: Fix floating point math issue by using `time.time_ns()` in `logging.LogRecord` (GH-102412) --- Doc/library/logging.rst | 2 +- Lib/logging/__init__.py | 17 ++++++---- Lib/test/test_logging.py | 39 ++++++++++++++++++++++ .../2023-03-03-21-13-08.gh-issue-102402.fpkRO1.rst | 2 ++ 4 files changed, 53 insertions(+), 7 deletions(-) create mode 100644 Misc/NEWS.d/next/Library/2023-03-03-21-13-08.gh-issue-102402.fpkRO1.rst diff --git a/Doc/library/logging.rst b/Doc/library/logging.rst index 7816cc2..a733b28 100644 --- a/Doc/library/logging.rst +++ b/Doc/library/logging.rst @@ -1003,7 +1003,7 @@ the options available to you. | | | portion of the time). | +----------------+-------------------------+-----------------------------------------------+ | created | ``%(created)f`` | Time when the :class:`LogRecord` was created | -| | | (as returned by :func:`time.time`). | +| | | (as returned by :func:`time.time_ns` / 1e9). | +----------------+-------------------------+-----------------------------------------------+ | exc_info | You shouldn't need to | Exception tuple (à la ``sys.exc_info``) or, | | | format this yourself. | if no exception has occurred, ``None``. | diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 927e3e6..174b37c 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -56,7 +56,7 @@ __date__ = "07 February 2010" # #_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 @@ class LogRecord(object): """ Initialize a logging record with interesting information. """ - ct = time.time() + ct = time.time_ns() self.name = name self.msg = msg # @@ -339,9 +339,14 @@ class LogRecord(object): 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 + + # 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 + + self.relativeCreated = (ct - _startTime) / 1e6 if logThreads: self.thread = threading.get_ident() self.threadName = threading.current_thread().name @@ -572,7 +577,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 diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index c3c4de0..3f0b363 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -60,6 +60,7 @@ import warnings 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) @@ -4552,6 +4553,44 @@ class FormatterTest(unittest.TestCase, AssertErrorMessage): s = f.format(r) self.assertNotIn('.1000', s) + def test_msecs_has_no_floating_point_precision_loss(self): + # See issue gh-102402 + tests = ( + # time_ns is approx. 2023-03-04 04:25:20 UTC + # (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) + self.assertEqual(record.created, ns / 1e9) + + def test_relativeCreated_has_higher_precision(self): + # See issue gh-102402 + ns = 1_677_903_920_000_998_503 # approx. 2023-03-04 04:25:20 UTC + offsets_ns = (200, 500, 12_354, 99_999, 1_677_903_456_999_123_456) + orig_modules = import_helper._save_and_remove_modules(['logging']) + try: + with patch("time.time_ns") as patched_ns: + # mock for module import + patched_ns.return_value = ns + import logging + for offset_ns in offsets_ns: + new_ns = ns + offset_ns + # mock for log record creation + patched_ns.return_value = new_ns + record = logging.makeLogRecord({'msg': 'test'}) + self.assertAlmostEqual(record.created, new_ns / 1e9, places=6) + # After PR gh-102412, precision (places) increases from 3 to 7 + self.assertAlmostEqual(record.relativeCreated, offset_ns / 1e6, places=7) + finally: + import_helper._save_and_remove_modules(['logging']) + sys.modules.update(orig_modules) + class TestBufferingFormatter(logging.BufferingFormatter): def formatHeader(self, records): diff --git a/Misc/NEWS.d/next/Library/2023-03-03-21-13-08.gh-issue-102402.fpkRO1.rst b/Misc/NEWS.d/next/Library/2023-03-03-21-13-08.gh-issue-102402.fpkRO1.rst new file mode 100644 index 0000000..fa8f375 --- /dev/null +++ b/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. -- cgit v0.12