unittest.mock.patch failing on time.time in py3.13

[catchyzheng]

Bug report

Bug description:

Hello Python community,

I recently got datetime mismatch in py3.13. It was good previously in py3.12. The error log is as below:

    def testExceptionsAlways(self):
      """Test that structured errors/exceptions go to stderr log and terminal."""
      log.SetVerbosity(logging.ERROR)
      log.SetUserOutputEnabled(True)
      properties.VALUES.core.show_structured_logs.Set('always')
    
      log.error('-%s-', '1')
      log.critical('-%s-', '2')
      log.fatal('-%s-', '3')
      log.exception(ValueError('test exception - 4'))
>     self.AssertErrContains(
          (r'{"version": "0.0.1", "verbosity": "ERROR", '
           '"timestamp": "2017-01-01T00:00:00.000Z", "message": "-1-"}'),
          normalize_space=True)

lib/tests/unit/core/log_test.py:1114: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
lib/tests/lib/test_case.py:2602: in AssertErrContains
    self._AssertContains(expected, self.GetErr(), name,
lib/tests/lib/test_case.py:751: in _AssertContains
    self._AssertCompare(
lib/tests/lib/test_case.py:734: in _AssertCompare
    self._CompareFail(reason, expected, actual)
lib/tests/lib/test_case.py:671: in _CompareFail
    self.fail(console_attr.SafeText(msg))
E   AssertionError: stderr does not contain the expected value:
E   <<<EXPECTED>>>
E   {"version": "0.0.1", "verbosity": "ERROR", "timestamp": "2017-01-01T00:00:00.000Z", "message": "-1-"}
E   <<<ACTUAL>>>
E   {"version": "0.0.1", "verbosity": "ERROR", "timestamp": "2024-06-20T17:42:56.697Z", "message": "-1-"}
E   {"version": "0.0.1", "verbosity": "CRITICAL", "timestamp": "2024-06-20T17:42:56.698Z", "message": "-2-"}
E   {"version": "0.0.1", "verbosity": "CRITICAL", "timestamp": "2024-06-20T17:42:56.698Z", "message": "-3-"}
E   {"version": "0.0.1", "verbosity": "ERROR", "timestamp": "2024-06-20T17:42:56.699Z", "message": "test exception - 4", "error": {"type": "ValueError", "details": "test exception - 4", "stacktrace": null}}
E   
E   <<<END>>>

However, I pinned the datetime to 2017.1.1 in the code already:

def SetUp(self):
    log_date = datetime.datetime(2017, 1, 1, 0, 0)
    log_time = times.GetTimeStampFromDateTime(log_date, tzinfo=times.UTC)
    self.StartObjectPatch(time, 'time').return_value = log_time
    properties.VALUES.core.show_structured_logs.Set(None)

    self.mock_method = MockPrintException()

def testExceptionsAlways(self):
    """Test that structured errors/exceptions go to stderr log and terminal."""
    log.SetVerbosity(logging.ERROR)
    log.SetUserOutputEnabled(True)
    properties.VALUES.core.show_structured_logs.Set('always')

    log.error('-%s-', '1')
    log.critical('-%s-', '2')
    log.fatal('-%s-', '3')
    log.exception(ValueError('test exception - 4'))
    self.AssertErrContains(
        (r'{"version": "0.0.1", "verbosity": "ERROR", '
         '"timestamp": "2017-01-01T00:00:00.000Z", "message": "-1-"}'),
        normalize_space=True)

    self.AssertErrContains(
        (r'{"version": "0.0.1", "verbosity": "CRITICAL", '
         '"timestamp": "2017-01-01T00:00:00.000Z", "message": "-2-"}'),
        normalize_space=True)

    self.AssertErrContains(
        (r'{"version": "0.0.1", "verbosity": "CRITICAL", '
         '"timestamp": "2017-01-01T00:00:00.000Z", "message": "-3-"}'),
        normalize_space=True)

    self.AssertErrContains(
        (r'{"version": "0.0.1", "verbosity": "ERROR", '
         '"timestamp": "2017-01-01T00:00:00.000Z", '
         '"message": "test exception - 4", "error": {"type": "ValueError", '
         '"details": "test exception - 4", "stacktrace": null}}'),
        normalize_space=True)

    self.StartObjectPatch(log._ConsoleWriter, 'isatty').return_value = True
    self.ClearErr()
    log.Reset()
    log.SetVerbosity(logging.ERROR)
    log.error('-%s-', '5')
    log.critical('-%s-', '6')
    log.fatal('-%s-', '7')
    log.exception(ValueError('test exception - 8'))
    self.AssertErrContains(
        (r'{"version": "0.0.1", "verbosity": "ERROR", '
         '"timestamp": "2017-01-01T00:00:00.000Z", "message": "-5-"}'),
        normalize_space=True)

    self.AssertErrContains(
        (r'{"version": "0.0.1", "verbosity": "CRITICAL", '
         '"timestamp": "2017-01-01T00:00:00.000Z", "message": "-6-"}'),
        normalize_space=True)

    self.AssertErrContains(
        (r'{"version": "0.0.1", "verbosity": "CRITICAL", '
         '"timestamp": "2017-01-01T00:00:00.000Z", "message": "-7-"}'),
        normalize_space=True)

    self.AssertErrContains(
        (r'{"version": "0.0.1", "verbosity": "ERROR", '
         '"timestamp": "2017-01-01T00:00:00.000Z", '
         '"message": "test exception - 8", "error": {"type": "ValueError", '
         '"details": "test exception - 8", "stacktrace": null}}'),
        normalize_space=True)

Please provide some troubleshoot suggestion. Thank you!

CPython versions tested on:

3.13

Operating systems tested on:

Linux

[ZeroIntensity]

What library are you using for testing? This doesn't look like unittest, so this might not be a CPython issue.

[catchyzheng]

What library are you using for testing? This doesn't look like unittest, so this might not be a CPython issue.

The test lib is googletest. I think the issue is about https://github.com/python/cpython/blob/3.12/Lib/datetime.py?

[ZeroIntensity]

Looks like you're doing something with gcloud_cli, which has its own testing system. I'm not too sure how to run their tests (or even setup the project, for that matter), but it seems to be something related to patching time.time().

I'm not too sure if this is an actual CPython issue, but I'll see if I can come up with a repro.

[ZeroIntensity]

Unable to reproduce this on 3.13b3, nor the CPython main branch. Here's my reproducer:

import datetime
import time
import unittest.mock

from dateutil import tz  # pip install python-dateutil

LOCAL = tz.tzlocal()
UTC = tz.tzutc()


# Found from the gcloud_cli repo
def GetTimeStampFromDateTime(dt, tzinfo=LOCAL):
    if not dt.tzinfo and tzinfo:
        dt = dt.replace(tzinfo=tzinfo)
    delta = dt - datetime.datetime.fromtimestamp(0, UTC)
    return delta.total_seconds()


log_date = datetime.datetime(2017, 1, 1, 0, 0)
log_time = GetTimeStampFromDateTime(log_date, tzinfo=UTC)
patch_obj = unittest.mock.patch.object(time, "time")
patcher = patch_obj.start()
patcher.return_value = log_time
assert time.time() == 1483228800.0  # If this fails, then this would be a bug

@catchyzheng does this script run without an AssertionError? If so, this is not a CPython issue.

[catchyzheng]

@ZeroIntensity Thank you for your help! Yes this script can pass. I will investigate further.
Can I keep this ticket open for some time? Wanna to see if someone else has other guidance.

[ZeroIntensity]

Could you rename the issue to be about the underlying problem? This is related to unittest.mock.patch failing on time.time, I don't think datetime has anything to do with it.

[serhiy-storchaka]

It may be related to the fact that logging now uses time.time_ns() instead of time.time().

[ZeroIntensity]

Yeah, that would be it. FWIW, this is not a logging issue then, simply a user-error.

[vsajip]

I'll close this now, as it's not a CPython issue, seemingly.