devpi icon indicating copy to clipboard operation
devpi copied to clipboard

Timing out when attempting to downloading packages from PyPi

Open lsiden opened this issue 1 year ago • 10 comments

I installed devpi 6.8.0 and set it up as per instructions. When I then attempt pip install -i http://127.0.0.1:3141/root/pypi/+simple/ simplejson it times out. In this case, I am expecting devpi to download jsonsimple from pypi.org and cache it locally.

Looking in indexes: http://127.0.0.1:3141/root/pypi/+simple/
WARNING: Retrying (Retry(total=4, connect=None, read=None, redirect=None, status=None)) after connection broken by 'ReadTimeoutError("HTTPConnectionPool(host='127.0.0.1', port=3141): Read timed out. (read timeout=15)")': /root/pypi/+simple/simplejson/
WARNING: Retrying (Retry(total=3, connect=None, read=None, redirect=None, status=None)) after connection broken by 'ReadTimeoutError("HTTPConnectionPool(host='127.0.0.1', port=3141): Read timed out. (read timeout=15)")': /root/pypi/+simple/simplejson/
WARNING: Retrying (Retry(total=2, connect=None, read=None, redirect=None, status=None)) after connection broken by 'ReadTimeoutError("HTTPConnectionPool(host='127.0.0.1', port=3141): Read timed out. (read timeout=15)")': /root/pypi/+simple/simplejson/
WARNING: Retrying (Retry(total=1, connect=None, read=None, redirect=None, status=None)) after connection broken by 'ReadTimeoutError("HTTPConnectionPool(host='127.0.0.1', port=3141): Read timed out. (read timeout=15)")': /root/pypi/+simple/simplejson/
WARNING: Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'ReadTimeoutError("HTTPConnectionPool(host='127.0.0.1', port=3141): Read timed out. (read timeout=15)")': /root/pypi/+simple/simplejson/
ERROR: Could not find a version that satisfies the requirement simplejson (from versions: none)
ERROR: No matching distribution found for simplejson

$ pip list
Package                Version
---------------------- ---------
build                  0.10.0
cachelib               0.9.0
certifi                2022.12.7
charset-normalizer     3.1.0
click                  8.1.3
dnspython              2.3.0
Flask                  2.2.3
Flask-Caching          2.0.2
Flask-Cors             3.0.10
Flask-HTTPAuth         4.7.0
idna                   3.4
itsdangerous           2.1.2
Jinja2                 3.1.2
ldap3                  2.9.1
MarkupSafe             2.1.2
mysql-connector-python 8.0.29
packaging              23.0
pip                    23.0.1
pip-tools              6.12.3
protobuf               4.22.1
pyasn1                 0.4.8
PyJWT                  2.6.0
pymongo                4.3.3
pyproject_hooks        1.0.0
PyYAML                 6.0
requests               2.28.2
setuptools             58.1.0
six                    1.16.0
tomli                  2.0.1
urllib3                1.26.15
vzwnetops-flask        3.13.1
Werkzeug               2.2.3
wheel                  0.40.0

The server logs:

