Skip to content

importlib: python -m test test_pkg fails semi-randomly #78381

Closed
Closed
importlib: python -m test test_pkg fails semi-randomly#78381
Assignees
gpshead
Labels
3.7 (EOL)end of life3.8 (EOL)end of lifedeferred-blockertestsTests in the Lib/test dir

Description

@vstinner
vstinner
opened on Jul 23, 2018
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']

    Activity

    1. vstinner commented on Jul 23, 2018

      @vstinner
      vstinner
      on Jul 23, 2018
      MemberAuthor

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

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

    2. vstinner
      added
      OS-windows
      3.7 (EOL)end of life
      3.8 (EOL)end of life
      testsTests in the Lib/test dir
      on Jul 23, 2018

    3. vstinner commented on Jul 23, 2018

      @vstinner
      vstinner
      on Jul 23, 2018
      MemberAuthor

      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

    4. vstinner
      changed the title [-][Windows] python -X utf8 -m test test_pkg fails[/-] [+]python -X utf8 -m test test_pkg fails[/+] on Jul 23, 2018
    5. vstinner
      changed the title [-]python -X utf8 -m test test_pkg fails[/-] [+]importlib: python -m test test_pkg -m test_7 fails randomly[/+] on Jul 23, 2018

    6. vstinner commented on Jul 23, 2018

      @vstinner
      vstinner
      on Jul 23, 2018
      MemberAuthor

      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

    7. vstinner commented on Jul 23, 2018

      @vstinner
      vstinner
      on Jul 23, 2018
      MemberAuthor

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

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

    8. tirkarthi commented on Jul 23, 2018

      @tirkarthi
      tirkarthi
      on Jul 23, 2018
      Member

      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)

    9. vstinner commented on Jul 23, 2018

      @vstinner
      vstinner
      on Jul 23, 2018
      MemberAuthor

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

    10. vstinner
      removed
      OS-windows
      on Jul 23, 2018

    11. brettcannon commented on Aug 17, 2018

      @brettcannon
      brettcannon
      on Aug 17, 2018
      Member

      I can't reproduce with master on macOS.

    12. vladima commented on Aug 27, 2018

      @vladima
      vladimamannequin
      on Aug 27, 2018
      Mannequin

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

    13. 17 remaining items

    14. gpshead
      added
      deferred-blocker
      on Sep 12, 2018

    15. gpshead commented on Sep 12, 2018

      @gpshead
      gpshead
      on Sep 12, 2018
      Member

      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.

    16. gpshead
      changed the title [-]importlib: python -m test test_pkg fails[/-] [+]importlib: python -m test test_pkg fails semi-randomly[/+] on Sep 12, 2018
    17. gpshead
      self-assigned this
      on Sep 12, 2018

    18. gpshead commented on Sep 12, 2018

      @gpshead
      gpshead
      on Sep 12, 2018
      Member

      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.

    19. gpshead commented on Sep 12, 2018

      @gpshead
      gpshead
      on Sep 12, 2018
      Member

      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.

    20. jkloth commented on Sep 13, 2018

      @jkloth
      jkloth
      on Sep 13, 2018
      Contributor

      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.

    21. gpshead commented on Sep 13, 2018

      @gpshead
      gpshead
      on Sep 13, 2018
      Member

      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.

    22. miss-islington commented on Sep 13, 2018

      @miss-islington
      miss-islington
      on Sep 13, 2018
      Contributor

      New changeset 4ae8ece by Miss Islington (bot) (Gregory P. Smith) in branch 'master':
      bpo-34200: Fix non-determinism of test_pkg (GH-9248)
      4ae8ece

    23. miss-islington commented on Sep 13, 2018

      @miss-islington
      miss-islington
      on Sep 13, 2018
      Contributor

      New changeset 90f7d45 by Miss Islington (bot) in branch '3.7':
      bpo-34200: Fix non-determinism of test_pkg (GH-9248)
      90f7d45

    24. miss-islington commented on Sep 13, 2018

      @miss-islington
      miss-islington
      on Sep 13, 2018
      Contributor

      New changeset 3e3d4a4 by Miss Islington (bot) in branch '3.6':
      bpo-34200: Fix non-determinism of test_pkg (GH-9248)
      3e3d4a4

    25. gpshead commented on Sep 13, 2018

      @gpshead
      gpshead
      on Sep 13, 2018
      Member

      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.

    26. gpshead
      closed this as completedon Sep 13, 2018

    27. vstinner commented on Sep 13, 2018

      @vstinner
      vstinner
      on Sep 13, 2018
      MemberAuthor

      Thank you for the fix Gregory!

    28. ezio-melotti
      transferred this issue fromon Apr 10, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

    Metadata

    Metadata

    Assignees

    Labels

    3.7 (EOL)end of life3.8 (EOL)end of lifedeferred-blockertestsTests in the Lib/test dir

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions