poetry install fails on KeyError even for defined environment variables

[pepastach]

• I am on the latest Poetry version.
• I have searched the issues of this repo and believe that this is not a duplicate.
• If an exception occurs when executing a command, I executed it again in debug mode (-vvv option).

• OS version and name: Debian Linux 10 Buster
• Poetry version: 1.1.2
• Link of a Gist with the contents of your pyproject.toml file: https://gist.github.com/pepastach/85b133f035fbb805cacd4d0fd75562b1

Issue

We run poetry install --remove-untracked and the process randomly fails on various "missing" environment variables. This has been reported in #3144 for the PATH variable (which happens quite a lot, more than other variables), but I have seen it for many other variables (often GitLab or Docker related). In all cases they are defined.

It fails really randomly. Different dependencies being installed, different environment variables. Sometimes it does not fail (but most often it does).
Sometimes it fails on multiple environment variables. Like KeyError 'PATH', KeyError 'CI_JOB_STAGE' or KeyError 'DOCKER_ENV_CI_DISPOSABLE_ENVIRONMENT' in the same run. It seems to me like some kind of race condition in the parallel install. I can't prove this hypothesis until we can disable parallel installation. I think it's scheduled for an upcoming release.

Here is an example output where it fails on the PATH variable.

Creating virtualenv bp-xxx-3RqKXHa2-py3.7 in /builds/xxx/.cache/poetry/pypoetry/virtualenvs
Installing dependencies from lock file
Package operations: 106 installs, 0 updates, 0 removals
  • Installing attrs (20.2.0)
  • Installing six (1.15.0)
  • Installing cattrs (1.0.0)
...
Stack trace:
  8  /usr/local/lib/python3.7/site-packages/poetry/installation/executor.py:199 in _execute_operation
      197│ 
      198│             try:
    → 199│                 result = self._do_execute_operation(operation)
      200│             except EnvCommandError as e:
      201│                 if e.e.returncode == -2:
  7  /usr/local/lib/python3.7/site-packages/poetry/installation/executor.py:273 in _do_execute_operation
      271│             return 0
      272│ 
    → 273│         result = getattr(self, "_execute_{}".format(method))(operation)
      274│ 
      275│         if result != 0:
  6  /usr/local/lib/python3.7/site-packages/poetry/installation/executor.py:408 in _execute_install
      406│ 
      407│     def _execute_install(self, operation):  # type: (Install) -> None
    → 408│         return self._install(operation)
      409│ 
      410│     def _execute_update(self, operation):  # type: (Update) -> None
  5  /usr/local/lib/python3.7/site-packages/poetry/installation/executor.py:446 in _install
      444│             args.insert(2, "-U")
      445│ 
    → 446│         return self.run_pip(*args)
      447│ 
      448│     def _update(self, operation):
  4  /usr/local/lib/python3.7/site-packages/poetry/installation/executor.py:297 in run_pip
      295│     def run_pip(self, *args, **kwargs):  # type: (...) -> int
      296│         try:
    → 297│             self._env.run_pip(*args, **kwargs)
      298│         except EnvCommandError as e:
      299│             output = decode(e.e.output)
  3  /usr/local/lib/python3.7/site-packages/poetry/utils/env.py:916 in run_pip
       914│         pip = self.get_pip_command()
       915│         cmd = pip + list(args)
    →  916│         return self._run(cmd, **kwargs)
       917│ 
       918│     def _run(self, cmd, **kwargs):
  2  /usr/local/lib/python3.7/site-packages/poetry/utils/env.py:1183 in _run
      1181│     def _run(self, cmd, **kwargs):
      1182│         with self.temp_environ():
    → 1183│             os.environ["PATH"] = self._updated_path()
      1184│             os.environ["VIRTUAL_ENV"] = str(self._path)
      1185│ 
  1  /usr/local/lib/python3.7/site-packages/poetry/utils/env.py:1215 in _updated_path
      1213│ 
      1214│     def _updated_path(self):
    → 1215│         return os.pathsep.join([str(self._bin_dir), os.environ["PATH"]])
      1216│ 
      1217│ 
  KeyError
  'PATH'
  at /usr/local/lib/python3.7/os.py:681 in __getitem__
       677│         try:
       678│             value = self._data[self.encodekey(key)]
       679│         except KeyError:
       680│             # raise KeyError with the original key value
    →  681│             raise KeyError(key) from None
       682│         return self.decodevalue(value)
       683│ 
       684│     def __setitem__(self, key, value):
       685│         key = self.encodekey(key)
  • Installing pluggy (0.13.1)
  • Installing py (1.9.0)
  • Installing wcwidth (0.2.5)
  • Installing yarl (1.6.0)