2023-04-03 14:21:23,333 INFO  NOCTX Loading node info from /home/sidela5/.devpi/server/.nodeinfo
2023-04-03 14:21:23,334 INFO  NOCTX wrote nodeinfo to: /home/sidela5/.devpi/server/.nodeinfo
2023-04-03 14:21:23,350 INFO  NOCTX running with role 'standalone'
2023-04-03 14:21:23,357 WARNI NOCTX No secret file provided, creating a new random secret. Login tokens issued before are invalid. Use --secretfile option to provide a persistent secret. You can create a proper secret with the devpi-gen-secret command.
2023-04-03 14:21:25,664 INFO  [ASYN] Starting asyncio event loop
2023-04-03 14:21:25,682 INFO  NOCTX devpi-server version: 6.8.0
2023-04-03 14:21:25,682 INFO  NOCTX serverdir: /home/sidela5/.devpi/server
2023-04-03 14:21:25,682 INFO  NOCTX uuid: d3e210f0cda2436fae65643add79dd89
2023-04-03 14:21:25,682 INFO  NOCTX serving at url: http://localhost:3141 (might be http://[localhost]:3141 for IPv6)
2023-04-03 14:21:25,682 INFO  NOCTX using 50 threads
2023-04-03 14:21:25,683 INFO  NOCTX bug tracker: https://github.com/devpi/devpi/issues
2023-04-03 14:21:25,683 INFO  NOCTX Hit Ctrl-C to quit.
2023-04-03 14:21:25,693 INFO  Serving on http://[::1]:3141
2023-04-03 14:21:25,693 INFO  Serving on http://127.0.0.1:3141
2023-04-03 14:21:54,932 INFO  [req0] GET /root/pypi/+simple/simplejson/
2023-04-03 14:22:09,949 INFO  [req1] GET /root/pypi/+simple/simplejson/
2023-04-03 14:22:25,467 INFO  [req2] GET /root/pypi/+simple/simplejson/
2023-04-03 14:22:41,486 INFO  [req3] GET /root/pypi/+simple/simplejson/
2023-04-03 14:22:58,504 INFO  [req4] GET /root/pypi/+simple/simplejson/
2023-04-03 14:23:17,520 INFO  [req5] GET /root/pypi/+simple/simplejson/
2023-04-03 14:24:01,585 ERROR [req1] [Rtx1] timeout after 5 seconds while getting data for 'simplejson'
2023-04-03 14:24:01,586 ERROR [req1] [Rtx1] while handling http://127.0.0.1:3141/root/pypi/+simple/simplejson/:
timeout after 5 seconds while getting data for 'simplejson'
2023-04-03 14:24:01,587 ERROR [req5] [Rtx1] timeout after 5 seconds while getting data for 'simplejson'
2023-04-03 14:24:01,588 ERROR [req5] [Rtx1] while handling http://127.0.0.1:3141/root/pypi/+simple/simplejson/:
timeout after 5 seconds while getting data for 'simplejson'
2023-04-03 14:24:01,588 ERROR [req4] [Rtx1] timeout after 5 seconds while getting data for 'simplejson'
2023-04-03 14:24:01,589 ERROR [req2] [Rtx1] timeout after 5 seconds while getting data for 'simplejson'
2023-04-03 14:24:01,589 ERROR [req3] [Rtx1] timeout after 5 seconds while getting data for 'simplejson'
2023-04-03 14:24:01,590 ERROR [req4] [Rtx1] while handling http://127.0.0.1:3141/root/pypi/+simple/simplejson/:
timeout after 5 seconds while getting data for 'simplejson'
2023-04-03 14:24:01,590 ERROR [req2] [Rtx1] while handling http://127.0.0.1:3141/root/pypi/+simple/simplejson/:
timeout after 5 seconds while getting data for 'simplejson'
2023-04-03 14:24:01,591 ERROR [req3] [Rtx1] while handling http://127.0.0.1:3141/root/pypi/+simple/simplejson/:
timeout after 5 seconds while getting data for 'simplejson'
2023-04-03 14:24:01,594 ERROR [req0] [Rtx1] timeout after 5 seconds while getting data for 'simplejson'
2023-04-03 14:24:01,594 ERROR [req0] [Rtx1] while handling http://127.0.0.1:3141/root/pypi/+simple/simplejson/:
timeout after 5 seconds while getting data for 'simplejson'

Also

$uname -a
Linux my-server 4.18.0-425.10.1.el8_7.x86_64 #1 SMP Wed Dec 14 16:00:01 EST 2022 x86_64 x86_64 x86_64 GNU/Linux

$ python -V
Python 3.10.4

Shouldn't devpi fetch simplejson from PyPi.org, cache it and serve it to pip? I tried increasing the timeout to 30 sec, but that didn't help. What else am I missing here?

Also, just wondering, what is the '+' for in "/root/+simple/"?

lsiden avatar Apr 03 '23 18:04 lsiden

It looks like your devpi-server can't connect to pypi.org. Try running with --debug to see more diagnostic output. Do you require a proxy to connect to the internet? Are there firewalls in place which prevent connections? Can you curl/wget pypi.org from your server?

Also, just wondering, what is the '+' for in "/root/+simple/"?

The + distinguishes the URL from packages, so there is no confusion to /root/pypi/simple the (possible) package.

fschulze avatar Apr 04 '23 05:04 fschulze

curl https://pypi.org/simple/ does get a (long) response.

After devpi-server --debug, pip install -i http://localhost:3141 simplejson produces:

2023-04-04 10:26:08,536 INFO  [req0] GET /simplejson/
2023-04-04 10:26:08,538 DEBUG [req0] [Rtx1] in-transaction 1
2023-04-04 10:26:08,541 DEBUG [req0] [Rtx1] closing transaction at 1
2023-04-04 10:26:08,541 DEBUG [req0] 404 Not Found 0.005s serial=1 length=0 type=text/html; charset=UTF-8
2023-04-04 10:26:08,553 INFO  [req1] GET /pip/
2023-04-04 10:26:08,553 DEBUG [req1] [Rtx1] in-transaction 1
2023-04-04 10:26:08,554 DEBUG [req1] [Rtx1] closing transaction at 1
2023-04-04 10:26:08,554 DEBUG [req1] 404 Not Found 0.001s serial=1 length=0 type=text/html; charset=UTF-8

Thank you for the insight on the '+' sign.

lsiden avatar Apr 04 '23 14:04 lsiden

You used -i http://localhost:3141 instead of -i http://localhost:3141/root/pypi/+simple/ when running with --debug. Please report results with the fixed URL.

fschulze avatar Apr 04 '23 15:04 fschulze

Sure.

$ pip install -i http://localhost:3141/root/pypi/+simple/ simplejson
Looking in indexes: http://localhost:3141/root/pypi/+simple/
WARNING: Retrying (Retry(total=4, connect=None, read=None, redirect=None, status=None)) after connection broken by 'ReadTimeoutError("HTTPConnectionPool(host='localhost', port=3141): Read timed out. (read timeout=15)")': /root/pypi/+simple/simplejson/

On the server:

2023-04-04 13:02:55,748 DEBUG Starting new HTTPS connection (1): pypi.org:443
2023-04-04 13:03:10,762 INFO  [req5] GET /root/pypi/+simple/simplejson/
2023-04-04 13:03:10,764 DEBUG [req5] [Rtx1] in-transaction 1

This will make several attempts and then time out.

lsiden avatar Apr 04 '23 17:04 lsiden

Also seeing this:

2023-04-04 13:05:02,481 DEBUG [req9] [Rtx1] closing transaction at 1
2023-04-04 13:05:02,481 DEBUG [req9] 502 Bad Gateway 44.155s serial=1 length=0 type=text/html; charset=UTF-8
2023-04-04 13:05:02,481 ERROR [req8] [Rtx1] timeout after 5 seconds while getting data for 'simplejson'
2023-04-04 13:05:02,481 ERROR [req8] [Rtx1] while handling http://localhost:3141/root/pypi/+simple/simplejson/:
timeout after 5 seconds while getting data for 'simplejson'

lsiden avatar Apr 04 '23 17:04 lsiden

I already cloned my own copy of devpi and I can start inserting debug traces after lunch. If you have any suggestions where to start that will make things easier for me (so I don't have to read all the code).

lsiden avatar Apr 04 '23 17:04 lsiden

Try starting from this line: https://github.com/devpi/devpi/blob/main/server/devpi_server/mirror.py#L535

fschulze avatar Apr 04 '23 17:04 fschulze

Simplejson may require Python 2.7 to download

zhenzi0322 avatar Apr 06 '23 06:04 zhenzi0322

@lsiden did you have a chance to look deeper into this?

fschulze avatar Oct 16 '23 12:10 fschulze

@fschulze Sorry I dropped the ball on this thread. No I didn’t look into it further. I punted and just use a directory /path/to/my-pypi/simple/… . I just have to be careful not to clobber already built wheels by bumping the SEMVER version numbers.

lsiden avatar Feb 09 '24 18:02 lsiden