ignore doesn't seem to work in more complicated setup (Django + S3 / boto)

[radoh]

I am using Django with S3 as the file storage (which uses boto3/botocore libs). I have a "management" command which creates some Django instances - I use freezegun, so these instances appear to be created in the past. However some of these models contain files, that are being saved to S3 - which raises some exceptions:

...
  File "/home/rado/.virtualenvs/twisto/lib/python3.6/site-packages/botocore/client.py", line 314, in _api_call
    return self._make_api_call(operation_name, kwargs)
  File "/home/rado/.virtualenvs/twisto/lib/python3.6/site-packages/botocore/client.py", line 612, in _make_api_call
    raise error_class(parsed_response, operation_name)
botocore.exceptions.ClientError: An error occurred (RequestTimeTooSkewed) when calling the ListObjectsV2 operation: The difference between the request time and the current time is too large.

this is due to some authentication code in botocore.auth module, that checks for time differences. I tried to solve this issue using ignore parameter (freeze_time(datetime_in_past, ignore=['botocore'])), but it didn't help, botocore.auth still used the FakeDatetime (I used debugger with breakpoints to pinpoint the issue).

I tried to recreate the issue with a simple reproducible example, so I came up with following:

# test.py
from freezegun import freeze_time
from datetime import datetime
import stuff_in_between

import test_time #  <-- note this unused import

with freeze_time(datetime(2019, 1, 1, 1, 1, 1, 1), ignore=['test_time']):
    print(f'frozen time: {datetime.now()}')
    stuff_in_between.call_test_time()

# stuff_in_between.py
def call_test_time():
    import test_time
    test_time.test_time()

# test_time.py
from datetime import datetime

def test_time():
    print(f'real datetime.now: {datetime.now()}')

This code correctly works, freeze_time ignore test_time and it prints real datetime.now: <real time>. However if I omit the marked unused import in test.py, it doesn't work - freeze_time doesn't ignore the module and the script prints out real datetime.now: <fake time>.

I thought I could try out something similar in my real Django go, so I did following:

...
import botocore
import botocore.auth
# hell, try to import everything possible related to S3
with freeze_time(datetime_in_past, ignore=['botocore']:
   ...
   # create some instances, that also save files to S3

This hasn't worked no matter what I imported or ignored, botocore.auth still continued to use FakeDatetime...
Is there a bug in freeze_time? Or am I misusing the library in some way? Why does it behave like this?

[boxed]

How deep is the call stack? Freezegun only looks 5 levels deep by default. You can change this with call_stack_inspection_limit

[radoh]

It's pretty deep from what I've observed, around 35 levels. I've set call_stack_inspection_limit to 100, but it didn't help 🙁
I've added some breakpoints and discovered that e.g. this line - https://github.com/boto/botocore/blob/556aaa205aa577fa58c298c6a042f735111de9ac/botocore/auth.py#L358 - calls FakeDatetime.utcnow() directly, so it doesn't use the _should_use_real_time() function (and therefore call_stack_inspection_limit doesn't seem help here)

For reference, I'm posting the call stack here:

__call__, freezegun.api.py:456
get_current_time, freezegun.api.py:178
_time_to_freeze, freezegun.api.py:370
utcnow, freezegun.api.py:364
add_auth, botocore.auth.py:353
add_auth, botocore.auth.py:420
sign, botocore.signers.py:156
handler, botocore.signers.py:90
_emit, botocore.hooks.py:210
emit, botocore.hooks.py:227
create_request, botocore.endpoint.py:157
_send_request, botocore.endpoint.py:173
make_request, botocore.endpoint.py:148
_make_api_call, botocore.client.py:599
_api_call, botocore.client.py:314
meta, django_s3_storage.storage.py:356
_do_wrap_errors, django_s3_storage.storage.py:45
exists, django_s3_storage.storage.py:375
get_available_name, django.core.files.storage.py:77
get_available_name, django_s3_storage.storage.py:347
do_wrap_path_impl, django_s3_storage.storage.py:73
save, django.core.files.storage.py:53
save, django.db.models.fields.files.py:94
pre_save, django.db.models.fields.files.py:296
pre_save_val, compiler.py:1013
<listcomp>, compiler.py:1063
<listcomp>, compiler.py:1064
as_sql, compiler.py:1064
execute_sql, compiler.py:1111
_insert, query.py:1079
manager_method, manager.py:85
_do_insert, base.py:963
_save_table, base.py:924
save_base, base.py:838
save, base.py:808
create, query.py:394
manager_method, manager.py:85
my_method_saving_django_models, my_management_command.py:108
...
execute, __init__.py:356
execute_from_command_line, __init__.py:364
<module>, manage.py:10

[lolobosse]

I can confirm the issue, call_stack_inspection_limit doesn't change anything because the function _should_use_real_time is not called:

Botocore calls utcnow directly which doesn't call _should_use_real_time:

@classmethod
def utcnow(cls):
        result = cls._time_to_freeze() or real_datetime.utcnow()
        return datetime_to_fakedatetime(result)

That's at least my understanding of the problem.

Did you find a solution @radoh ?

[lolobosse]

So for the people you might run into the issue:

It works if you change the utcnow method as follows:

@classmethod
def utcnow(cls):
        if _should_use_real_time():
            result = real_datetime.utcnow()
        else:
            result = cls._time_to_freeze() or real_datetime.utcnow()
        return datetime_to_fakedatetime(result)

However, this really hacky and I suppose that there is a bug somewhere in freezegun but I have no clear understanding of what's going on under the hood...

[adrianrego]

I believe we've run into a similar issue with urllib3 since a recent change:

urllib3/urllib3@3f21165#diff-542c95910a277028550d2c8943e8c49bbcb10f9af96e35d0a0eee99b8cfe9e8c

Since then our tests have been printing SystemTimeWarnings and adding both requests and urllib3 to the ignore list doesn't have an effect.

[MythicManiac]

Also ran into this issue, specifically getting

botocore.exceptions.ClientError: An error occurred (RequestTimeTooSkewed) when calling the PutObject operation: The diff
erence between the request time and the server's time is too large.

when writing tests that also happen to use s3 based storage. Adding the related packages to the ignore list doesn't seem to have any effect.

[eht16]

@MythicManiac you noticed #391 and #430?

[MythicManiac]

Ah, I didn't, but good to know 👍 just worked around it a bit differently in our case.

[stickperson]

Any update on this issue? It would be nice to know why FakeDatetime.utcnow() does not call _should_use_real_time. Is it simply an oversight and a PR with the fix would be welcome? Or is there a reason it was not implemented this way and we should look for alternative solutions?

[nullie]

The cause of the bug: freezgun unconditionally patches datetime module.

The ignore mechanism is only working on the part which traverses import modules and patches functions and classes which were already imported from datetime module, e.g. from datetime import datetime.

botocore uses datetime like this: import datetime ... datetime.datetime.now(), so ignore mechanism does not affect this.

One solution to this is to check stack at every call of fake datetime as proposed earlier, but is computationally more expensive (I'm not sure how this affects use cases, maybe this can be an option alongside ignore list)

[boxed]

You probably want to migrate to time-machine. It is well maintained and by its different design does not have this issue.

[nullie]

I didn't find any ignore facilities in neither time-machine nor libfaketime