[abn]

@pepastach do you have any additional system information around cores availabe etc? Even any reference to the speciifcation of the runner the above occurs in.

[pepastach]

It runs in AWS on m4.xlarge instances in Docker. That's 4 cores, 16 GB RAM, 2.3 GHz Intel Xeon® E5-2686 v4 (Broadwell) processors or 2.4 GHz Intel Xeon® E5-2676 v3 (Haswell) processors

[abn]

Any limits on the container instances? Particularly CPU or Memory?

[pepastach]

No. When we run distributed unit tests, it reports 4 cores as it should. And memory is plenty. All the machine resources are available to the docker container running poetry.

[abn]

Thanks @pepastach will try reproduce it.

[pepastach]

@jihadik as far as I know you can't disable parallel install in poetry 1.1.2

[kosta-p]

@pepastach actually you can.
poetry config experimental.new-installer false helped me to resolve similar issues on my MacOS dev environment and inside docker during Gitlab CI

[pepastach]

Thanks @kosta-p that seems to help. I ran our CI/CD three times and all runs passed.

For anyone experiencing this issue, try disabling parallel installer before running poetry install:

poetry config experimental.new-installer false

[gcalmettes]

Same error encountered during Gitlab CI, and disabling parrallel installer as noted above worked.
Thanks !

[abn]

For issues relating to connection reset errors; please see #3219 (comment). We would like to keep this issue focussed on the key error issue.

[max-wittig]

Same happening here in GitLab CI. 1.1.3 didn't fix it.

[AzMoo]

I'm receiving the same error in the gitlab-runner.

As far as I can see, the issue occurs for me only when using the docker executor with linked services. It doesn't seem to occur if I don't have any linked services.

It seems not to occur if I run the same install in docker-compose with the same linked services, it seems specific to the gitlab-runner.

The issue does not occur if I disable the new installer with poetry config experimental.new-installer false.

I hope this helps to narrow down the problem.

[abn]

@AzMoo @max-wittig are you referring to the KeyError or the connection reset error?

[AzMoo]

@abn Sorry, I am referring specifically to the KeyError as described in the original post by @pepastach

I have also seen it raise an EnvCommandError.

[abn]

Thanks for confirming @AzMoo appreciate it.

[AzMoo]

I've created a repo here: https://github.com/AzMoo/gitlab-poetry-test that replicates the issue.

I've found it doesn't require linked services, just to be running in the gitlab-runner with the docker executor, and to install a fairly significant amount of packages.

[abn]

Unfortunately I was unable to reproduce the issue on my machine. I do not have access to a gitlab environment readily to test. But, can you please try the fix at #3253. See if that makes a difference?

Using pipx

pipx install --suffix=@3253 'poetry @ git+https://github.com/python-poetry/poetry.git@refs/pull/3253/head'

Using a container (podman | docker)

podman run --rm -i --entrypoint bash python:3.8 <<EOF
set -xe
python -m pip install -q git+https://github.com/python-poetry/poetry.git@refs/pull/3253/head
git clone https://github.com/AzMoo/gitlab-poetry-test 
pushd gitlab-poetry-test 
poetry install
EOF

[max-wittig]

@abn I was mentioning the KeyError as in the issue title. @AzMoo Could you mirror that repo to gitlab.com, so that @abn can see the error in the logs?

[abn]

