Race condition in new installer (1.1.0rc1) with --remove-untracked

[PetterS]

To reproduce:

• Add ipython = "*" as a dev dependency to a repo.
• poetry lock
• poetry install
• Remove it again.
• poetry lock
• poerty install --remove-untracked

I get this:

Installing dependencies from lock file

Package operations: 0 installs, 0 updates, 15 removals

  • Removing backcall (0.2.0)
  • Removing decorator (4.4.2)
  • Removing ipython (7.16.1): Failed

  EnvCommandError

  Command ['/home/petter/.cache/pypoetry/virtualenvs/openai-test-cYZNiyR8-py3.8/bin/python', '-m', 'pip', 'uninstall', 'ipython', '-y'] errored with the following return code 2, and output:
  ERROR: Exception:
  Traceback (most recent call last):
    File "/home/petter/.cache/pypoetry/virtualenvs/openai-test-cYZNiyR8-py3.8/lib/python3.8/site-packages/pip/_internal/cli/base_command.py", line 186, in _main
      status = self.run(options, args)
    File "/home/petter/.cache/pypoetry/virtualenvs/openai-test-cYZNiyR8-py3.8/lib/python3.8/site-packages/pip/_internal/commands/uninstall.py", line 51, in run
      session = self.get_default_session(options)
    File "/home/petter/.cache/pypoetry/virtualenvs/openai-test-cYZNiyR8-py3.8/lib/python3.8/site-packages/pip/_internal/cli/req_command.py", line 74, in get_default_session
      self._session = self.enter_context(self._build_session(options))
    File "/home/petter/.cache/pypoetry/virtualenvs/openai-test-cYZNiyR8-py3.8/lib/python3.8/site-packages/pip/_internal/cli/req_command.py", line 84, in _build_session
      session = PipSession(
    File "/home/petter/.cache/pypoetry/virtualenvs/openai-test-cYZNiyR8-py3.8/lib/python3.8/site-packages/pip/_internal/network/session.py", line 241, in __init__
      self.headers["User-Agent"] = user_agent()
    File "/home/petter/.cache/pypoetry/virtualenvs/openai-test-cYZNiyR8-py3.8/lib/python3.8/site-packages/pip/_internal/network/session.py", line 159, in user_agent
      setuptools_version = get_installed_version("setuptools")
    File "/home/petter/.cache/pypoetry/virtualenvs/openai-test-cYZNiyR8-py3.8/lib/python3.8/site-packages/pip/_internal/utils/misc.py", line 637, in get_installed_version
      working_set = pkg_resources.WorkingSet()
    File "/home/petter/.cache/pypoetry/virtualenvs/openai-test-cYZNiyR8-py3.8/share/python-wheels/pkg_resources-0.0.0-py2.py3-none-any.whl/pkg_resources/__init__.py", line 567, in __init__
      self.add_entry(entry)
    File "/home/petter/.cache/pypoetry/virtualenvs/openai-test-cYZNiyR8-py3.8/share/python-wheels/pkg_resources-0.0.0-py2.py3-none-any.whl/pkg_resources/__init__.py", line 623, in add_entry
      for dist in find_distributions(entry, True):
    File "/home/petter/.cache/pypoetry/virtualenvs/openai-test-cYZNiyR8-py3.8/share/python-wheels/pkg_resources-0.0.0-py2.py3-none-any.whl/pkg_resources/__init__.py", line 2065, in find_on_path
      for dist in factory(fullpath):
    File "/home/petter/.cache/pypoetry/virtualenvs/openai-test-cYZNiyR8-py3.8/share/python-wheels/pkg_resources-0.0.0-py2.py3-none-any.whl/pkg_resources/__init__.py", line 2127, in distributions_from_metadata
      if len(os.listdir(path)) == 0:
  FileNotFoundError: [Errno 2] No such file or directory: '/home/petter/.cache/pypoetry/virtualenvs/openai-test-cYZNiyR8-py3.8/lib/python3.8/site-packages/~typrocess-0.6.0.dist-info'


  at /usr/local/lib/python3.8/dist-packages/poetry/utils/env.py:937 in _run
       933│                 output = subprocess.check_output(
       934│                     cmd, stderr=subprocess.STDOUT, **kwargs
       935│                 )
       936│         except CalledProcessError as e:
    →  937│             raise EnvCommandError(e, input=input_)
       938│
       939│         return decode(output)
       940│
       941│     def execute(self, bin, *args, **kwargs):

  • Removing ipython-genutils (0.2.0)
  • Removing jedi (0.17.1)
  • Removing parso (0.7.0)
  • Removing pickleshare (0.7.5)
  • Removing pkg-resources (0.0.0)
  • Removing prompt-toolkit (3.0.5)
  • Removing ptyprocess (0.6.0)
  • Removing pygments (2.6.1)
  • Removing pexpect (4.8.0)
  • Removing six (1.15.0)
  • Removing traitlets (4.3.3)
  • Removing wcwidth (0.2.5)

I don't know what site-packages/~typrocess-0.6.0.dist-info' is but my guess is that it has something to do with the parallel processing. Runing the command again fixes the issue.

I suggest that we do not process uninstalls in parallel unless this is easy to fix. I don't know how to fix this. @sdispater wrote the new installer.

[PetterS]

From the stack trace, I think it is plausible that running pip uninstall in parallel simply isn't safe.

We could make sure all uninstall commands have different priorities so that they appear in different groups here:

poetry/poetry/installation/executor.py

Line 106 in 27d1599

groups = itertools.groupby(operations, key=lambda o: -o.priority)

[PetterS]

Will investigate this more once #2624 is in.

[abn]

@PetterS is this consistently reproducible for you? I am having issues reproducing it using develop.

[PetterS]

@abn not consistently as in triggering every time, no.

But it really needs to be fixed before 1.1. I think the stack trace pretty clearly shows that running the installs in parallel is unsafe?

[PetterS]

Crashed on the second attempt with 1.1.0b2. So it should be easy to reproduce.

FileNotFoundError: [Errno 2] No such file or directory: '/home/petter/.cache/pypoetry/virtualenvs/testenv-wETKOq8S-py3.8/lib/python3.8/site-packages/~ecorator-4.4.2.dist-info'

[PetterS]

Will you accept a PR making all uninstalls run sequentially? We have to do something about this.

[abn]

@PetterS I am not sure what to tell you. I just ran this against the current master, and I did not hit the issue. Effectively sets up your issue and iterates 10 times.

#!/usr/bin/env bash -e

TMP_DIR=`mktemp -d`
TOML=${TMP_DIR}/pyproject.toml

function reset-pyproject() {
  cat > ${TOML} <<EOF
[tool.poetry]
name = "foobar"
version = "0.1.0"
description = ""
authors = ["Bender Rodriguez <bender@planetexpress.com>"]

[tool.poetry.dependencies]
python = "^3.8"

[tool.poetry.dev-dependencies]
ipython = "*"
EOF
}

mkdir -p ${TMP_DIR}/foobar
touch ${TMP_DIR}/foobar/__init__.py

pushd ${TMP_DIR}

POETRY=poetry

for i in $(seq 1 10); do
  reset-pyproject
  ${POETRY} lock
  ${POETRY} install
  sed -i /ipython/d ${TOML}
  ${POETRY} lock
  ${POETRY} install --remove-untracked
done

popd

I am curious as to what the root cause here is, considering each package is only uninstalled once, how two packages try to remove the same file/directory is confounding.

@sdispater you have any input here since you implemented the new installer? Would also be great if you can see if you can reproduce the issue.

[PetterS]

Any progress here? This still looks like a concurrency bug to me.

[PetterS]

@abn

Your script does not reproduce the issue on my desktop computer (16 cores/32 threads Ubuntu 20.04 WSL2).

Your script does reproduce the issue on my laptop (Ubuntu 20.04 WSL1). First attempt as well.

Both with Poetry 1.1 RC1.

[PetterS]

It is a pretty easy change to make all uninstalls run sequentially. Will not affect performance that much either.

[abn]

I am curious as to what the root cause here is, considering each package is only uninstalled once, how two packages try to remove the same file/directory is confounding.

@PetterS as I mentioned before I am a bit hesitant to recommend the change until we know the root cause of the issue. As in why two operations are attempting to remove the same file as you have indicated.

[PetterS]

The crashing code is this:

    root = os.path.dirname(path)
    if os.path.isdir(path):
        if len(os.listdir(path)) == 0:

The last line fails with a FileNotFoundError. It seems this can only happen in a concurrent setting? It does not fail all the time either, which rule out deterministic bugs.

Does pip even document that concurrent uninstalls are safe?

[PetterS]

Here is the smoking gun, I think! 🥳

• The uninstallation process for ptyprocess creates an adjacent temp directory starting with "~" (per the code above).
  • This class, AdjacentTempDirectory, generates a directory with a leading "~": https://github.com/pypa/pip/blob/703d6ac874d2703cf9283ccb252ff6d22932b8c4/src/pip/_internal/utils/temp_dir.py#L217
  • The class AdjacentTempDirectory adding the "~" is used when uninstalling here: https://github.com/pypa/pip/blob/faee60baea2b850427b5fceb22383883fa11290b/src/pip/_internal/req/req_uninstall.py#L238
• The uninstallation process for ipython does package discovery at the same time, executing this code (https://github.com/pypa/setuptools/blob/1ea521c51b0ed2967a9ff1d8ad41160043a8a981/pkg_resources/__init__.py#L2116)

    root = os.path.dirname(path)
    if os.path.isdir(path):
        if len(os.listdir(path)) == 0:

• The temp directory is very short-lived, causing the above code to fail.

The leading "~" can be seen in the stack trace.

@abn

[PetterS]

@abn @sdispater
This is a problem in the released version 1.1.0 as well. See by comment above that explains why parallel uninstallations are not safe.

I can make a PR, but need to know that it will be accepted. It is an easy fix.

[klarose]

This is also causing issues with source packages. I'm installing source packages from our self-hosted git repo, and there is a clear race condition when using the new installer. I originally blamed #2102, but after some experimentation determined that the issue was unrelated to that.

My symptoms are that some of my source packages do not exist in my environment after doing the install. The happens both for system installs and venvs. Digging in, I find that with python -m site the path to the source is no longer in the python path.

Further digging shows that the paths come from site-packages/easy-install.pth, which has a list of the source-installed packages. Every time I run the install, that list changes. Some of the packages just aren't there. Which ones are change. The number that are in the list changes from time to time as well.

I suspect that there is a race condition on the installation of these: multiple separate processes/threads modify the file at the same time without taking a lock.

There's a few options I can see to fix this, though I'm sure this is a non-exhaustive list:

• Ensure .pth files are installed for all source packages (it looks like some do -- ones that themselves use poetry).
• Make sure the easy-install.pth file is locked, and that whatever is modifying it takes the lock
• Process source dependencies serially.

I worked around this problem by disabling the experimental installer. Downgrading to 1.0.10 also did the trick. Neither of these are fantastic solutions. I suppose I could update all the dependencies to use poetry, but that may not always be possible, and it adds quite a bit of work in the short term to unblock my builds.

[abn]

@klarose this was, funnily enough, brought up on discord a few hours ago via #3086.

I'd like to treat the issue being discussed here slightly separate to the issue you have raised as they are different enough to warrant separate solutions.

The 1.1 bug fix might be to, as @PetterS suggests, serialise the uninstalls and installations that use develop mode. However, the 1.2 fix, should be focused on the efforts to drop sub-process calls to pip for install/uninstall operations. I would like to look at efforts involved in both, if the final solution is simple enough, maybe we simply back port that to 1.1, otherwise we simply carry the performance hit until 1.2.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.