classification
Title: test_venv: test_isolation() failed on AMD64 Windows7 SP1 3.x: directory not empty: Scripts\
Type: Stage: resolved
Components: Tests Versions: Python 3.9
process
Status: closed Resolution: out of date
Dependencies: Superseder:
Assigned To: Nosy List: jkloth, vinay.sajip, vstinner
Priority: normal Keywords:

Created on 2019-10-21 10:19 by vstinner, last changed 2020-05-18 15:40 by vstinner. This issue is now closed.

Messages (9)
msg355040 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-21 10:19
https://buildbot.python.org/all/#/builders/40/builds/3317

test_executable (test.test_venv.BasicTest) ... ok
test_executable_symlinks (test.test_venv.BasicTest) ... skipped 'Needs symlinks'
test_isolation (test.test_venv.BasicTest) ... ERROR
ERROR
test_multiprocessing (test.test_venv.BasicTest) ... ok
test_overwrite_existing (test.test_venv.BasicTest) ... ok

======================================================================
ERROR: test_isolation (test.test_venv.BasicTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\test_venv.py", line 272, in test_isolation
    builder.create(self.env_dir)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\venv\__init__.py", line 65, in create
    context = self.ensure_directories(env_dir)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\venv\__init__.py", line 108, in ensure_directories
    self.clear_directory(env_dir)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\venv\__init__.py", line 91, in clear_directory
    shutil.rmtree(fn)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\shutil.py", line 730, in rmtree
    return _rmtree_unsafe(path, onerror)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\shutil.py", line 612, in _rmtree_unsafe
    onerror(os.rmdir, path, sys.exc_info())
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\shutil.py", line 610, in _rmtree_unsafe
    os.rmdir(path)
OSError: [WinError 145] The directory is not empty: 'C:\\Users\\Buildbot\\AppData\\Local\\Temp\\tmp2y7z3288\\Scripts'
msg355041 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-21 10:19
Similar error on the same build when the test was re-run in verbose mode:

0:10:55 load avg: 1.82 Re-running test_venv in verbose mode
test_deactivate_with_strict_bash_opts (test.test_venv.BasicTest) ... skipped 'not relevant on Windows'
test_defaults (test.test_venv.BasicTest) ... ok
test_executable (test.test_venv.BasicTest) ... ok
test_executable_symlinks (test.test_venv.BasicTest) ... skipped 'Needs symlinks'
test_isolation (test.test_venv.BasicTest) ... ok
test_multiprocessing (test.test_venv.BasicTest) ... ok
test_overwrite_existing (test.test_venv.BasicTest) ... ERROR
ERROR
test_prefixes (test.test_venv.BasicTest) ... ok
test_prompt (test.test_venv.BasicTest) ... ok
test_symlinking (test.test_venv.BasicTest) ... skipped 'Needs symlinks'
test_unicode_in_batch_file (test.test_venv.BasicTest) ... ok
test_unoverwritable_fails (test.test_venv.BasicTest) ... ok
test_upgrade (test.test_venv.BasicTest) ... ok
test_upgrade_dependencies (test.test_venv.BasicTest) ... ok
test_devnull (test.test_venv.EnsurePipTest) ... ok
test_explicit_no_pip (test.test_venv.EnsurePipTest) ... ok
test_no_pip_by_default (test.test_venv.EnsurePipTest) ... ok
test_with_pip (test.test_venv.EnsurePipTest) ... ok

======================================================================
ERROR: test_overwrite_existing (test.test_venv.BasicTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\test_venv.py", line 223, in test_overwrite_existing
    builder.create(self.env_dir)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\venv\__init__.py", line 65, in create
    context = self.ensure_directories(env_dir)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\venv\__init__.py", line 108, in ensure_directories
    self.clear_directory(env_dir)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\venv\__init__.py", line 91, in clear_directory
    shutil.rmtree(fn)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\shutil.py", line 730, in rmtree
    return _rmtree_unsafe(path, onerror)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\shutil.py", line 612, in _rmtree_unsafe
    onerror(os.rmdir, path, sys.exc_info())
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\shutil.py", line 610, in _rmtree_unsafe
    os.rmdir(path)
OSError: [WinError 145] The directory is not empty: 'C:\\Users\\Buildbot\\AppData\\Local\\Temp\\tmpvw7zok8k\\Scripts'

======================================================================
ERROR: test_overwrite_existing (test.test_venv.BasicTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 336, in _force_run
    return func(*args)
PermissionError: [WinError 5] Access is denied: 'C:\\Users\\Buildbot\\AppData\\Local\\Temp\\tmpvw7zok8k\\Scripts\\activate.bat'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\test_venv.py", line 71, in tearDown
    rmtree(self.env_dir)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 458, in rmtree
    _rmtree(path)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 399, in _rmtree
    _waitfor(_rmtree_inner, path, waitall=True)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 347, in _waitfor
    func(pathname)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 395, in _rmtree_inner
    _waitfor(_rmtree_inner, fullname, waitall=True)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 347, in _waitfor
    func(pathname)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 398, in _rmtree_inner
    _force_run(fullname, os.unlink, fullname)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 341, in _force_run
    os.chmod(path, stat.S_IRWXU)
PermissionError: [WinError 5] Access is denied: 'C:\\Users\\Buildbot\\AppData\\Local\\Temp\\tmpvw7zok8k\\Scripts\\activate.bat'

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

Ran 18 tests in 45.669s

FAILED (errors=2, skipped=3)
msg355061 - (view) Author: Jeremy Kloth (jkloth) * Date: 2019-10-21 12:04
While not getting into the error itself, there seems to be another issue in that the logging that should be happening when the deletion routines from test.support fail:

https://github.com/python/cpython/blob/5bc6a7c06eda20ba131ecba6752be0506d310181/Lib/test/support/__init__.py#L339
https://github.com/python/cpython/blob/5bc6a7c06eda20ba131ecba6752be0506d310181/Lib/test/support/__init__.py#L375

is not showing up when the test is re-run in verbose mode.
msg355067 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-21 13:18
> ... is not showing up when the test is re-run in verbose mode.

_force_run() logs require verbose >= 2. The test suite is run using:

'Tools\\buildbot\\test.bat' '-x64' '-j2' '-j4' '--timeout' '900'

which runs:

C:\buildbot.python.org\3.x.kloth-win64\build>"C:\buildbot.python.org\3.x.kloth-win64\build\PCbuild\amd64\python_d.exe"  -u -Wd -E -bb -m test  -uall -rwW --slowest --timeout 1200 --fail-env-changed -j1 -j2 -j4 --timeout 900 

Using this command, I get: support.verbose=1 in the main regrtest process and in regrtest worker processes.

Maybe _force_run() should always log, or log "if verbose:" (remove ">= 2" restriction).
msg355069 - (view) Author: Jeremy Kloth (jkloth) * Date: 2019-10-21 13:35
That covers the logging in _force_run(), but the warning.warn() line is also not output, suggesting that the RuntimeWarning is being suppressed somewhere.
msg357925 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-12-06 17:27
I marked bpo-38983 as a duplicate of this issue. It's the same error in the same function (clear_directory()). Copy of the first message:

Failure on AMD64 Windows7 SP1 3.x:
https://buildbot.python.org/all/#builders/81/builds/16

======================================================================
ERROR: test_overwrite_existing (test.test_venv.BasicTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\test_venv.py", line 225, in test_overwrite_existing
    builder.create(self.env_dir)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\venv\__init__.py", line 65, in create
    context = self.ensure_directories(env_dir)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\venv\__init__.py", line 108, in ensure_directories
    self.clear_directory(env_dir)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\venv\__init__.py", line 91, in clear_directory
    shutil.rmtree(fn)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\shutil.py", line 731, in rmtree
    return _rmtree_unsafe(path, onerror)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\shutil.py", line 613, in _rmtree_unsafe
    onerror(os.rmdir, path, sys.exc_info())
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\shutil.py", line 611, in _rmtree_unsafe
    os.rmdir(path)
OSError: [WinError 145] The directory is not empty: 'C:\\Users\\Buildbot\\AppData\\Local\\Temp\\tmp9y0m6j7z\\Scripts'

======================================================================
ERROR: test_overwrite_existing (test.test_venv.BasicTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 380, in _force_run
    return func(*args)
PermissionError: [WinError 5] Access is denied: 'C:\\Users\\Buildbot\\AppData\\Local\\Temp\\tmp9y0m6j7z\\Scripts\\activate.bat'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\test_venv.py", line 71, in tearDown
    rmtree(self.env_dir)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 502, in rmtree
    _rmtree(path)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 443, in _rmtree
    _waitfor(_rmtree_inner, path, waitall=True)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 391, in _waitfor
    func(pathname)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 439, in _rmtree_inner
    _waitfor(_rmtree_inner, fullname, waitall=True)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 391, in _waitfor
    func(pathname)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 442, in _rmtree_inner
    _force_run(fullname, os.unlink, fullname)
  File "C:\buildbot.python.org\3.x.kloth-win64\build\lib\test\support\__init__.py", line 385, in _force_run
    os.chmod(path, stat.S_IRWXU)
PermissionError: [WinError 5] Access is denied: 'C:\\Users\\Buildbot\\AppData\\Local\\Temp\\tmp9y0m6j7z\\Scripts\\activate.bat
msg357938 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2019-12-06 19:08
Not sure what's changed in this area, if anything, to cause this. Can we check if there is anti-virus software running on the buildbot box? This can sometimes hold files open for short periods while scanning for malware, causing this type of permission error fairly randomly.
msg357939 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-12-06 19:12
Maybe the test can replace shutil.rmtree() with test.support.rmtree() temporarily in test_venv, since test.support.rmtree() handles the anti-malwares protections by retrying and/or sleep (if I recall correctly).
msg369250 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-05-18 15:40
I didn't see this race condition recently, I just close the issue.
History
Date User Action Args
2020-05-18 15:40:07vstinnersetstatus: open -> closed
resolution: out of date
messages: + msg369250

stage: resolved
2019-12-06 19:12:33vstinnersetmessages: + msg357939
2019-12-06 19:08:12vinay.sajipsetmessages: + msg357938
2019-12-06 17:55:43brett.cannonsetnosy: + vinay.sajip
2019-12-06 17:27:35vstinnersetmessages: + msg357925
2019-12-06 16:05:09vstinnerlinkissue38983 superseder
2019-10-21 13:35:04jklothsetmessages: + msg355069
2019-10-21 13:18:13vstinnersetmessages: + msg355067
2019-10-21 12:04:52jklothsetmessages: + msg355061
2019-10-21 12:01:29jklothsetnosy: + jkloth
2019-10-21 10:19:48vstinnersetmessages: + msg355041
2019-10-21 10:19:04vstinnercreate