Frequent intermittent connection failures

[maroux]

• 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 GNU/Linux 10 (buster)
• Poetry version: 1.1.3
• Link of a Gist with the contents of your pyproject.toml file: https://gist.github.com/maroux/5bfc38375acd0e1c1a710fc0e62b8e93

Issue

Environment: Docker debian slim buster image running in Google Cloud Platform Cloud Build
Installation: poetry install -vvv --no-root --no-dev
Outcome: Fails with networking error intermittently, but frequently enough that upgrade to poetry v1.1 is blocked on solving this issue.
Notes: Older version (v1.0.9) works fine but is slow because of old installer.
Verbose logs:

16:05:17 Step #2 - "build": Skipping virtualenv creation, as specified in config file.
16:05:17 Step #2 - "build": Installing dependencies from lock file
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build": Finding the necessary packages for the current system
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build": Package operations: 17 installs, 1 update, 0 removals, 11 skipped
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":   ? Installing certifi (2020.6.20): Skipped for the following reason: Already installed
16:05:17 Step #2 - "build":   ? Installing chardet (3.0.4): Skipped for the following reason: Already installed
16:05:17 Step #2 - "build":   ? Installing idna (2.10): Skipped for the following reason: Already installed
16:05:17 Step #2 - "build":   ? Installing markupsafe (1.1.1)
16:05:17 Step #2 - "build":   ? Installing pyparsing (2.4.7): Skipped for the following reason: Already installed
16:05:17 Step #2 - "build":   ? Installing pytz (2020.1): Skipped for the following reason: Already installed
16:05:17 Step #2 - "build":   ? Installing six (1.15.0): Skipped for the following reason: Already installed
16:05:17 Step #2 - "build":   ? Installing urllib3 (1.25.10): Skipped for the following reason: Already installed
16:05:17 Step #2 - "build":   ? Installing alabaster (0.7.12)
16:05:17 Step #2 - "build":   ? Installing babel (2.8.0)
16:05:17 Step #2 - "build":   ? Updating colorama (0.4.4 -> 0.4.3): Skipped for the following reason: Not needed for the current environment
16:05:17 Step #2 - "build":   ? Installing docutils (0.16): Skipped for the following reason: Already installed
16:05:17 Step #2 - "build":   ? Installing imagesize (1.2.0)
16:05:17 Step #2 - "build":   ? Installing jinja2 (2.11.2)
16:05:17 Step #2 - "build":   ? Installing packaging (20.4): Skipped for the following reason: Already installed
16:05:17 Step #2 - "build":   ? Updating pygments (2.7.1 -> 2.6.1)
16:05:17 Step #2 - "build":   ? Installing requests (2.24.0): Skipped for the following reason: Already installed
16:05:17 Step #2 - "build":   ? Installing snowballstemmer (2.0.0)
16:05:17 Step #2 - "build":   ? Installing sphinxcontrib-applehelp (1.0.1)
16:05:17 Step #2 - "build":   ? Installing sphinxcontrib-devhelp (1.0.1)
16:05:17 Step #2 - "build":   ? Installing sphinxcontrib-htmlhelp (1.0.2)
16:05:17 Step #2 - "build":   ? Installing sphinxcontrib-jsmath (1.0.1)
16:05:17 Step #2 - "build":   ? Installing sphinxcontrib-qthelp (1.0.2)
16:05:17 Step #2 - "build":   ? Installing sphinxcontrib-serializinghtml (1.1.3)
16:05:17 Step #2 - "build":   ? Installing commonmark (0.9.1)
16:05:17 Step #2 - "build":   ? Installing sphinx (3.1.2)
16:05:17 Step #2 - "build": Retrying HTTP request in 0.5 seconds.
16:05:17 Step #2 - "build":   ? Installing recommonmark (0.5.0)
16:05:17 Step #2 - "build":   ? Installing sphinx-autodoc-typehints (1.11.0)
16:05:17 Step #2 - "build":   ? Installing sphinx-rtd-theme (0.4.3)
16:05:17 Step #2 - "build": Retrying HTTP request in 0.5 seconds.
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":   Stack trace:
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":   13  ~/.poetry/lib/poetry/installation/executor.py:199 in _execute_operation
16:05:17 Step #2 - "build":        197? 
16:05:17 Step #2 - "build":        198?             try:
16:05:17 Step #2 - "build":      ? 199?                 result = self._do_execute_operation(operation)
16:05:17 Step #2 - "build":        200?             except EnvCommandError as e:
16:05:17 Step #2 - "build":        201?                 if e.e.returncode == -2:
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":   12  ~/.poetry/lib/poetry/installation/executor.py:273 in _do_execute_operation
16:05:17 Step #2 - "build":        271?             return 0
16:05:17 Step #2 - "build":        272? 
16:05:17 Step #2 - "build":      ? 273?         result = getattr(self, "_execute_{}".format(method))(operation)
16:05:17 Step #2 - "build":        274? 
16:05:17 Step #2 - "build":        275?         if result != 0:
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":   11  ~/.poetry/lib/poetry/installation/executor.py:408 in _execute_install
16:05:17 Step #2 - "build":        406? 
16:05:17 Step #2 - "build":        407?     def _execute_install(self, operation):  # type: (Install) -> None
16:05:17 Step #2 - "build":      ? 408?         return self._install(operation)
16:05:17 Step #2 - "build":        409? 
16:05:17 Step #2 - "build":        410?     def _execute_update(self, operation):  # type: (Update) -> None
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":   10  ~/.poetry/lib/poetry/installation/executor.py:434 in _install
16:05:17 Step #2 - "build":        432?             archive = self._download_link(operation, Link(package.source_url))
16:05:17 Step #2 - "build":        433?         else:
16:05:17 Step #2 - "build":      ? 434?             archive = self._download(operation)
16:05:17 Step #2 - "build":        435? 
16:05:17 Step #2 - "build":        436?         operation_message = self.get_operation_message(operation)
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":    9  ~/.poetry/lib/poetry/installation/executor.py:575 in _download
16:05:17 Step #2 - "build":        573? 
16:05:17 Step #2 - "build":        574?     def _download(self, operation):  # type: (Operation) -> Path
16:05:17 Step #2 - "build":      ? 575?         link = self._chooser.choose_for(operation.package)
16:05:17 Step #2 - "build":        576? 
16:05:17 Step #2 - "build":        577?         return self._download_link(operation, link)
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":    8  ~/.poetry/lib/poetry/installation/chooser.py:60 in choose_for
16:05:17 Step #2 - "build":         58?         """
16:05:17 Step #2 - "build":         59?         links = []
16:05:17 Step #2 - "build":      ?  60?         for link in self._get_links(package):
16:05:17 Step #2 - "build":         61?             if link.is_wheel and not Wheel(link.filename).is_supported_by_environment(
16:05:17 Step #2 - "build":         62?                 self._env
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":    7  ~/.poetry/lib/poetry/installation/chooser.py:94 in _get_links
16:05:17 Step #2 - "build":         92?             repository = self._pool.repository(package.source_reference)
16:05:17 Step #2 - "build":         93? 
16:05:17 Step #2 - "build":      ?  94?         links = repository.find_links_for_package(package)
16:05:17 Step #2 - "build":         95? 
16:05:17 Step #2 - "build":         96?         hashes = [f["hash"] for f in package.files]
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":    6  ~/.poetry/lib/poetry/repositories/pypi_repository.py:245 in find_links_for_package
16:05:17 Step #2 - "build":        243? 
16:05:17 Step #2 - "build":        244?     def find_links_for_package(self, package):
16:05:17 Step #2 - "build":      ? 245?         json_data = self._get("pypi/{}/{}/json".format(package.name, package.version))
16:05:17 Step #2 - "build":        246?         if json_data is None:
16:05:17 Step #2 - "build":        247?             return []
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":    5  ~/.poetry/lib/poetry/repositories/pypi_repository.py:319 in _get
16:05:17 Step #2 - "build":        317?     def _get(self, endpoint):  # type: (str) -> Union[dict, None]
16:05:17 Step #2 - "build":        318?         try:
16:05:17 Step #2 - "build":      ? 319?             json_response = self.session.get(self._base_url + endpoint)
16:05:17 Step #2 - "build":        320?         except requests.exceptions.TooManyRedirects:
16:05:17 Step #2 - "build":        321?             # Cache control redirect loop.
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":    4  ~/.poetry/lib/poetry/_vendor/py3.7/requests/sessions.py:543 in get
16:05:17 Step #2 - "build":        541? 
16:05:17 Step #2 - "build":        542?         kwargs.setdefault('allow_redirects', True)
16:05:17 Step #2 - "build":      ? 543?         return self.request('GET', url, **kwargs)
16:05:17 Step #2 - "build":        544? 
16:05:17 Step #2 - "build":        545?     def options(self, url, **kwargs):
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":    3  ~/.poetry/lib/poetry/_vendor/py3.7/requests/sessions.py:530 in request
16:05:17 Step #2 - "build":        528?         }
16:05:17 Step #2 - "build":        529?         send_kwargs.update(settings)
16:05:17 Step #2 - "build":      ? 530?         resp = self.send(prep, **send_kwargs)
16:05:17 Step #2 - "build":        531? 
16:05:17 Step #2 - "build":        532?         return resp
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":    2  ~/.poetry/lib/poetry/_vendor/py3.7/requests/sessions.py:643 in send
16:05:17 Step #2 - "build":        641? 
16:05:17 Step #2 - "build":        642?         # Send the request
16:05:17 Step #2 - "build":      ? 643?         r = adapter.send(request, **kwargs)
16:05:17 Step #2 - "build":        644? 
16:05:17 Step #2 - "build":        645?         # Total elapsed time of the request (approximately)
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":    1  ~/.poetry/lib/poetry/_vendor/py3.7/cachecontrol/adapter.py:53 in send
16:05:17 Step #2 - "build":         51?             request.headers.update(self.controller.conditional_headers(request))
16:05:17 Step #2 - "build":         52? 
16:05:17 Step #2 - "build":      ?  53?         resp = super(CacheControlAdapter, self).send(request, **kw)
16:05:17 Step #2 - "build":         54? 
16:05:17 Step #2 - "build":         55?         return resp
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":   ConnectionError
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":   ('Connection aborted.', ConnectionResetError(104, 'Connection reset by peer'))
16:05:17 Step #2 - "build": 
16:05:17 Step #2 - "build":   at ~/.poetry/lib/poetry/_vendor/py3.7/requests/adapters.py:498 in send
16:05:17 Step #2 - "build":       494?                     low_conn.close()
16:05:17 Step #2 - "build":       495?                     raise
16:05:17 Step #2 - "build":       496? 
16:05:17 Step #2 - "build":       497?         except (ProtocolError, socket.error) as err:
16:05:17 Step #2 - "build":     ? 498?             raise ConnectionError(err, request=request)
16:05:17 Step #2 - "build":       499? 
16:05:17 Step #2 - "build":       500?         except MaxRetryError as e:
16:05:17 Step #2 - "build":       501?             if isinstance(e.reason, ConnectTimeoutError):
16:05:17 Step #2 - "build":       502?                 # TODO: Remove this in 3.0.0: see #2811
16:05:17 Step #2 - "build": 

[winpat]

I can confirm the same issue with Poetry 1.1.2. Every other install fails with a ConnectionError.

[abn]

Hmm, we saw this intermittently in our own CI a while ago, but was restricted to Cirrus CI FreeBSD instances (which runs on Google Cloud).

We might be able to do a bug fix to try recreate the session, but I suspect the issue might be at the process/scoket level.

@winpat what environment are you seeing your errors in?

I am really inclined to move http logic to httpx in the next minor to handle concurrent scenarios a bit better.

[winpat]

@winpat what environment are you seeing your errors in?

I observed the problem in various GitLab CI pipelines (GitLab.com, not self hosted). If I remember correctly then GitLab also uses GCP.

[dariobig]

We are having the same issue with our CircleCI builds (poetry 1.1.2, VM with ubuntu-1604:202004-01 image and python 3.7)

...
#21 423.2 
#21 423.2   ConnectionError
#21 423.2 
#21 423.2   ('Connection aborted.', ConnectionResetError(104, 'Connection reset by peer'))
#21 423.2 
#21 423.2   at ~/.poetry/lib/poetry/_vendor/py3.7/requests/adapters.py:498 in send
#21 423.4       494│                     low_conn.close()
#21 423.4       495│                     raise
#21 423.4       496│ 
#21 423.4       497│         except (ProtocolError, socket.error) as err:
#21 423.4     → 498│             raise ConnectionError(err, request=request)
#21 423.4       499│ 
#21 423.4       500│         except MaxRetryError as e:
#21 423.4       501│             if isinstance(e.reason, ConnectTimeoutError):
#21 423.4       502│                 # TODO: Remove this in 3.0.0: see #2811
#21 423.4 
#21 426.5   • Installing pytest-timeout (1.4.2)
#21 427.7   • Installing scipy (1.5.2)
#21 428.1   • Installing threadpoolctl (2.1.0)
#21 ERROR: executor failed running [/bin/sh -c $POETRY_BINARY install]: runc did not terminate sucessfully

