"IndexError: list index out of range" when accessing ignore_lists or freeze_factories from thread

[alex-kowalczyk]

When fake_time or similar patched thing is somehow passed (eg via queue) to some thread, it might be later called there. In the meanwhile the patching might have been removed (e.g main thread exited with freeze_time() block). This resuls in ignore_lists or freeze_factories being empty.

This bugs hits logging background transports heavily.

Quick and dirty solution would be to check for presence of the element [-1] before accessing it.

This results in an exception like these:

    self.run()
  File "/opt/python3.7/lib/python3.7/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/env/lib/python3.7/site-packages/google/cloud/logging/handlers/transports/background_thread.py", line 141, in _thread_main
    max_latency=self._max_latency,
  File "/env/lib/python3.7/site-packages/google/cloud/logging/handlers/transports/background_thread.py", line 67, in _get_many
    elapsed = time.time() - start
  File "/env/lib/python3.7/site-packages/freezegun/api.py", line 173, in fake_time
    if _should_use_real_time():
  File "/env/lib/python3.7/site-packages/freezegun/api.py", line 151, in _should_use_real_time
    if not ignore_lists[-1]:
IndexError: list index out of range" ```

Or: 
``` File "/usr/lib/python3.7/socketserver.py", line 650, in process_request_thread
    self.finish_request(request, client_address)
  File "/usr/lib/python3.7/socketserver.py", line 360, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/lib/python3.7/socketserver.py", line 720, in __init__
    self.handle()
  File "site-packages/django/core/servers/basehttp.py", line 155, in handle
    handler.run(self.server.get_app())
  File "/usr/lib/python3.7/wsgiref/handlers.py", line 148, in run
    self.close()
  File "/usr/lib/python3.7/wsgiref/simple_server.py", line 35, in close
    self.status.split(' ',1)[0], self.bytes_sent
  File "/usr/lib/python3.7/http/server.py", line 544, in log_request
    self.requestline, str(code), str(size))
  File "site-packages/django/core/servers/basehttp.py", line 99, in log_message
    'server_time': self.log_date_time_string(),
  File "/usr/lib/python3.7/http/server.py", line 594, in log_date_time_string
    now = time.time()
  File "site-packages/freezegun/api.py", line 175, in fake_time
    current_time = get_current_time()
  File "site-packages/freezegun/api.py", line 169, in get_current_time```

[spulec]

Can you confirm which version of freezegun you are using?

By default, moto should be not running when it sees threading in the stacktrace: https://github.com/spulec/freezegun/commit/270e3cae8216878d4c83d3d39001e37ff457649d

See https://github.com/spulec/freezegun/issues/307 for why that is also an issue.

[alex-kowalczyk]

0.3.12 , so it includes the commit. The issue is not with ignoring threading itself. The problem occurs when the thread still runs and uses time functions (eg time.time()) after the main thread has been unfrozen (exited with block). time.time() checks if it should be ignored while the ignore_lists is already removed.

[spulec]

Ah, I see.

If we just check for the presence of ignore_lists[-1] before accessing it, I believe the code will still break later on. We could return True is ignore_lists is empty. Is that the behavior we want though? As a user, would you expect this thread to be using the real time or the fake time at this point?

[alex-kowalczyk]

Ideally the threads spawned in frozen-time should be frozen, to make this predictable.

[lig]

Any workaround for this? It really hurts.

[deeTEEcee]

I hit the same issue and after upgrading to 1.1.0, it was fixed.

[PhilMarsh]

This is a simple multi-threading bug caused by not locking around accesses of the global freezegun.api.ignore_lists. For example:

• Thread 1 starts a frozen context, appending to the global freezegun.api.ignore_lists.
• Thread 2 asks for a time value, invoking _should_use_real_time() which first checks if ignore_lists is empty. It's not empty, so we continue.
• Thread 1 ends its frozen context, popping from ignore_lists.
• Thread 2, still in the middle of _should_use_real_time(), tries to use ignore_lists[-1]. ignore_lists is now empty, so an IndexError is raised.

It doesn't actually matter if we've correctly configured to ignore the affected module. The attempt to check for ignored modules is failing before we can make a decision.

---

One option is to add locking around the most of _should_use_real_time() and the .append() and .pop() calls. As long as we're only freezing time for testing purposes, any lock contention should be negligible.

Another option is to fix this locklessly with an EAFP approach. At the top of _should_use_real_time(), try to grab ignore_lists[-1]. If it raises and IndexError, then we're not in a frozen context, so return True. Else, hold onto the value we just got and use it for the rest of the function. This would look something like:

def _should_use_real_time():
    ...
    try:
        modules_to_ignore = ignore_lists[-1]
    except IndexError:
        # Means stop() has already been called, so we can now return the real time
        return True

    for ...:
        ...
        if ... module_name.startswith(modules_to_ignore):
            return True
    ...

This avoid a lock, but the modules_to_ignore value could become stale while using it. Again, this shouldn't be a big deal if we're only testing.

---

Also, this problem exists for all of the mutable globals: https://github.com/spulec/freezegun/blob/1af533984e118f5fe58d3264a52c904737df7d77/freezegun/api.py#L60-L63

Some of these look like they need a larger refactor to make threadsafe.