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:                                                      
'__spec__'                                                                      
'__path__'                                                                      

Second list contains 1 additional elements.                                     
First extra element 7:                                                          
'__spec__'                                                                      

  ['__cached__',                                                                
   '__doc__',                                                                   
   '__file__',                                                                  
   '__loader__',                                                                
   '__name__',                                                                  
   '__package__',                                                               
+  '__path__',                                                                  
   '__spec__']                                                                  

----------------------------------------------------------------------

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 
Run tests sequentially
0:00:00 load avg: 1.30 [1/1] test_pkg

== Tests result: SUCCESS ==

1 test OK.

Total duration: 73 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

== 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:
'__spec__'
'__path__'

Second list contains 1 additional elements.
First extra element 7:
'__spec__'

  ['__cached__',
   '__doc__',
   '__file__',
   '__loader__',
   '__name__',
   '__package__',
+  '__path__',
   '__spec__']

test_pkg failed

== Tests result: FAILURE ==

1 test failed:
    test_pkg

Total duration: 74 ms
Tests result: FAILURE

The test creates the following files:

/tmp/tmpsobc8gzf/t7.py
/tmp/tmpsobc8gzf/t7
/tmp/tmpsobc8gzf/t7/__init__.py
/tmp/tmpsobc8gzf/t7/sub.py
/tmp/tmpsobc8gzf/t7/sub
/tmp/tmpsobc8gzf/t7/sub/__init__.py
/tmp/tmpsobc8gzf/t7/sub/.py
/tmp/tmpsobc8gzf/t7/sub/subsub
/tmp/tmpsobc8gzf/t7/sub/subsub/__init__.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
Run tests sequentially
0:00:00 load avg: 0.96 [1/1] test_pkg
MODULE <module 't7' from '/tmp/tmp4f6zuep7/t7/__init__.py'>

== Tests result: SUCCESS ==

1 test OK.

Total duration: 51 ms
Tests result: SUCCESS


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:
'__spec__'
'__path__'

Second list contains 1 additional elements.
First extra element 7:
'__spec__'

  ['__cached__',
   '__doc__',
   '__file__',
   '__loader__',
   '__name__',
   '__package__',
+  '__path__',
   '__spec__']

test_pkg failed

== Tests result: FAILURE ==

1 test failed:
    test_pkg

Total duration: 49 ms
Tests result: FAILURE

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
test_1 (test.test_pkg.TestPkg) ... ok
test_2 (test.test_pkg.TestPkg) ... ok
test_3 (test.test_pkg.TestPkg) ... ok
test_4 (test.test_pkg.TestPkg) ... ERROR
test_5 (test.test_pkg.TestPkg) ... ok
test_6 (test.test_pkg.TestPkg) ... ok
test_7 (test.test_pkg.TestPkg) ... FAIL
test_8 (test.test_pkg.TestPkg) ... ok

======================================================================
ERROR: test_4 (test.test_pkg.TestPkg)
----------------------------------------------------------------------
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

======================================================================
FAIL: test_7 (test.test_pkg.TestPkg)
----------------------------------------------------------------------
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:
'__spec__'
'__path__'

Second list contains 1 additional elements.
First extra element 7:
'__spec__'

  ['__cached__',
   '__doc__',
   '__file__',
   '__loader__',
   '__name__',
   '__package__',
+  '__path__',
   '__spec__']

----------------------------------------------------------------------
Ran 8 tests in 0.040s

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)
test_1 (test.test_pkg.TestPkg) ... ok
test_2 (test.test_pkg.TestPkg) ... ok
test_3 (test.test_pkg.TestPkg) ... ok
test_4 (test.test_pkg.TestPkg) ... ERROR
test_5 (test.test_pkg.TestPkg) ... ok
test_6 (test.test_pkg.TestPkg) ... ok
test_7 (test.test_pkg.TestPkg) ... FAIL
test_8 (test.test_pkg.TestPkg) ... ok

======================================================================
ERROR: test_4 (test.test_pkg.TestPkg)
----------------------------------------------------------------------
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

