https://github.com/python/cpython/commit/1316692e8c7c1e1f3b6639e51804f9db5ed892ea
commit: 1316692e8c7c1e1f3b6639e51804f9db5ed892ea
branch: main
author: Douglas Thor <dougthor42@users.noreply.github.com>
committer: vsajip <vinay_sajip@yahoo.co.uk>
date: 2024-04-16T10:44:57+01:00
summary:
gh-102402: Fix floating point math issue by using `time.time_ns()` in `logging.LogRecord` (GH-102412)
files:
A Misc/NEWS.d/next/Library/2023-03-03-21-13-08.gh-issue-102402.fpkRO1.rst
M Doc/library/logging.rst
M Lib/logging/__init__.py
M Lib/test/test_logging.py
diff --git a/Doc/library/logging.rst b/Doc/library/logging.rst
index 7816cc20945fa8..a733b288ecb6d0 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 927e3e653f065a..174b37c0ab305b 100644
--- a/Lib/logging/__init__.py
+++ b/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,14 @@ 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
+
+ # 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 c3c4de06fa0f09..3f0b363066df2c 100644
--- a/Lib/test/test_logging.py
+++ b/Lib/test/test_logging.py
@@ -60,6 +60,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)
@@ -4552,6 +4553,44 @@ def test_issue_89047(self):
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 00000000000000..fa8f3750b85a6b
--- /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.
_______________________________________________
Python-checkins mailing list -- python-checkins@python.org
To unsubscribe send an email to python-checkins-leave@python.org
https://mail.python.org/mailman3/lists/python-checkins.python.org/
Member address: list-python-checkins@lists.gossamer-threads.com
commit: 1316692e8c7c1e1f3b6639e51804f9db5ed892ea
branch: main
author: Douglas Thor <dougthor42@users.noreply.github.com>
committer: vsajip <vinay_sajip@yahoo.co.uk>
date: 2024-04-16T10:44:57+01:00
summary:
gh-102402: Fix floating point math issue by using `time.time_ns()` in `logging.LogRecord` (GH-102412)
files:
A Misc/NEWS.d/next/Library/2023-03-03-21-13-08.gh-issue-102402.fpkRO1.rst
M Doc/library/logging.rst
M Lib/logging/__init__.py
M Lib/test/test_logging.py
diff --git a/Doc/library/logging.rst b/Doc/library/logging.rst
index 7816cc20945fa8..a733b288ecb6d0 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 927e3e653f065a..174b37c0ab305b 100644
--- a/Lib/logging/__init__.py
+++ b/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,14 @@ 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
+
+ # 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 c3c4de06fa0f09..3f0b363066df2c 100644
--- a/Lib/test/test_logging.py
+++ b/Lib/test/test_logging.py
@@ -60,6 +60,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)
@@ -4552,6 +4553,44 @@ def test_issue_89047(self):
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 00000000000000..fa8f3750b85a6b
--- /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.
_______________________________________________
Python-checkins mailing list -- python-checkins@python.org
To unsubscribe send an email to python-checkins-leave@python.org
https://mail.python.org/mailman3/lists/python-checkins.python.org/
Member address: list-python-checkins@lists.gossamer-threads.com