Issue 31070: test_threaded_import: KeyError ignored in _get_module_lock.<locals>.cb

See bpo-bpo-30891 and bpo-30876 for recent changes in importlib.

http://buildbot.python.org/all/builders/AMD64%20Windows8.1%20Refleaks%203.x/builds/57/steps/test/logs/stdio

1:33:30 [312/406/2] test_threaded_import passed (30 sec) -- running: test_decimal (826 sec), test_set (84 sec), test_mmap (1151 sec)
beginning 6 repetitions
123456
...Exception ignored in: <function _get_module_lock.<locals>.cb at 0x000000813CA18EB8>
Traceback (most recent call last):
  File "<frozen importlib._bootstrap>", line 176, in cb
KeyError: ('random',)
...

Oh, it's easy to reproduce the bug on the master branch. Example on Linux:

haypo@selma$ ./python -m test test_threaded_import
Run tests sequentially
0:00:00 load avg: 0.16 [1/1] test_threaded_import
Exception ignored in: <function _get_module_lock.<locals>.cb at 0x7f53201e2f70>
Traceback (most recent call last):
  File "<frozen importlib._bootstrap>", line 176, in cb
KeyError: ('random',)
1 test OK.

Total duration: 2 sec
Tests result: SUCCESS

The problem is the weakref callback of _module_locks. It seems like the callback is called after a second thread replaced _module_locks[name]

* Thread 1: _get_module_lock('random') sets _module_locks['random'] and registers a weakref callback on the newly created lock

* Thread 1: the lock is destroyed, the weakref callback will be called as soon as possible

* Thread 2: _get_module_lock('random') sees that the weakref is dead and so replaces _module_locks['random'] with a new lock, and registers a new weakref callback on the second lock

* Thread 1: Call the weakref callback removing _module_locks['random'] -- BUG: the callback is called too late, after Thread 2 already sets a new lock

* Thread 2: The lock is destroyed, the second weakref callback will be called as soon as possible

* Thread 2: The second callback is called and fails with KeyError since _module_locks['random'] was already called in the Thread 1 in the meanwhile

I wrote https://github.com/python/cpython/pull/3029 which seems to fix the issue.

I don't know importlib well enough to understand why we need a weak reference to a lock.

My PR adds a second lock per module lock (!) to be able to wait until _module_locks[name] is deleted when a thread detects that _module_locks[name] exists and the associated lock was destroyed.

I think the solution can be simpler. PR 3033 uses the global import lock for guarding modification of the _module_locks dictionary.

Serhiy: "I think the solution can be simpler. PR 3033 uses the global import lock for guarding modification of the _module_locks dictionary."

I tried exactly that, but it wasn't enough. But your PR is correct because it also checks the current value of _module_locks[name] using the callback parameter.

I disliked my own PR, so I'm happy that someone else wrote a simpler fix! (I already abandonned my PR.)

New changeset 9b0d1d647e3d2ec9d299e5c9f49b02fbbb810a5a by Serhiy Storchaka in branch 'master':
bpo-31070: Fix a race condition in importlib _get_module_lock(). (#3033)
https://github.com/python/cpython/commit/9b0d1d647e3d2ec9d299e5c9f49b02fbbb810a5a

New changeset f3b891718e104b6e7018b58bbcd86421a2837fb8 by Serhiy Storchaka in branch '3.6':
[3.6] bpo-31070: Fix a race condition in importlib _get_module_lock(). (GH-3033). (#3038)
https://github.com/python/cpython/commit/f3b891718e104b6e7018b58bbcd86421a2837fb8

Thank you for review Victor and Nick.

I'm curious to know if this issue is a regression caused by recent changes: bpo-30891 and bpo-30876. But well, it doesn't matter as soon as it's fixed :-)

I don't think the changes created the bug, but I do think the new tests to provoke the other race conditions made it easier for the test suite to hit this race as well.

>  I don't think the changes created the bug, but I do think the new tests to provoke the other race conditions made it easier for the test suite to hit this race as well.

Oh ok, that's a good news!

A recent numpy threaded import bug report that appears in 3.6.1 but is absent in 3.6.3: https://github.com/numpy/numpy/issues/9931

So that's additional evidence that this really was a pre-existing race condition that the new tests for the SystemError cases revealed.

stage: patch review -> resolved

components: + Interpreter Core, - Tests
type: behavior
stage: patch review