======================================================================
FAIL: test_7 (test.test_pkg.TestPkg)
----------------------------------------------------------------------
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:
'__spec__'
'__path__'

Second list contains 1 additional elements.
First extra element 7:
'__spec__'

  ['__cached__',
   '__doc__',
   '__file__',
   '__loader__',
   '__name__',
   '__package__',
+  '__path__',
   '__spec__']

----------------------------------------------------------------------
Ran 8 tests in 0.038s

FAILED (failures=1, errors=1)

Brett:
> I can't reproduce with master on macOS.

Vladimir Matveev:
> I've tried to repro this on Mac, Windows box and Windows VM - works fine for all cases.

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)
FAIL: test_7 (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:
    
    # Write a file
    f = open(os.path.join(dirname, "testname.py"), "w")
    f.write("text\n")
    f.close()
    # Make a directory
    os.mkdir(os.path.join(dirname, "testname"))
    # List the directory
    os.listdir(dirname)

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.
All sequential test runs are good.
With parallel execution a race condition comes up, as Victor already mentioned.

I was able to track the issue to the teardown function of the TestCase
In parallel the cleanup of the modules crashed the other tests.

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
The fix works for me reproducable, tests run normal now.
Why dont you create a PR?

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]
== Linux-4.9.0-6-amd64-x86_64-with-glibc2.17 little-endian
== cwd: /home/xxx/xxx/cpython/git/cpython/build/test_python_55266
== CPU count: 4
== encodings: locale=UTF-8, FS=utf-8
Using random seed 1679661
Run tests in parallel using 6 child processes
0:00:00 load avg: 0.35 [1/1/1] test_pkg failed
test_1 (test.test_pkg.TestPkg) ... ok
test_2 (test.test_pkg.TestPkg) ... ok
test_3 (test.test_pkg.TestPkg) ... ok
test_4 (test.test_pkg.TestPkg) ... ERROR
test_5 (test.test_pkg.TestPkg) ... ok
test_6 (test.test_pkg.TestPkg) ... ok
test_7 (test.test_pkg.TestPkg) ... FAIL
test_8 (test.test_pkg.TestPkg) ... ok

======================================================================
ERROR: test_4 (test.test_pkg.TestPkg)
----------------------------------------------------------------------
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

======================================================================
FAIL: test_7 (test.test_pkg.TestPkg)
----------------------------------------------------------------------
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:
'__spec__'
'__path__'

Second list contains 1 additional elements.
First extra element 7:
'__spec__'

  ['__cached__',
   '__doc__',
   '__file__',
   '__loader__',
   '__name__',
   '__package__',
+  '__path__',
   '__spec__']

----------------------------------------------------------------------
Ran 8 tests in 0.028s

FAILED (failures=1, errors=1)
test test_pkg failed

== Tests result: FAILURE ==

1 test failed:
    test_pkg

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 9dfa0fe587)

confirmed that this is present in 3.7 rev 72c34cf6dd 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. :/

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.

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.

New changeset 4ae8ece5cd4c5853b625381db13429f25512108d by Miss Islington (bot) (Gregory P. Smith) in branch 'master':
bpo-34200: Fix non-determinism of test_pkg (GH-9248)
https://github.com/python/cpython/commit/4ae8ece5cd4c5853b625381db13429f25512108d

New changeset 90f7d455b7f4bd53d3af11cb951347c9c8230399 by Miss Islington (bot) in branch '3.7':
bpo-34200: Fix non-determinism of test_pkg (GH-9248)
https://github.com/python/cpython/commit/90f7d455b7f4bd53d3af11cb951347c9c8230399

New changeset 3e3d4a4b55cbef481486aaa68ee255f4928b9c3f by Miss Islington (bot) in branch '3.6':
bpo-34200: Fix non-determinism of test_pkg (GH-9248)
https://github.com/python/cpython/commit/3e3d4a4b55cbef481486aaa68ee255f4928b9c3f

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!