importlib: _find_and_load() race condition on sys.modules[name] check

[vstinner]

BPO	30891
Nosy	@gvanrossum, @Yhg1s, @warsaw, @brettcannon, @pfmoore, @ncoghlan, @vstinner, @tjguk, @ambv, @ericsnowcurrently, @zware, @serhiy-storchaka, @zooba
PRs	[3.5] bpo-30814: Add a test for concurrent relative import. (GH-2580). #2645 bpo-30891: Fix importlib _find_and_load() race condition #2646 [3.6] bpo-30891: Fix importlib _find_and_load() race condition (#2646) #2651 bpo-30891: importlib _find_and_load() try/except #2665 [3.6] bpo-30891: Fix again importlib _find_and_load() (#2665) #2801
Files	importlib_sleep.patch

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2017-07-27.10:25:47.039>
created_at = <Date 2017-07-10.09:44:24.364>
labels = ['3.7', 'type-bug', 'tests', 'OS-windows']
title = 'importlib: _find_and_load() race condition on sys.modules[name] check'
updated_at = <Date 2018-04-04.19:19:31.431>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2018-04-04.19:19:31.431>
actor = 'gvanrossum'
assignee = 'none'
closed = True
closed_date = <Date 2017-07-27.10:25:47.039>
closer = 'vstinner'
components = ['Tests', 'Windows']
creation = <Date 2017-07-10.09:44:24.364>
creator = 'vstinner'
dependencies = []
files = ['47000']
hgrepos = []
issue_num = 30891
keywords = ['patch']
message_count = 35.0
messages = ['298044', '298046', '298047', '298048', '298049', '298053', '298058', '298063', '298064', '298066', '298067', '298068', '298069', '298070', '298071', '298072', '298081', '298087', '298088', '298798', '298801', '299184', '299305', '302106', '302124', '314594', '314615', '314818', '314819', '314879', '314887', '314889', '314894', '314948', '314949']
nosy_count = 13.0
nosy_names = ['gvanrossum', 'twouters', 'barry', 'brett.cannon', 'paul.moore', 'ncoghlan', 'vstinner', 'tim.golden', 'lukasz.langa', 'eric.snow', 'zach.ware', 'serhiy.storchaka', 'steve.dower']
pr_nums = ['2645', '2646', '2651', '2665', '2801']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue30891'
versions = ['Python 3.6', 'Python 3.7']

[vstinner]

1:36:32 [224/405/1] test_import failed -- running: test_mmap (2236 sec), test_io (2529 sec), test_venv (1437 sec)
beginning 6 repetitions
123456
.....test test_import failed -- Traceback (most recent call last):
  File "D:\buildarea\3.6.ware-win81-release.refleak\build\lib\test\test_import\__init__.py", line 377, in test_concurrency
    raise exc
  File "D:\buildarea\3.6.ware-win81-release.refleak\build\lib\test\test_import\__init__.py", line 362, in run
    import package
  File "D:\buildarea\3.6.ware-win81-release.refleak\build\lib\test\test_import\data\package\__init__.py", line 2, in <module>
    package.submodule
AttributeError: module 'package' has no attribute 'submodule'

[vstinner]

I was able to *easily* (100% failure rate) reproduce the failure with Python 3.6 and 3.7 (master) on Windows using this command:

./python -m test -R 3:100 -m test_concurrency test_import

[vstinner]

I don't understand if a test_concurrency() failure is a bug in importlib, or a bug in the test :-)

[vstinner]

Note: "./python -m test -R 3:100 -m test_concurrency test_import" is just a convenient way to run test_concurrency() "in a loop", in the same process, 100 times.

I'm unable to reproduce the bug on Linux, even when I write 3 into /proc/sys/vm/drop_caches while the test is running to drop filesystem caches.

I also tried to use a temporary directory in my home (TMPDIR=$HOME/tmp) to use temporary files in ext4 rather than tmpfs. But I don't know if importlib uses temporary files or not :-)

[vstinner]

Oh, the unit test was added 4 days ago:

commit b4baace
Author: Serhiy Storchaka <storchaka@gmail.com>
Date: Thu Jul 6 08:09:03 2017 +0300

