Skip to content

gh-102402: Make test_relativeCreated_has_higher_precision less implementation dependent #118062

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.

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
Changes from all commits
Commits
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
60 changes: 45 additions & 15 deletions Lib/test/test_logging.py
Original file line number Diff line number Diff line change
Expand Up @@ -4598,25 +4598,55 @@ def test_msecs_has_no_floating_point_precision_loss(self):
self.assertEqual(record.msecs, want)
self.assertEqual(record.created, ns / 1e9)

# The test overrides a private attribute
@support.cpython_only
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
# See issue gh-102402.
# Run the code in the subprocess, because the time module should
# be patched before the first import of the logging package.
# Temporary unloading and re-importing the logging package has
# side effects (including registering the atexit callback and
# references leak).
start_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)
Copy link
Member

Choose a reason for hiding this comment

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

Add maybe a comment explaining why you spawn a subprocess? In short, I understood that it's hard to avoid side effects of re-importing the logging module, such as reference leaks.

Copy link
Member Author

Choose a reason for hiding this comment

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

Done.

code = textwrap.dedent(f"""
start_ns = {start_ns!r}
offsets_ns = {offsets_ns!r}
start_monotonic_ns = start_ns - 1

import time
# Only time.time_ns needs to be patched for the current
# implementation, but patch also other functions to make
# the test less implementation depending.
old_time_ns = time.time_ns
old_time = time.time
old_monotonic_ns = time.monotonic_ns
old_monotonic = time.monotonic
time_ns_result = start_ns
time.time_ns = lambda: time_ns_result
time.time = lambda: time.time_ns()/1e9
time.monotonic_ns = lambda: time_ns_result - start_monotonic_ns
time.monotonic = lambda: time.monotonic_ns()/1e9
try:
import logging

with (patch("time.time_ns") as time_ns_mock,
support.swap_attr(logging, '_startTime', ns)):
for offset_ns in offsets_ns:
# mock for log record creation
new_ns = ns + offset_ns
time_ns_mock.return_value = new_ns

record = logging.makeLogRecord({'msg': 'test'})
self.assertAlmostEqual(record.created, new_ns / 1e9, places=6)

for offset_ns in offsets_ns:
# mock for log record creation
time_ns_result = start_ns + offset_ns
record = logging.makeLogRecord({{'msg': 'test'}})
print(record.created, record.relativeCreated)
finally:
time.time_ns = old_time_ns
time.time = old_time
time.monotonic_ns = old_monotonic_ns
time.monotonic = old_monotonic
""")
rc, out, err = assert_python_ok("-c", code)
out = out.decode()
for offset_ns, line in zip(offsets_ns, out.splitlines(), strict=True):
with self.subTest(offset_ns=offset_ns):
created, relativeCreated = map(float, line.split())
self.assertAlmostEqual(created, (start_ns + offset_ns) / 1e9, places=6)
Copy link
Member

Choose a reason for hiding this comment

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

You could implement these checks in the child process (in "code").

Copy link
Member Author

Choose a reason for hiding this comment

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

How? if not math.isclose(...): sys.exit(1)? I do not remember parameters of math.isclose(), and in any case the TestCase methods provide more informative error reports.

Copy link
Member

Choose a reason for hiding this comment

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

Maybe write a test case and call unittest.main(). But I'm fine with your code.

Copy link
Member Author

Choose a reason for hiding this comment

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

It will add unpredicable complexity. What if unittest uses the time module, directly or indirectly?

We need also a way to translate the result from the subprocess and translate it to the outer TestCase. Much complex work for no gain. I prefer if we pass a raw data from a subprocess. It is not always possible if the data is too large or complex.

Thank you for your review @vstinner.

# After PR gh-102412, precision (places) increases from 3 to 7
self.assertAlmostEqual(record.relativeCreated, offset_ns / 1e6, places=7)
self.assertAlmostEqual(relativeCreated, offset_ns / 1e6, places=7)


class TestBufferingFormatter(logging.BufferingFormatter):
Expand Down