importlib: python -m test test_pkg fails semi-randomly

[vstinner]

BPO	34200
Nosy	@warsaw, @brettcannon, @gpshead, @ncoghlan, @vstinner, @jkloth, @ned-deily, @miss-islington, @LorenzMende, @vladima
PRs	bpo-34200: Fix non-determinism of test_pkg #9248 [3.7] bpo-34200: Fix non-determinism of test_pkg (GH-9248) #9252 [3.6] bpo-34200: Fix non-determinism of test_pkg (GH-9248) #9253

^{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 = 'https://github.com/gpshead'
closed_at = <Date 2018-09-13.01:32:06.244>
created_at = <Date 2018-07-23.12:45:09.504>
labels = ['3.8', 'deferred-blocker', '3.7', 'tests']
title = 'importlib: python -m test test_pkg fails semi-randomly'
updated_at = <Date 2018-09-13.06:18:42.107>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2018-09-13.06:18:42.107>
actor = 'vstinner'
assignee = 'gregory.p.smith'
closed = True
closed_date = <Date 2018-09-13.01:32:06.244>
closer = 'gregory.p.smith'
components = ['Tests']
creation = <Date 2018-07-23.12:45:09.504>
creator = 'vstinner'
dependencies = []
files = []
hgrepos = []
issue_num = 34200
keywords = ['patch']
message_count = 32.0
messages = ['322208', '322210', '322212', '322213', '322214', '322215', '323664', '324197', '324291', '324292', '324293', '324391', '324464', '324467', '324478', '324531', '324623', '324714', '325159', '325161', '325163', '325187', '325188', '325194', '325214', '325218', '325222', '325224', '325225', '325226', '325227', '325236']
nosy_count = 11.0
nosy_names = ['barry', 'brett.cannon', 'gregory.p.smith', 'ncoghlan', 'vstinner', 'jkloth', 'ned.deily', 'miss-islington', 'LorenzMende', 'v2m', 'pms.coder']
pr_nums = ['9248', '9252', '9253']
priority = 'deferred blocker'
resolution = 'fixed'
stage = 'commit review'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue34200'
versions = ['Python 3.5', 'Python 3.6', 'Python 3.7', 'Python 3.8']

[vstinner]

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__']

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

[vstinner]

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

[vstinner]

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

[vstinner]

I'm also able to reproduce the bug on Python 3.6.

Note: -X utf8 option is unrelated to this issue.

[tirkarthi]

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)

[vstinner]

I removed Windows experts from the nosy list, since the issue is related to importlib, no Windows.

[brettcannon]

I can't reproduce with master on macOS.

[vladima]

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