Skipping page https://pypi.org/simple/idna/ because of Content-Type: unknown

[njsmith]

• Pip version: 10.0.1
• Python version: Python 3.5
• Operating system: MacOS

Description:

We've been hitting an intermittent error in downloading packages from PyPI using pip 10.0.1. So far it seems to only hit our MacOS, python 3.5 CI system (not python 3.6 on MacOS, and not any versions on other OSes). The actual package varies, but we always get an error like

  Could not find a version that satisfies the requirement pyOpenSSL (from -r test-requirements.txt (line 4)) (from versions: )

or

  Could not find a version that satisfies the requirement pytest>=3.3 (from -r test-requirements.txt (line 1)) (from versions: )

We finally managed to trigger the error with pip's -vvv flag enabled, and it said:

  Looking up "https://pypi.org/simple/idna/" in the cache
  Current age based on date: 31182
  Freshness lifetime from max-age: 600
  Freshness lifetime from request max-age: 600
  https://pypi.org:443 "GET /simple/idna/ HTTP/1.1" 304 0
  Skipping page https://pypi.org/simple/idna/ because of Content-Type: unknown
  Could not find a version that satisfies the requirement idna (from trio==0.4.0+dev) (from versions: )

(Full log here)

So to my ignorant eye, it looks like:

• pip found a cache entry for the https://pypi.org/simple/idna/ page
• It asked pypi if the cache was accurate, and pypi said "304 Not Modified", i.e., yeah, go ahead, use your cache
• Then pip somehow decided that... the cached entry, maybe, had "Content-Type: unknown" and freaked out?

I don't know how to debug further, so... help?

(our bug: python-trio/trio#508)

[mithrandi]

FWIW we're seeing the same thing on Debian Linux, only with PyPy. If this has something to do with the state of the cache, the OS/interpreter may be a red herring and some file only used on that platform is corrupt in the cache.

[njsmith]

@mithrandi is yours also intermittent and affecting different packages each time? Seems like a weird pattern for a corrupt state file, but could be...

[njsmith]

@mithrandi also... I notice that I'm getting this on our jenkins builder – if you're hitting it in twisted (?), then maybe it's in buildbot? I'm wondering if it might have something to do with multiple pips accessing the same cache simultaneously, in CI systems that have less isolation between builds than like, Travis-CI does.

[mithrandi]

@njsmith This is my day job's CI; it's a Docker container started by Drone.io. We run two concurrent builds (in separate containers, but sharing the same cache directory), one on CPython 2.7 (which I haven't seen fail this way) and one on PyPy (which seems to be failing quite frequently as of late), so your theory about concurrent access seems to hold up.

EDIT: Also, it seems to be totally different packages each time, so the concurrency seems more likely to be at fault than a permanently corrupt something in the cache.

[alex]

We've occasionally seen this in CI for pyca/cryptography, but on our Windows builders. Our windows builders are the only ones which share the cache between multiple concurrent builds, so that seems related 🤔

[njsmith]

Pip has some nice options for controlling cache access, like --cache-dir=$WHATEVER and --no-cache-dir, so I guess we might be able to check this hypothesis by e.g. disabling the cache in the build that's working and see if that fixes the build that's breaking. But that's tricky with an intermittent issue like this b/c it's hard to know whether it's fixed or whether you just got lucky :-/

[ssbarnea]

Apparently this problem started right after CDN migration last month and I would really be surprised not to be linked by it. On our CI system I identified at leat 130 failures and errors look like https://gist.github.com/ssbarnea/78df2a80137cca04ca72872b1d14498f#file-pypi-pip-failure-log-L34

The package name is irrelevant, and running again does not reproduce the same error.

Disabling the local cache would be a disaster as we had a huge number of builds and we would endup putting a very high load on the CDN. Also I doubt platform has anything to do with this as I can confirm that it does happen on RHEL/Centos/MacOS.

[JackLeo]

We identified the problem occurs when multiple jobs run pip install at the same time at the same node. As a workaround, we use --cache-dir option on pip and each unique step in the pipeline uses its own cache dir (/tmp/<pipeline>_<step_name>/), this bloats disk space use, but at least it's somewhat faster and does not produce load on CDN.
Also under Unix, pip should also respect XDG_CACHE_HOME so you might just need to export a single variable on each step. I will let you know if the problem re-emerges with this in place.

[ssbarnea]

I think I found a temporary workaround for avoiding this bug on Jenkins slaves with multiple workers: define XDG_CACHE_HOME=$HOME/.cache/$EXECUTOR_NUMBER on master configuration.

This means that each executor will have a different cache directory so they would avoid clashing each other. As the number of executors is limited this would limit bit the increase in disk space needed.

I hope that my comment would not be considered a reason for not fixing this issue as soon as possible as this bug does really break CI/CD systems.

[di]

I'm not sure how meaningful this is but I noticed in @ssbarnea's log, pip doesn't actually seem to be initiating a new connection to PyPI to get the 304.

Here's a debug log I reproduced when the cache is stale and pip reaches back out to PyPI and gets a 304:

1 location(s) to search for versions of deprecation:
* https://pypi.org/simple/deprecation/
Getting page https://pypi.org/simple/deprecation/
Looking up "https://pypi.org/simple/deprecation/" in the cache
Current age based on date: 10000
Freshness lifetime from max-age: 600
Freshness lifetime from request max-age: 600
Starting new HTTPS connection (1): pypi.org
https://pypi.org:443 "GET /simple/deprecation/ HTTP/1.1" 304 0
Analyzing links from page https://pypi.org/simple/deprecation/
...

Here's the log from https://gist.github.com/ssbarnea/78df2a80137cca04ca72872b1d14498f#file-pypi-pip-failure-log-L34:

1 location(s) to search for versions of deprecation:
* https://pypi.org/simple/deprecation/
Getting page https://pypi.org/simple/deprecation/
Looking up "https://pypi.org/simple/deprecation/" in the cache
Current age based on date: 6767
Freshness lifetime from max-age: 600
Freshness lifetime from request max-age: 600
https://pypi.org:443 "GET /simple/deprecation/ HTTP/1.1" 304 0
Skipping page https://pypi.org/simple/deprecation/ because of Content-Type: unknown
...

Note the lack of a Starting new HTTPS connection (1): pypi.org from urllib3.

[di]

I'd be curious if this is reproducible with 9.0.3, looks like two of the related vendored libraries (cachecontrol and requests) got updated since then.

[ssbarnea]

@di Most of our jobs are first upgrading pip and doing the rest after. This means that this problem reproduced with latest pip 10.0.1.