classification
Title: Import dotted name as alias breaks with concurrency
Type: behavior Stage: resolved
Components: Interpreter Core Versions: Python 3.7, Python 3.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: serhiy.storchaka Nosy List: RazerM, SamueleSanti, brett.cannon, eric.snow, ncoghlan, ned.deily, serhiy.storchaka, vstinner
Priority: high Keywords: 3.6regression

Created on 2017-06-30 11:09 by SamueleSanti, last changed 2017-07-27 10:19 by serhiy.storchaka. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 2580 merged serhiy.storchaka, 2017-07-05 06:24
PR 2598 merged serhiy.storchaka, 2017-07-06 05:26
PR 2645 closed serhiy.storchaka, 2017-07-10 14:21
PR 2665 merged vstinner, 2017-07-21 10:49
PR 2851 merged serhiy.storchaka, 2017-07-24 18:20
PR 2912 merged serhiy.storchaka, 2017-07-27 09:43
Messages (18)
msg297380 - (view) Author: Samuele Santi (SamueleSanti) Date: 2017-06-30 11:09
I noticed this weird behavior in Python 3.6:

Apparently ``import package.module as _alias`` fails in a threaded environment, sometimes raising an ``ImportError``, seemingly at random.

Everything seems to be working perfectly fine:

- On 3.5 and lower
- When *not* defining an alias, eg. ``import package.module``
- When using the ``from package import module as alias`` style


See this repo with code for reproducing the issue:

https://github.com/rshk/python36-import-alias-concurrency-bug


I tested this on the system Python 3.6.1 shipped with Archlinux (both inside and outside of a virtualenv), and in the official docker image for 3.6.

This all started here https://github.com/psycopg/psycopg2/issues/550 as others were experiencing this issue too.
msg297475 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-07-01 06:07
See also issue23203.

This was fixed in master in issue30024. Maybe it is worth to backport that change to maintained versions?
msg297482 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-07-01 16:38
On other side, issue23203 fixed just a symptom. The issue is reproduced in master when replace "import foobar.submodule as foo" with "import foobar.submodule; foo = foobar.submodule".

The regression may be related to issue22557. Either the optimization introduced a bug, or it exposed an existing bug by changing timings.
msg297679 - (view) Author: Brett Cannon (brett.cannon) * (Python committer) Date: 2017-07-04 17:00
My guess is the import of package has completed but package.submodule hasn't (I don't know what state it would be in, but obviously before the module is assigned as an attribute on the package), a context switch occurs, and then the assignment fails due to package.submodule not being set on package yet.

I wonder if package.submodule is in sys.modules when the AttributeError is triggered? I don't remember when the assignment of a submodule to an attriute on a package occurs, but this suggests it's rather late and that's why this is failing. Maybe the assignment is outside of the per-module lock being released and that is what's causing this?

Hey, at least importing in a thread doesn't deadlock anymore like it used to. ;)
msg297698 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2017-07-05 04:41
Documenting explicitly what I believe the expected order of module lock acquisition would be in this case:

    Thread A acquires package.subpackage lock
    Thread B blocks on package.subpackage lock
    Thread A acquires package lock
    Thread A releases package lock
    Thread A releases package.subpackage lock
    Thread B acquires & immediately releases package.subpackage lock

Looking at https://hg.python.org/cpython/rev/64f195790a3a#l4.367 (the commit for issue 22557), there's a potentially suspect change in the scope of a "_PyImport_AcquireLock/_PyImport_ReleaseLock" pair inside PyImport_ImportModuleLevelObject

Specifically, I think we may now have a race condition at https://github.com/python/cpython/blob/master/Python/import.c#L1534, where two threads can *both* end up trying to initialize the same module, since we're no longer holding the global import lock around that "mod = PyDict_GetItem(interp->modules, abs_name);" call and the associated state updates where the first thread indicates that it is already initializing that module so the second thread should just wait for it to finish doing so.
msg297704 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-07-05 06:28
I have came to the same conclusion.

