importlib: python -m test test_pkg fails semi-randomly #78381
Comments
|
vstinner@WIN C:\vstinner\python\master>python -X utf8 -m test -v test_pkg ======================================================================
ERROR: test_4 (test.test_pkg.TestPkg)
----------------------------------------------------------------------
Traceback (most recent call last):
File "C:\vstinner\python\master\lib\test\test_pkg.py", line 180, in test_4
self.run_code(s)
File "C:\vstinner\python\master\lib\test\test_pkg.py", line 69, in run_code
exec(textwrap.dedent(code), globals(), {"self": self})
File "<string>", line 2, in <module>
File "C:\Users\vstinner\AppData\Local\Temp\tmpgr2te1hp\t4.py", line 1, in <mod
ule>
RuntimeError: Shouldnt load t4.py
======================================================================
FAIL: test_7 (test.test_pkg.TestPkg)
----------------------------------------------------------------------
Traceback (most recent call last):
File "C:\vstinner\python\master\lib\test\test_pkg.py", line 260, in test_7
'__name__', '__package__', '__path__', '__spec__'])
AssertionError: Lists differ: ['__c[34 chars]__loader__', '__name__', '__package
__', '__spec__'] != ['__c[34 chars]__loader__', '__name__', '__package__', '__pa
th__', '__spec__'] First differing element 6: Second list contains 1 additional elements. ['__cached__', ---------------------------------------------------------------------- |
vstinner
added
OS-windows
3.7 (EOL)
|
I'm able to reproduce the bug on Linux as well. I able to reproduce the bug on 3.7 and master, but the bug seems random. Example on Linux with master: vstinner@apu$ ./python -X utf8 -m test test_pkg == Tests result: SUCCESS == 1 test OK. Total duration: 73 ms == Tests result: SUCCESS == 1 test OK. Total duration: 72 ms
Tests result: SUCCESS
vstinner@apu$ ./python -X utf8 -m test test_pkg
Run tests sequentially
0:00:00 load avg: 1.35 [1/1] test_pkg
test test_pkg failed -- Traceback (most recent call last):
File "/home/vstinner/prog/python/master/Lib/test/test_pkg.py", line 260, in test_7
'__name__', '__package__', '__path__', '__spec__'])
AssertionError: Lists differ: ['__c[34 chars]__loader__', '__name__', '__package__', '__spec__'] != ['__c[34 chars]__loader__', '__name__', '__package__', '__path__', '__spec__']First differing element 6: Second list contains 1 additional elements. ['__cached__', test_pkg failed == Tests result: FAILURE == 1 test failed: Total duration: 74 ms |
vstinner
changed the title
vstinner
changed the title
|
The test creates the following files: /tmp/tmpsobc8gzf/t7.py /tmp/tmpsobc8gzf contains t7.py file and t7/ subdirectory. The test pass when the directory is loaded: vstinner@apu$ ./python -m test test_pkg -m test_7 == Tests result: SUCCESS == 1 test OK. Total duration: 51 ms But fail when it gets the t7.py file: vstinner@apu$ ./python -m test test_pkg -m test_7
Run tests sequentially
0:00:00 load avg: 0.96 [1/1] test_pkg
MODULE <module 't7' from '/tmp/tmpqzs7ftzl/t7.py'>
test test_pkg failed -- Traceback (most recent call last):
File "/home/vstinner/prog/python/master/Lib/test/test_pkg.py", line 261, in test_7
'__name__', '__package__', '__path__', '__spec__'])
AssertionError: Lists differ: ['__c[34 chars]__loader__', '__name__', '__package__', '__spec__'] != ['__c[34 chars]__loader__', '__name__', '__package__', '__path__', '__spec__']First differing element 6: Second list contains 1 additional elements. ['__cached__', test_pkg failed == Tests result: FAILURE == 1 test failed: Total duration: 49 ms |
|
I'm also able to reproduce the bug on Python 3.6. Note: -X utf8 option is unrelated to this issue. |
|
Almost always fails 8/10 times. cpython git:(master) $ ./python -m unittest -v test.test_pkg ====================================================================== Traceback (most recent call last):
File "/home/cpython/Lib/test/test_pkg.py", line 180, in test_4
self.run_code(s)
File "/home/cpython/Lib/test/test_pkg.py", line 69, in run_code
exec(textwrap.dedent(code), globals(), {"self": self})
File "<string>", line 2, in <module>
File "/tmp/tmpfxqne6o1/t4.py", line 1, in <module>
RuntimeError: Shouldnt load t4.py====================================================================== Traceback (most recent call last):
File "/home/cpython/Lib/test/test_pkg.py", line 260, in test_7
'__name__', '__package__', '__path__', '__spec__'])
AssertionError: Lists differ: ['__c[34 chars]__loader__', '__name__', '__package__', '__spec__'] != ['__c[34 chars]__loader__', '__name__', '__package__', '__path__', '__spec__']First differing element 6: Second list contains 1 additional elements. ['__cached__', ---------------------------------------------------------------------- FAILED (failures=1, errors=1) |
|
I removed Windows experts from the nosy list, since the issue is related to importlib, no Windows. |
|
I can't reproduce with master on macOS. |
|
I've tried to repro this on Mac, Windows box and Windows VM - works fine for all cases. |
|
Recent failure on AMD64 Debian root 3.x: https://buildbot.python.org/all/#/builders/27/builds/1433 0:07:40 load avg: 2.19 [278/418/1] test_pkg failed -- running: test_tools (1 min 18 sec) ====================================================================== Traceback (most recent call last):
File "/root/buildarea/3.x.angelico-debian-amd64/build/Lib/test/test_pkg.py", line 180, in test_4
self.run_code(s)
File "/root/buildarea/3.x.angelico-debian-amd64/build/Lib/test/test_pkg.py", line 69, in run_code
exec(textwrap.dedent(code), globals(), {"self": self})
File "<string>", line 2, in <module>
File "/tmp/tmpblwoj1h4/t4.py", line 1, in <module>
RuntimeError: Shouldnt load t4.py====================================================================== Traceback (most recent call last):
File "/root/buildarea/3.x.angelico-debian-amd64/build/Lib/test/test_pkg.py", line 260, in test_7
'__name__', '__package__', '__path__', '__spec__'])
AssertionError: Lists differ: ['__c[34 chars]__loader__', '__name__', '__package__', '__spec__'] != ['__c[34 chars]__loader__', '__name__', '__package__', '__path__', '__spec__']First differing element 6: Second list contains 1 additional elements. ['__cached__', ---------------------------------------------------------------------- FAILED (failures=1, errors=1) |
|
Brett:
Vladimir Matveev:
Well, it's a race condition :-( It seems hard to reproduce, but it exists ;-) |
|
Failure on AMD64 Windows8.1 Non-Debug 3.x buildbot: https://buildbot.python.org/all/#/builders/12/builds/1223 ERROR: test_4 (test.test_pkg.TestPkg) |
|
Given that importlib is essentially just doing "listdir", it would be interesting to know how the following behaves in a tight loop on affected systems: The core assumption that test_pkg is indirectly making is that the directory listing in importlib will always list both entries created by the test suite without any special care being needed at the application level. |
|
I was able to reproduce the issue with Win 10, current cpython @master. I was able to track the issue to the teardown function of the TestCase line 57: support.modules_cleanup(*self.modules_before) Is it possible to manage the cleanup differently? |
|
Maybe I'm missing something, but who is racing whom in this case? All the examples people have shared are simply running the test module directly which means there's no parallelism in the execution of the test runner with other tests. Does unittest.main() randomize the order and it's a sequence issue more than a concurrency issue? For instance, Lorenz may have tracked this issue down to cleanup, but each of those test methods should have been run sequentially, meaning that the tearDown() method would have been called after every execution of a test with no concurrency going on. And the temp modules for the tests are put in a directory created using tempfile.mkdtemp() so that should prevent test methods stomping on each other. Perhaps we need to improve the failure messages at this point in the tests to get more clues as to the state of things when the failures occur? |
|
Since my buildbot has been infected with this bug, I took some time to hunt it out. It turns out that issue is caused by an internal import triggered by the open() function (at least on Windows). A recent change to the interpreter (commit 9e4994d) changed the order of internal imports wrt file encodings so the default encoding for text files triggers a walking of sys.path thus seeing an incomplete test tree. The reason being that the path for the test tree is added to sys.path prior to it being completely flushed out. In theory this should not be a problem due to mtimes, but it seems that the all the additions occur within the time resolution of the directory's mtime. A quick fix for how internal imports happen *now* is: @@ -81,7 +81,7 @@ class TestPkg(unittest.TestCase):
if contents is None:
os.mkdir(fullname)
else:
- f = open(fullname, "w")
+ f = open(fullname, "w", encoding="utf-8")
f.write(contents)
if contents and contents[-1] != '\n':
f.write('\n')however, to prevent further changes to internal imports cauing further problems, the following seems to be prudent: @@ -70,7 +70,6 @@ class TestPkg(unittest.TestCase): def mkhier(self, descr):
root = tempfile.mkdtemp()
- sys.path.insert(0, root)
if not os.path.isdir(root):
os.mkdir(root)
for name, contents in descr:
@@ -86,6 +85,7 @@ class TestPkg(unittest.TestCase):
if contents and contents[-1] != '\n':
f.write('\n')
f.close()
+ sys.path.insert(0, root)
self.root = root
# package name is the name of the first item
self.pkgname = descr[0][0] |
|
@jeremy: nice work Can someone explain why this issue only came up with parallel tests? |
|
My guess as to why we're only seeing this for parallel test cases is taht for sequential tests, the implicit import inside open() is unlikely to happen while test_pkg is running, whereas for parallel tests, test_pkg will run in a relatively pristine process, and hence be more likely to trigger the implicit import. |
|
I have the same issue on Debian 9: == CPython 3.8.0a0 (heads/master:874809e, Sep 6 2018, 23:31:00) [GCC 6.3.0 20170516] ====================================================================== Traceback (most recent call last):
File "/home/xxx/xxx/cpython/git/cpython/Lib/test/test_pkg.py", line 180, in test_4
self.run_code(s)
File "/home/xxx/xxx/cpython/git/cpython/Lib/test/test_pkg.py", line 69, in run_code
exec(textwrap.dedent(code), globals(), {"self": self})
File "<string>", line 2, in <module>
File "/tmp/tmppheh3y0k/t4.py", line 1, in <module>
RuntimeError: Shouldnt load t4.py====================================================================== Traceback (most recent call last):
File "/home/xxx/xxx/cpython/git/cpython/Lib/test/test_pkg.py", line 260, in test_7
'__name__', '__package__', '__path__', '__spec__'])
AssertionError: Lists differ: ['__c[34 chars]__loader__', '__name__', '__package__', '__spec__'] != ['__c[34 chars]__loader__', '__name__', '__package__', '__path__', '__spec__']First differing element 6: Second list contains 1 additional elements. ['__cached__', ---------------------------------------------------------------------- FAILED (failures=1, errors=1) == Tests result: FAILURE == 1 test failed: |
|
This is consistent for me, not random. run -m test.regrtest in -v mode and it passes. remove the -v and it fails. run Lib/test/test_pkg.py directly and it fails with the details mentioned here. this prevents CI builds from succeeding for me now. (confirmed on actual master at rev 9dfa0fe) |
|
confirmed that this is present in 3.7 rev 72c34cf as well. |
|
marking release blocker solely because this prevents CI runs from succeeding. I'm surprised how long this issue has been here though, i don't know what caused it to start happening consistently but as with many such heisenbugs changes at a distance could be related. :/ |
gpshead
changed the title
|
this also happens in 3.6. whatever the problem is, it has been around a long time. |
|
and I do agree that it is somewhat random. while i have some situations where I can reproduce this, i have others where I can rerun exactly the same binary and single process single thread process running just test_pkg.py and nothing else where the behavior differs between runs in terms of which of test_4 and test_7 fail or not. |
gpshead
changed the title
|
kinda poking at ideas here, but from a lunch conversation could this be related to the filesystem iteration order within the temp directories. assigned to me while i investigate possibilities. |
|
I can make the test reliable... but I wouldn't say I fully understand the ultimate cause of the problem. The reliability fix for test_pkg is to stop using test.support.modules_setup() and test.support.modules_cleanup() in the setUp() and tearDown() methods. these test support functions are semi scary. they attempt to backup and replace sys.modules contents with special case code in the cleanup function to try and avoid doing that to things that are still necessary. running python -vvv when I could get test_pkg to fail led me looking at code paths that were being executed mid-test that i'd expect to be executed only on process startup. locale.getpreferredencoding triggering a _bootlocale import, etc. I don't understand why it cause the problem though. PR to at least make the test reliable coming. |
|
Did you attempt to use the 3-line change I posted earlier? I stepped through to test line-by-line to find the offending piece of code. And it was indeed the open() call causing the test-tree to be processed prior to it being completed. Thus making the .py file seen before the directory of same name would exist. |
|
this is also present in 3.5, but it'll be up to the 3.5 release manager to cherry pick the test_pkg.py reliability fix into the 3.5 branch if it impacts them during the release process. |
|
I still feel like there is an underlying issue within the import system that use of test.support.modules_cleanup somehow triggers that I never managed to really understand. but the particular issue in this bug that people were seeing frequently is fixed. |
|
Thank you for the fix Gregory! |
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:
bugs.python.org fields:
The text was updated successfully, but these errors were encountered: