poetry install fails on KeyError even for defined environment variables

[pepastach]

• [x] I am on the latest Poetry version.
• [x] I have searched the issues of this repo and believe that this is not a duplicate.
• [x] 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.

[Jihadik]

I'm also seeing spurious errors like this one:

Connection pool is full, discarding connection: pypi.org
  Stack trace:
  13  ~/.poetry/lib/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:
  12  ~/.poetry/lib/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:
  11  ~/.poetry/lib/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
  10  ~/.poetry/lib/poetry/installation/executor.py:434 in _install
       432│             archive = self._download_link(operation, Link(package.source_url))
       433│         else:
     → 434│             archive = self._download(operation)
       435│ 
       436│         operation_message = self.get_operation_message(operation)
   9  ~/.poetry/lib/poetry/installation/executor.py:575 in _download
       573│ 
       574│     def _download(self, operation):  # type: (Operation) -> Path
     → 575│         link = self._chooser.choose_for(operation.package)
       576│ 
       577│         return self._download_link(operation, link)
   8  ~/.poetry/lib/poetry/installation/chooser.py:60 in choose_for
        58│         """
        59│         links = []
     →  60│         for link in self._get_links(package):
        61│             if link.is_wheel and not Wheel(link.filename).is_supported_by_environment(
        62│                 self._env
   7  ~/.poetry/lib/poetry/installation/chooser.py:94 in _get_links
        92│             repository = self._pool.repository(package.source_reference)
        93│ 
     →  94│         links = repository.find_links_for_package(package)
        95│ 
        96│         hashes = [f["hash"] for f in package.files]
   6  ~/.poetry/lib/poetry/repositories/pypi_repository.py:245 in find_links_for_package
       243│ 
       244│     def find_links_for_package(self, package):
     → 245│         json_data = self._get("pypi/{}/{}/json".format(package.name, package.version))
       246│         if json_data is None:
       247│             return []
   5  ~/.poetry/lib/poetry/repositories/pypi_repository.py:319 in _get
       317│     def _get(self, endpoint):  # type: (str) -> Union[dict, None]
       318│         try:
     → 319│             json_response = self.session.get(self._base_url + endpoint)
       320│         except requests.exceptions.TooManyRedirects:
       321│             # Cache control redirect loop.
   4  ~/.poetry/lib/poetry/_vendor/py3.7/requests/sessions.py:543 in get
       541│ 
       542│         kwargs.setdefault('allow_redirects', True)
     → 543│         return self.request('GET', url, **kwargs)
       544│ 
       545│     def options(self, url, **kwargs):
   3  ~/.poetry/lib/poetry/_vendor/py3.7/requests/sessions.py:530 in request
       528│         }
       529│         send_kwargs.update(settings)
     → 530│         resp = self.send(prep, **send_kwargs)
       531│ 
       532│         return resp
   2  ~/.poetry/lib/poetry/_vendor/py3.7/requests/sessions.py:643 in send
       641│ 
       642│         # Send the request
     → 643│         r = adapter.send(request, **kwargs)
       644│ 
       645│         # Total elapsed time of the request (approximately)
   1  ~/.poetry/lib/poetry/_vendor/py3.7/cachecontrol/adapter.py:53 in send
        51│             request.headers.update(self.controller.conditional_headers(request))
        52│ 
     →  53│         resp = super(CacheControlAdapter, self).send(request, **kw)
        54│ 
        55│         return resp
  ConnectionError
  ('Connection aborted.', ConnectionResetError(104, 'Connection reset by peer'))
  at ~/.poetry/lib/poetry/_vendor/py3.7/requests/adapters.py:498 in send
      494│                     low_conn.close()
      495│                     raise
      496│ 
      497│         except (ProtocolError, socket.error) as err:
    → 498│             raise ConnectionError(err, request=request)
      499│ 
      500│         except MaxRetryError as e:
      501│             if isinstance(e.reason, ConnectTimeoutError):
      502│                 # TODO: Remove this in 3.0.0: see #2811

which causes poetry install to exit with code 1. It might be caused by parallel install.
@pepastach, have you tried disabling parallel installs?

[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 https://github.com/python-poetry/poetry/issues/3219#issuecomment-710718687. 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:

```bash
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)

[glg-nnguyen]

I have this issue and sometimes it just doesn't go away.