@AzMoo @max-wittig https://gitlab.com/abn/poetry-issue-3199/-/jobs/801924761 The errors seem to be package build related not the issue described here.

[AzMoo]

Ah damn, I'm really sorry, I pushed that up in a hurry and didn't read the errors properly. Let me revisit and get it right this time.

[b-long]

Adding a note, that I think I'm seeing the same issue. However, I'll say I haven't investigated and it could be a different issue. My environment is Gitlab, using gitlab-runner as well as the Docker executor. Errors that I've seen:

  KeyError
  'POSTGRES_ENV_CI_RUNNER_DESCRIPTION'
  at /usr/local/lib/python3.7/os.py:681 in __getitem__
       677│         try:
       678│             value = self._data[self.encodekey(key)]
       679│         except KeyError:
       680│             # raise KeyError with the original key value
    →  681│             raise KeyError(key) from None
       682│         return self.decodevalue(value)
       683│ 
       684│     def __setitem__(self, key, value):
       685│         key = self.encodekey(key)

and

  KeyError
  'POSTGRES_ENV_CI_DEFAULT_BRANCH'
  at /usr/local/lib/python3.7/os.py:681 in __getitem__
       677│         try:
       678│             value = self._data[self.encodekey(key)]
       679│         except KeyError:
       680│             # raise KeyError with the original key value
    →  681│             raise KeyError(key) from None
       682│         return self.decodevalue(value)
       683│ 
       684│     def __setitem__(self, key, value):
       685│         key = self.encodekey(key)

Edit
I will also point out, this happens only some of the time. I don't know what causes it to occur.

[cglacet]

That's strange I got a similar error on gitlab CI (even though I don't get the same locally, even using the gitlab-runner):

 • Installing multidict (5.0.0)
  Stack trace:
  12  /usr/local/lib/python3.8/site-packages/poetry/installation/executor.py:202 in _execute_operation
      result = self._do_execute_operation(operation)
  11  /usr/local/lib/python3.8/site-packages/poetry/installation/executor.py:276 in _do_execute_operation
      result = getattr(self, "_execute_{}".format(method))(operation)
  10  /usr/local/lib/python3.8/site-packages/poetry/installation/executor.py:411 in _execute_install
      return self._install(operation)
   9  /usr/local/lib/python3.8/site-packages/poetry/installation/executor.py:437 in _install
      archive = self._download(operation)
   8  /usr/local/lib/python3.8/site-packages/poetry/installation/executor.py:580 in _download
      return self._download_link(operation, link)
   7  /usr/local/lib/python3.8/site-packages/poetry/installation/executor.py:589 in _download_link
      archive = self._download_archive(operation, link)
   6  /usr/local/lib/python3.8/site-packages/poetry/installation/executor.py:615 in _download_archive
      response = self._authenticator.request(
   5  /usr/local/lib/python3.8/site-packages/poetry/installation/authenticator.py:66 in request
      settings = session.merge_environment_settings(
   4  /usr/local/lib/python3.8/site-packages/requests/sessions.py:711 in merge_environment_settings
      env_proxies = get_environ_proxies(url, no_proxy=no_proxy)
   3  /usr/local/lib/python3.8/site-packages/requests/utils.py:775 in get_environ_proxies
      return getproxies()
   2  /usr/local/lib/python3.8/urllib/request.py:2502 in getproxies_environment
      for name, value in os.environ.items():
   1  /usr/local/lib/python3.8/_collections_abc.py:744 in __iter__
      yield (key, self._mapping[key])
  KeyError
  'VIRTUAL_ENV'
  at /usr/local/lib/python3.8/os.py:675 in __getitem__
       671│         try:
       672│             value = self._data[self.encodekey(key)]
       673│         except KeyError:
       674│             # raise KeyError with the original key value
    →  675│             raise KeyError(key) from None
       676│         return self.decodevalue(value)
       677│ 
       678│     def __setitem__(self, key, value):
       679│         key = self.encodekey(key)

On the other hand, locally I have the environment variable defined:

❯ echo $VIRTUAL_ENV
/Users/cglacet/.pyenv/versions/3.7.7/envs/env-name

The suggested fix did work for me too:

poetry config experimental.new-installer false

[gsemet]

I see this issue from time to time on our gitlab ci (kubernetes runner). I works pretty much all the time after a retry (so same environment, same container, same git commit)

[max-wittig]

Any chance that somebody could take a look? It would be really nice to be able to use the new installer and get the speed improvement.

[RobinFrcd]

@abn Managed to reproduce the issue locally (with poetry 1.1.5), it's a bit hacky though.

First, set a lot of env variables (10k will make your bash session very laggy):

for var in {1..10000}
do
  export v${var}=$var
done

pyproject.toml

[tool.poetry]
name = "poetry-demo"
version = "0.1.0"
description = ""
authors = ["RobinFrcd"]

[tool.poetry.dependencies]
python = "^3.7"
pendulum = "*"
boto3 = "*"
urllib3 = "*"
requests = "*"
certifi = "*"

[tool.poetry.dev-dependencies]
pytest = "^5.2"

[build-system]
requires = ["poetry-core>=1.0.0"]
build-backend = "poetry.core.masonry.api"

poetry install while now fail:

❯ poetry install
Installing dependencies from lock file

Package operations: 18 installs, 0 updates, 0 removals

  • Installing botocore (1.20.38): Failed

  KeyError

  'v8240'

  at ~/.pyenv/versions/3.7.9/lib/python3.7/os.py:681 in __getitem__
       677│         try:
       678│             value = self._data[self.encodekey(key)]
       679│         except KeyError:
       680│             # raise KeyError with the original key value
    →  681│             raise KeyError(key) from None
       682│         return self.decodevalue(value)
       683│ 
       684│     def __setitem__(self, key, value):
       685│         key = self.encodekey(key)

  • Installing importlib-metadata (3.7.3)
  • Installing pyparsing (2.4.7)

[abn]

@RobinFrcd thanks for posting that. However, I am finding it rather hard to reproduce this (see below for what I tried). Is this consistent for you? And if so, could there be something else in the environment that I might need to change to reproduce this?

podman run --rm -i --entrypoint bash python:3.7 <<EOF
for var in {1..10000}; do export v\${var}=\$var; done
set -xe
python -m pip install -q poetry
install -d foobar
pushd foobar
cat > pyproject.toml <<TOML
[tool.poetry]
name = "poetry-demo"
version = "0.1.0"
description = ""
authors = ["RobinFrcd"]

[tool.poetry.dependencies]
python = "^3.7"
pendulum = "*"
boto3 = "*"
urllib3 = "*"
requests = "*"
certifi = "*"

[tool.poetry.dev-dependencies]
pytest = "^5.2"

[build-system]
requires = ["poetry-core>=1.0.0"]
build-backend = "poetry.core.masonry.api"
TOML
poetry install
EOF

Edit: Had to go to 1..100000 to get it to reproduce.

[abn]

Good news is that I was able to verify that #3253 does indeed fix it. But would definitely like confirmation, can someone please try the above snippet but with the following installation?

python -m pip install -q git+https://github.com/python-poetry/poetry.git@refs/pull/3253/head

Alternatively install via pipx with a suffix.

pipx install --suffix=@3253 'poetry @ git+https://github.com/python-poetry/poetry.git@refs/pull/3253/head'

[RobinFrcd]

With "only" 10k env vars it was indeed not consistent at all. Had to increase the numbers to make it fail more often.

So, I installed #3253 and two great news:

• Doesn't fail any more with about 10 tests
• It seems it's much faster now (about 3x faster with 30k env vars)

Thank you so much for the fix! 👍

[pierresouchay]

Good news is that I was able to verify that #3253 does indeed fix it. But would definitely like confirmation, can someone please try the above snippet but with the following installation?

python -m pip install -q git+https://github.com/python-poetry/poetry.git@refs/pull/3253/head

Yes, we are impacted as well and your fix does fix our CI in Gitlab... can't wait for release 1.1.6 to be available!

Thank you @stephsamson !

[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.