bpo-30814: Fixed a race condition when import a submodule from a package. (bpo-2580)

[ncoghlan]

Indeed, Serhiy's been stress-testing some bits of the import system, and finding a few holes made possible by the shift away from a single global import lock to per-module locks. (bpo-30876 is another example of that)

Nothing immediately comes to mind as a platform-dependent code path that could explain why that error is showing up on Windows and not on Linux, though.

[serhiy-storchaka]

Some parts of import machinery are platform depended (see bpo-30873).

I don't have idea what is wrong on Windows.

I'm puzzled. test_concurrency itself runs a test in a loop. The only difference between one and several consequent runs of test_concurrency is running setUp() and tearDown() between tests. Victor, try to add importlib.invalidate_caches() inside a loop. Does it cause a failure in a single test_concurrency?

[vstinner]

Victor, try to add importlib.invalidate_caches() inside a loop. Does it cause a failure in a single test_concurrency?

I added a "importlib.invalidate_caches()" call in the "for i in range(10):" loop. With this change, a single run doesn't fail. It doesn't fix the test neither: with -R 3:100, the command still fails.

Some parts of import machinery are platform depended (see bpo-30873).

I don't think that this bpo-30873 or bpo-30626 is platform dependent.

I don't have idea what is wrong on Windows.

IMHO it's just that my Windows VM is slow. It's a race condition. If I run "./python -m test -m test_concurrency test_import test_import": the command pass, but when again, it fails. It's pure random :-)

[vstinner]

I added print(id(package)) in Lib/test/test_import/data/package/init.py: when the bug occurs on my Windows VM, I see two print with two different identifiers. Moreover, when the bug occurs, first id(sys.modules['package']) is the first identifier, and then package is replaced with the new 'package' package in sys.modules (new identifier).

I don't understand something: sys.modules isn't supposed to be protected by a lock? I checked if _installed_safely.__enter__() if the _imp is held: it isn't held when _bootstrap._setup() is called, nor when _imp._install_external_importers() is called. But even if I patch these two functions to acquire the lock, Python startup fails on importing a codec module, because the _imp lock is not held in _installed_safely.__enter__(). So maybe sys.modules dict is supposed to be protected by a different lock, maybe indirectly?

I hack _bootstrap._find_and_load_unlocked() to sleep 10 ms if name == 'package'. With this change, test_concurrency() fails immediatly on my Linux box.

• Apply attached importlib_sleep.patch (written for the current master branch)
• Recompile: make regen-importlib && make
• Run test_concurrency() just once: ./python -m test -m test_concurrency -v test_import
• You get the bug

By the way, importlib_sleep.patch changes test_concurrency() to run the test exactly once (it changes to loop to a single iteration, instead of 10).

Is it normal that a sleep makes import failing? Imports are not supposed to be atomic?

--

I tried to similar hack before the commit b4baace:

• add a sleep in importlib
• copy test_concurrency() from master
• Run test_concurrency()
• The test pass

While I'm not sure of my hack, it *seems* like sys.modules was somehow atomic before this commit?

[vstinner]

FYI test_concurrency() added by commit b4baace doesn't really test bpo-30814. I backported the unit test on 1ccbad9 (commit before b4baace), and the test pass, whereas I expected it to fail before the fix.

[ncoghlan]

No, there's no global lock on the import system these days.

Instead, imports are supposed to be atomic on a per-module basis, but bpo-30814 showed that some of the accesses to the shared state management (which *is* still supposed to be protected by the import lock) could get into trouble given concurrent imports from different threads.

However, the new test exercises an interesting sequence of per-module lock acquisition, since each thread effectively runs through this sequence:

• import package # Test case
• import package.submodule # Package init
• import package # Parent package import

That moves back-and-forth between C & Python in a few different places, and hence may have been relying on the GIL to keep the parts executed in C atomic.

So now I'm wondering whether or not this new problem might be due to moving the _imp.acquire_lock() calls into Python code as part of bpo-30814, as that creates a window near the start of _find_and_load() where the thread may end up holding neither the GIL *nor* the import lock. By contrast, when the import lock was acquired in C, then by the time the Python code starts running (potentially releasing the GIL), the import lock has already been acquired.