tox4 -p fails intermittently with zipfile.BadZipFile and FileNotFoundError

[rra]

When attempting to build https://github.com/lsst-sqre/gafaelfawr with tox4 and the corresponding version of tox-docker (after stripping the hashes from the requirements file to work around https://github.com/tox-dev/tox/issues/2373), I found tox4 -p would intermittently fail with various exception when installing the virtual env. The environments that failed varied from run to run, and sometimes all environments would succeed.

One exception I saw a lot originally but then couldn't reproduce with when trying to capture a full trace with tox4 -vv -r -p is:

ERROR: Exception:
Traceback (most recent call last):
  File "/home/eagle/lsst/gafaelfawr/.tox/4/py/lib/python3.10/site-packages/pip/_internal/cli/base_command.py", line 167, in exc_logging_wrapper
    status = run_func(*args)
  File "/home/eagle/lsst/gafaelfawr/.tox/4/py/lib/python3.10/site-packages/pip/_internal/cli/req_command.py", line 205, in wrapper
    return func(self, options, args)
  File "/home/eagle/lsst/gafaelfawr/.tox/4/py/lib/python3.10/site-packages/pip/_internal/commands/install.py", line 405, in run
    installed = install_given_reqs(
  File "/home/eagle/lsst/gafaelfawr/.tox/4/py/lib/python3.10/site-packages/pip/_internal/req/__init__.py", line 73, in install_given_reqs
    requirement.install(
  File "/home/eagle/lsst/gafaelfawr/.tox/4/py/lib/python3.10/site-packages/pip/_internal/req/req_install.py", line 769, in install
    install_wheel(
  File "/home/eagle/lsst/gafaelfawr/.tox/4/py/lib/python3.10/site-packages/pip/_internal/operations/install/wheel.py", line 727, in install_wheel
    with ZipFile(wheel_path, allowZip64=True) as z:
  File "/usr/lib/python3.10/zipfile.py", line 1265, in __init__
    self._RealGetContents()
  File "/usr/lib/python3.10/zipfile.py", line 1332, in _RealGetContents
    raise BadZipFile("File is not a zip file")
zipfile.BadZipFile: File is not a zip file

Another one that does show up with tox4 -vv -r -p (trace attached) is:

docs: 2187 E internal error [tox/session/cmd/run/single.py:57]
Traceback (most recent call last):
  File "/home/eagle/dvl/venvs/gafaelfawr/lib/python3.10/site-packages/tox/session/cmd/run/single.py", line 45, in _evaluate
    tox_env.setup()
  File "/home/eagle/dvl/venvs/gafaelfawr/lib/python3.10/site-packages/tox/tox_env/api.py", line 224, in setup
    self._clean(transitive=True)
  File "/home/eagle/dvl/venvs/gafaelfawr/lib/python3.10/site-packages/tox/tox_env/runner.py", line 127, in _clean
    self._call_pkg_envs("_clean")
  File "/home/eagle/dvl/venvs/gafaelfawr/lib/python3.10/site-packages/tox/tox_env/runner.py", line 122, in _call_pkg_envs
    getattr(package_env, method_name)(*args)
  File "/home/eagle/dvl/venvs/gafaelfawr/lib/python3.10/site-packages/tox/tox_env/api.py", line 293, in _clean
    ensure_empty_dir(env_dir)
  File "/home/eagle/dvl/venvs/gafaelfawr/lib/python3.10/site-packages/tox/util/path.py", line 14, in ensure_empty_dir
    sub_path.unlink()
  File "/usr/lib/python3.10/pathlib.py", line 1204, in unlink
    self._accessor.unlink(self)
FileNotFoundError: [Errno 2] No such file or directory: '/home/eagle/lsst/gafaelfawr/.tox/4/.pkg/pyvenv.cfg'

I made no changes to my tox configuration, so it's possible that I'm missing some setting that's new with tox4.

If I had to guess, these feel like some sort of weird race conditions. tox-output.txt

[gaborbernat]

Unless you can replicate this without using tox-docker this sounds like an issue introduced by that plugin :thinking:

[rra]

I was able to reproduce without tox-docker using https://github.com/lsst-sqre/cachemachine. Example error messages:

ERROR: Wheel 'cachemachine' located at /home/eagle/.cache/pip/wheels/2c/d0/9c/40e99e6eff5220af92bb48a09d57c0fec9b5d34805baaf417c/cachemachine-1.1.2.dev16+g7a676f3.d20220325-py3-none-any.whl is invalid.
typing: FAIL ✖ in 7.67 seconds
.pkg: get_requires_for_build_sdist> python /home/eagle/dvl/venvs/cachemachine/lib/python3.10/site-packages/pyproject_api/_backend.py True setuptools.build_meta
.pkg: prepare_metadata_for_build_wheel> python /home/eagle/dvl/venvs/cachemachine/lib/python3.10/site-packages/pyproject_api/_backend.py True setuptools.build_meta
.pkg: build_sdist> python /home/eagle/dvl/venvs/cachemachine/lib/python3.10/site-packages/pyproject_api/_backend.py True setuptools.build_meta
typing: install_package> python -I -m pip install --force-reinstall --no-deps /home/eagle/lsst/cachemachine/.tox/4/.pkg/dist/cachemachine-1.1.2.dev16+g7a676f3.d20220325.tar.gz
typing: exit 1 (5.81 seconds) /home/eagle/lsst/cachemachine> python -I -m pip install --force-reinstall --no-deps /home/eagle/lsst/cachemachine/.tox/4/.pkg/dist/cachemachine-1.1.2.dev16+g7a676f3.d20220325.tar.gz pid=64734

  WARNING: No metadata found in ./.tox/4/py/lib/python3.10/site-packages
ERROR: For req: cachemachine==1.1.2.dev16+g7a676f3.d20220325. cachemachine has an invalid wheel, cachemachine has an invalid wheel, could not read 'cachemachine-1.1.2.dev16+g7a676f3.d20220325.dist-info/WHEEL' file: BadZipFile('Truncated file header')
py: FAIL ✖ in 7.77 seconds
.pkg: get_requires_for_build_sdist> python /home/eagle/dvl/venvs/cachemachine/lib/python3.10/site-packages/pyproject_api/_backend.py True setuptools.build_meta
.pkg: prepare_metadata_for_build_wheel> python /home/eagle/dvl/venvs/cachemachine/lib/python3.10/site-packages/pyproject_api/_backend.py True setuptools.build_meta
.pkg: build_sdist> python /home/eagle/dvl/venvs/cachemachine/lib/python3.10/site-packages/pyproject_api/_backend.py True setuptools.build_meta
py: install_package> python -I -m pip install --force-reinstall --no-deps /home/eagle/lsst/cachemachine/.tox/4/.pkg/dist/cachemachine-1.1.2.dev16+g7a676f3.d20220325.tar.gz
py: exit 1 (5.84 seconds) /home/eagle/lsst/cachemachine> python -I -m pip install --force-reinstall --no-deps /home/eagle/lsst/cachemachine/.tox/4/.pkg/dist/cachemachine-1.1.2.dev16+g7a676f3.d20220325.tar.gz pid=65129
coverage-report: FAIL ✖ in 0.09 seconds

WARNING: No metadata found in ./.tox/4/py/lib/python3.10/site-packages
ERROR: Exception:
Traceback (most recent call last):
  File "/home/eagle/lsst/cachemachine/.tox/4/py/lib/python3.10/site-packages/pip/_internal/cli/base_command.py", line 167, in exc_logging_wrapper
    status = run_func(*args)
  File "/home/eagle/lsst/cachemachine/.tox/4/py/lib/python3.10/site-packages/pip/_internal/cli/req_command.py", line 205, in wrapper
    return func(self, options, args)
  File "/home/eagle/lsst/cachemachine/.tox/4/py/lib/python3.10/site-packages/pip/_internal/commands/install.py", line 405, in run
    installed = install_given_reqs(
  File "/home/eagle/lsst/cachemachine/.tox/4/py/lib/python3.10/site-packages/pip/_internal/req/__init__.py", line 73, in install_given_reqs
    requirement.install(
  File "/home/eagle/lsst/cachemachine/.tox/4/py/lib/python3.10/site-packages/pip/_internal/req/req_install.py", line 769, in install
    install_wheel(
  File "/home/eagle/lsst/cachemachine/.tox/4/py/lib/python3.10/site-packages/pip/_internal/operations/install/wheel.py", line 729, in install_wheel
    _install_wheel(
  File "/home/eagle/lsst/cachemachine/.tox/4/py/lib/python3.10/site-packages/pip/_internal/operations/install/wheel.py", line 589, in _install_wheel
    file.save()
  File "/home/eagle/lsst/cachemachine/.tox/4/py/lib/python3.10/site-packages/pip/_internal/operations/install/wheel.py", line 390, in save
    shutil.copyfileobj(f, dest)
  File "/usr/lib/python3.10/shutil.py", line 195, in copyfileobj
    buf = fsrc_read(length)
  File "/usr/lib/python3.10/zipfile.py", line 925, in read
    data = self._read1(n)
  File "/usr/lib/python3.10/zipfile.py", line 993, in _read1
    data += self._read2(n - len(data))
  File "/usr/lib/python3.10/zipfile.py", line 1028, in _read2
    raise EOFError
EOFError
py: FAIL ✖ in 7.87 seconds
.pkg: get_requires_for_build_sdist> python /home/eagle/dvl/venvs/cachemachine/lib/python3.10/site-packages/pyproject_api/_backend.py True setuptools.build_meta
.pkg: prepare_metadata_for_build_wheel> python /home/eagle/dvl/venvs/cachemachine/lib/python3.10/site-packages/pyproject_api/_backend.py True setuptools.build_meta
.pkg: build_sdist> python /home/eagle/dvl/venvs/cachemachine/lib/python3.10/site-packages/pyproject_api/_backend.py True setuptools.build_meta
py: install_package> python -I -m pip install --force-reinstall --no-deps /home/eagle/lsst/cachemachine/.tox/4/.pkg/dist/cachemachine-1.1.2.dev16+g7a676f3.d20220325.tar.gz
py: exit 2 (5.93 seconds) /home/eagle/lsst/cachemachine> python -I -m pip install --force-reinstall --no-deps /home/eagle/lsst/cachemachine/.tox/4/.pkg/dist/cachemachine-1.1.2.dev16+g7a676f3.d20220325.tar.gz pid=67213
coverage-report: FAIL ✖ in 0.09 seconds

It seems very sensitive to small details of timing. I was unable to reproduce it with -r or with -vvv. The above errors were all from running tox4 -p all repeatedly until it failed.

[rra]

There we go. I managed to reproduce it with tox4 -vvv -r -p all.

tox-log.txt

[jugmac00]

The latest version of cachemachine, which you used as an reproducer, fails with a poetry error:

ERROR: In --require-hashes mode, all requirements must have their versions pinned with ==. These do not:
    importlib-resources>=1.4.0 from https://files.pythonhosted.org/packages/ab/72/b4374afdfacc45bfcdd71404d5ac1315cf90b5b591d6110e1a4a8d1c8cfe/importlib_resources-5.10.1-py3-none-any.whl (from jsonschema==4.17.3->-r /tmp/cachemachine/requirements/main.txt (line 407))
typing: 14349 C exit 1 (6.48 seconds) /tmp/cachemachine> python -I -m pip install -r /tmp/cachemachine/requirements/main.txt -r /tmp/cachemachine/requirements/dev.txt pid=482356

Does the error still exist with the latest tox v4?

[rra]

(We don't use poetry. I suspect you're trying to use Python 3.9, which isn't supported.)

I haven't seen this error in quite some time with tox 3 either, and indeed I can't reproduce it now with that repository with tox 4. I suspect the problem was really with some underlying library and has been fixed. Thanks for pinging this issue!