[abn]

I am not entirely sure if this will fix the issue, since I am assuming the real issue here is some sort of networking layer throttling being hit. If some of you can please try the fix at #3230, it would be helpful to know if session reuse across thread exeuctions was the issue here.

Using pipx

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

Using a container (podman | docker)

podman run --rm -i --entrypoint bash python:3.8 <<EOF
set -xe
pip install -q git+https://github.com/python-poetry/poetry.git@refs/pull/3230/head
poetry new foobar
pushd foobar
sed -i /pytest/d pyproject.toml
poetry add pycowsay
# commands to reproduce your build
EOF

[abn]

@maroux @winpat @dariobig can you please verify if the fix above resolves the issue for your environments. If it does I can get that into the next patch.

[winpat]

@abn Thanks for your help! I've added your fix to a couple of different projects. It will take a day or two until I can whether it's working or not.

[maroux]

@maroux @winpat @dariobig can you please verify if the fix above resolves the issue for your environments. If it does I can get that into the next patch.

I've run it four times now and it's worked every time. I believe the PR does fix this issue.

[dariobig]

Unfortunately I can't test it in our environment, I've turned off "new installer" instead and that fixed the issue for us.

…

On Tue, Oct 20, 2020 at 11:37 AM Aniruddha Maru ***@***.***> wrote: @maroux <https://github.com/maroux> @winpat <https://github.com/winpat> @dariobig <https://github.com/dariobig> can you please verify if the fix above resolves the issue for your environments. If it does I can get that into the next patch. I've run it four times now and it's worked every time. I believe the PR does fix this issue. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#3219 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAABFE553C5KZ7MJQTQMHVTSLWVEPANCNFSM4SSUHTOA> .

[winpat]

@maroux @winpat @dariobig can you please verify if the fix above resolves the issue for your environments. If it does I can get that into the next patch.

I've run it four times now and it's worked every time. I believe the PR does fix this issue.

I also ran it a couple of times without any issues so far 👍.