Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
vsajip merged 24 commits into from
Apr 16, 2024
Merged

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

Show file tree
Hide file tree
Changes from 7 commits
Commits
Show all changes
24 commits
Select commit Hold shift + click to select a range
2f046c2
Add test for 102402 100msecs
dougthor42 Mar 4, 2023
2460f88
Update logging.LogRecord to use time_ns.
dougthor42 Mar 4, 2023
059f856
Simplify msecs calculation
dougthor42 Mar 4, 2023
997bd41
Add blurb
dougthor42 Mar 4, 2023
2e7cde3
Fix comments, remove superfluous comment
dougthor42 Mar 4, 2023
5505cea
Merge branch 'main' into fix-gh-102402-logging-msecs
dougthor42 Mar 4, 2023
411a421
Switch to math algorithm rather than string manipulation.
dougthor42 Mar 5, 2023
d3a1f78
Correct and update comment
dougthor42 Apr 15, 2023
5fa370b
Use unittest.mock.patch instead of manual monkeypatching
dougthor42 Apr 15, 2023
39cab9d
formatting in test_logging.py
dougthor42 Mar 2, 2024
920bf74
Update docs
dougthor42 Mar 2, 2024
8bdc406
Keep ref to gh-89047
dougthor42 Mar 2, 2024
bf68b26
Use modulo arithmetic, update comment
dougthor42 Mar 2, 2024
e404ca0
Add comment
dougthor42 Mar 2, 2024
9661499
Correct comment
dougthor42 Mar 3, 2024
ec74b0e
Rename test
dougthor42 Mar 3, 2024
710f3ac
Add test for relativeCreated
dougthor42 Mar 3, 2024
ff8140c
remove issue num from test names; move to comment
dougthor42 Mar 3, 2024
fd45694
Use importhelper instead of importlib.reload
dougthor42 Mar 3, 2024
84b931b
Also assert record.created
dougthor42 Mar 3, 2024
5a604f9
Update test to check multiple offset values
dougthor42 Mar 3, 2024
dc90919
Optimize loop vs import CM
dougthor42 Mar 4, 2024
502ff65
Move item to variable
dougthor42 Mar 4, 2024
65ea1b5
Merge branch 'main' into fix-gh-102402-logging-msecs
vsajip Apr 15, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
18 changes: 12 additions & 6 deletions Lib/logging/__init__.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
#
Expand Down Expand Up @@ -339,9 +339,15 @@ 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
Comment thread
serhiy-storchaka marked this conversation as resolved.

# 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
Comment thread
serhiy-storchaka marked this conversation as resolved.
Outdated
# Convert to float for historical reasons.
self.msecs = (ct - (ct // 1_000_000_000) * 1_000_000_000) // 1_000_000 + 0.0
Comment thread
serhiy-storchaka marked this conversation as resolved.
Outdated

self.relativeCreated = (ct - _startTime) / 1e6
if logThreads:
self.thread = threading.get_ident()
self.threadName = threading.current_thread().name
Expand Down Expand Up @@ -572,7 +578,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
Comment thread
serhiy-storchaka marked this conversation as resolved.
return value)
%(asctime)s Textual time when the LogRecord was created
%(msecs)d Millisecond portion of the creation time
Expand Down
17 changes: 17 additions & 0 deletions Lib/test/test_logging.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4310,6 +4310,23 @@ def test_issue_89047(self):
s = f.format(r)
self.assertNotIn('.1000', s)

def test_issue_102402_100msecs(self):
Comment thread
serhiy-storchaka marked this conversation as resolved.
Outdated
og_time_ns = time.time_ns
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

Comment thread
serhiy-storchaka marked this conversation as resolved.
Outdated
)
try:
for ns, want in tests:
time.time_ns = lambda: ns
record = logging.makeLogRecord({'msg': 'test'})
self.assertEqual(record.msecs, want)
finally:
time.time_ns = og_time_ns

@dougthor42 dougthor42 Mar 4, 2023

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Question: Is there a more preferred way to accomplish this other than monkeypatching time.time_ns?

@vsajip vsajip Apr 12, 2023

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You can use unittest.mock.patch as in this example:

import time
from unittest.mock import patch

for t in (123, 456, 789):
    with patch('time.time_ns') as patched_ns:
        patched_ns.return_value = t
        value = time.time_ns()
        print(f'patched: {value}')
    print(f'OG: {time.time_ns()}')

which should, when run, print something like this:

patched: 123
OG: 1681278183002693921
patched: 456
OG: 1681278183003199141
patched: 789
OG: 1681278183003610801

@dougthor42 dougthor42 Apr 15, 2023

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, my assumption was that we probably didn't want to add imports (I don't know why I assumed that...).

Updated to patch with mock instead of manual patching.



class TestBufferingFormatter(logging.BufferingFormatter):
def formatHeader(self, records):
Expand Down
2 changes: 2 additions & 0 deletions Misc/NEWS.d/next/Library/2023-03-03-21-13-08.gh-issue-102402.fpkRO1.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,2 @@
Adjust ``logging.LogRecord`` to use ``time.time_ns()`` and fix minor bug
related to floating point math.