PR 2580 adds a double check in _bootstrap._find_and_load() (and also moves the locking into it). It also simplifies the C code by removing the fast path for the case sys.module[name] is None.
msg297803 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-07-06 05:09
New changeset b4baacee1adc06edbe30ac7574d17a8cd168e2e0 by Serhiy Storchaka in branch 'master':
bpo-30814: Fixed a race condition when import a submodule from a package. (#2580)
https://github.com/python/cpython/commit/b4baacee1adc06edbe30ac7574d17a8cd168e2e0
msg297806 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-07-06 05:38
New changeset 03b0e8374b2ea93adf8fb6a48db2916f3b0388cc by Serhiy Storchaka in branch '3.6':
[3.6] bpo-30814: Fixed a race condition when import a submodule from a package. (GH-2580). (#2598)
https://github.com/python/cpython/commit/03b0e8374b2ea93adf8fb6a48db2916f3b0388cc
msg297966 - (view) Author: Brett Cannon (brett.cannon) * (Python committer) Date: 2017-07-08 18:39
I just wanted to say thanks to everyone who helped to fix this bug. The locking situation in import is probably the trickiest part of it and has also been tweaked the most as of late and so solving these kinds of issues is tricky.
msg298050 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-07-10 10:05
test_concurrency() of test_import fails randomly on Windows: see bpo-30891.
msg298065 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-07-10 14:23
It is worth to backport the test to older versions. Just to be sure that this is a 3.6 regression.
msg298951 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2017-07-24 10:25
When running tests from installed location, test_import now fails on master and 3.6 with:

======================================================================
ERROR: test_concurrency (test.test_import.ImportTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/nad/Projects/PyDev/active/dev/3x/root/uxd/lib/python3.7/test/test_import/__init__.py", line 408, in test_concurrency
    raise exc
  File "/Users/nad/Projects/PyDev/active/dev/3x/root/uxd/lib/python3.7/test/test_import/__init__.py", line 393, in run
    import package
ModuleNotFoundError: No module named 'package'
msg298958 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-07-24 11:07
> When running tests from installed location, test_import now fails on master and 3.6 with:

Which Git revisions are you testing? On master, do you have my latest commit e72b1359f81d1dd42bd8a5c5cc2b3928b74f8023 ?
msg299005 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2017-07-24 17:50
> Which Git revisions are you testing? On master, do you have my latest commit e72b1359f81d1dd42bd8a5c5cc2b3928b74f8023 ?

Yes, this is with current top of trunk of both branches.  Perhaps I wasn't clear about "installed location".  The test does not fail if you run it directly from the build directory like with "make test".  It fails when you do a "make install" and then run the test using the newly installed Python.  Tests need to work both ways.
msg299018 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-07-24 21:13
Serhiy on PR 2851:
> I forget to include directories with new test files in the list of the library directories. This caused that these test files were not installed.

Oh, too bad that Zach's "x86 Gentoo Installed with X 3.6" buildbot is offline.
msg299019 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2017-07-24 21:15
I also opened https://github.com/python/devguide/issues/241 : "Document how to add a new file or a new directory". It's not the first time that we make such mistake.
msg299296 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-07-27 09:24
New changeset d5ed47dea25e04a3a144eddf99a4ac4a29242dbc by Serhiy Storchaka in branch 'master':
bpo-30814, bpo-30876: Add new import test files to projects. (#2851)
https://github.com/python/cpython/commit/d5ed47dea25e04a3a144eddf99a4ac4a29242dbc
msg299302 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2017-07-27 10:16
New changeset 95b16a9705d6b4d31c016c014e59744fc33d53ea by Serhiy Storchaka in branch '3.6':
[3.6] bpo-30814, bpo-30876: Add new import test files to projects. (GH-2851). (#2912)
https://github.com/python/cpython/commit/95b16a9705d6b4d31c016c014e59744fc33d53ea
History
Date User Action Args
2017-07-27 10:19:01serhiy.storchakasetstatus: open -> closed
resolution: fixed
2017-07-27 10:16:03serhiy.storchakasetmessages: + msg299302
2017-07-27 09:43:07serhiy.storchakasetpull_requests: + pull_request2963
2017-07-27 09:24:39serhiy.storchakasetmessages: + msg299296
2017-07-24 21:15:54vstinnersetmessages: + msg299019
2017-07-24 21:13:33vstinnersetmessages: + msg299018
2017-07-24 18:20:45serhiy.storchakasetpull_requests: + pull_request2900
2017-07-24 17:50:59ned.deilysetmessages: + msg299005
2017-07-24 11:07:37vstinnersetmessages: + msg298958
2017-07-24 10:25:07ned.deilysetnosy: + ned.deily
messages: + msg298951
2017-07-21 10:49:13vstinnersetpull_requests: + pull_request2851
2017-07-10 14:23:52serhiy.storchakasetmessages: + msg298065
2017-07-10 14:21:50serhiy.storchakasetpull_requests: + pull_request2710
2017-07-10 10:05:38vstinnersetstatus: closed -> open

nosy: + vstinner
messages: + msg298050

resolution: fixed -> (no value)
2017-07-08 18:39:45brett.cannonsetmessages: + msg297966
2017-07-07 18:04:46serhiy.storchakasetstatus: open -> closed
resolution: fixed
stage: patch review -> resolved
2017-07-06 05:38:27serhiy.storchakasetmessages: + msg297806
2017-07-06 05:26:51serhiy.storchakasetpull_requests: + pull_request2666
2017-07-06 05:09:05serhiy.storchakasetmessages: + msg297803
2017-07-05 06:28:15serhiy.storchakasetmessages: + msg297704
stage: patch review
2017-07-05 06:24:05serhiy.storchakasetpull_requests: + pull_request2650
2017-07-05 04:41:27ncoghlansetmessages: + msg297698
2017-07-04 19:03:15pitrousetpriority: normal -> high
2017-07-04 17:00:59brett.cannonsetmessages: + msg297679
2017-07-01 16:39:42serhiy.storchakasetkeywords: + 3.6regression
assignee: serhiy.storchaka
versions: + Python 3.7
2017-07-01 16:38:52serhiy.storchakasetmessages: + msg297482
2017-07-01 06:07:55serhiy.storchakasetmessages: + msg297475
2017-06-30 19:13:18serhiy.storchakasetnosy: + brett.cannon, ncoghlan, eric.snow, serhiy.storchaka
type: behavior
components: + Interpreter Core
2017-06-30 12:37:39RazerMsetnosy: + RazerM
2017-06-30 11:09:48SamueleSanticreate