Very slow download speeds while installing anything from the store


#1

I’m observing consistently slow download speeds from the snapcraft store when installing anything via snap install. Downloads linger around 200 kB/s while I can even upload to the store much faster.

To aid with the troubleshooting, @popey told me to set the following environment variables in /etc/environment:

SNAPD_DEBUG=1
SNAPD_DEBUG_HTTP=7

(tried SNAPD_DEBUG_HTTP=1 initially)

And restart snapd. I did so and tried to install pycharm (as a sufficiently large package I don’t yet have installed). Unfortunately, the only extra logging I got is the single line visible on the screenshot. Is it logging somewhere else?

I’m running Linux Mint 19.

Also, found this similar topic: Snap store download slow


#2

It is; setting those SNAPD_* variables makes it use system logging, so you can check detailed log output with:

sudo journalctl -u snapd


#3

I doubt this is an ISP-related issue, sometime the download speed will be capped to 30KiB/s at my end…


#4

No, definitely not ISP related. Only the snapcraft store is slow for me.


#5

Snaps from the Snap Store are hosted on Fastly CDN, you might want to check if other online resources also on Fastly CDN has the same problem(not sure how though)


#6

Try http://www.fastly-debug.com/, which will test your connectivity to various Fastly servers and your bandwidth to your closest one.

Where in the world are you, and which ISP are you using? What does mtr -c 10 -w -r fastly.cdn.snapcraft.io say?


Snap download very slow,
#7

Thanks for all the input, here are my answers:

journalctl

I restarted snapd, then installed pycharm-community. It took 27 minutes.

Oct 12 14:16:30 desktop systemd[1]: Started Snappy daemon.
Oct 12 14:16:30 desktop snapd[27087]: autorefresh.go:255: DEBUG: Next refresh scheduled for 2018-10-12 22:58:01.299573016 +0200 CEST.
Oct 12 14:16:30 desktop snapd[27087]: catalogrefresh.go:71: DEBUG: Catalog refresh starting now; next scheduled for 2018-10-13 14:16:30.073774404 +0200 CEST.
Oct 12 14:16:30 desktop snapd[27087]: retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/sections, attempt 1, elapsed time=5.477µs
Oct 12 14:16:30 desktop snapd[27087]: logger.go:69: DEBUG: > "GET /api/v1/snaps/sections HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.35.2 (series 16; classic) linuxmint/19 (amd64) linux/4.15.0-36-gen
Oct 12 14:16:30 desktop snapd[27087]: logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 286\r\nAge: 3069\r\nCache-Control: public, max-age=3600\r\nContent-Type: application/hal+json\r\nDate: Fri, 12 Oct 2
Oct 12 14:16:30 desktop snapd[27087]: retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/sections finished after 1 retries, elapsed time=297.524485ms, status: 200
Oct 12 14:16:30 desktop snapd[27087]: retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/names?confinement=strict%2Cclassic, attempt 1, elapsed time=7.607µs
Oct 12 14:16:30 desktop snapd[27087]: logger.go:69: DEBUG: > "GET /api/v1/snaps/names?confinement=strict%2Cclassic HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.35.2 (series 16; classic) linuxmint/19 (
Oct 12 14:16:30 desktop snapd[27087]: logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 329036\r\nAge: 94\r\nCache-Control: public, max-age=3600\r\nContent-Type: application/hal+json\r\nDate: Fri, 12 Oct
Oct 12 14:16:31 desktop snapd[27087]: retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/names?confinement=strict%2Cclassic finished after 1 retries, elapsed time=681.61569ms, status: 200
Oct 12 14:16:31 desktop snapd[27087]: catalogrefresh.go:75: DEBUG: Catalog refresh succeeded.
Oct 12 14:17:02 desktop snapd[27087]: api.go:1046: Installing snap "pycharm-community" revision unset
Oct 12 14:17:02 desktop snapd[27087]: store.go:2208: DEBUG: Deltas enabled. Adding header Snap-Accept-Delta-Format: xdelta3
Oct 12 14:17:02 desktop snapd[27087]: retry.go:40: DEBUG: Retrying https://api.snapcraft.io/v2/snaps/refresh, attempt 1, elapsed time=3.862µs
Oct 12 14:17:02 desktop snapd[27087]: logger.go:69: DEBUG: > "POST /v2/snaps/refresh HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.35.2 (series 16; classic) linuxmint/19 (amd64) linux/4.15.0-36-generic
Oct 12 14:17:02 desktop snapd[27087]: logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1843\r\nContent-Type: application/json\r\nDate: Fri, 12 Oct 2018 12:17:05 GMT\r\nServer: gunicorn/19.7.1\r\nSnap-Sto
Oct 12 14:17:02 desktop snapd[27087]: retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/v2/snaps/refresh finished after 1 retries, elapsed time=251.615736ms, status: 200
Oct 12 14:17:02 desktop snapd[27087]: daemon.go:273: DEBUG: pid=27604;uid=0;socket=/run/snapd.socket;@ POST /v2/snaps/pycharm-community 270.664481ms 202
Oct 12 14:17:02 desktop snapd[27087]: taskrunner.go:418: DEBUG: Running task 2147 on Do: Ensure prerequisites for "pycharm-community" are available
Oct 12 14:17:02 desktop snapd[27087]: taskrunner.go:418: DEBUG: Running task 2148 on Do: Download snap "pycharm-community" (85) from channel "stable"
Oct 12 14:17:02 desktop snapd[27087]: store.go:1337: DEBUG: Available deltas returned by store: []
Oct 12 14:17:02 desktop snapd[27087]: store.go:1369: DEBUG: Starting download of "/var/lib/snapd/snaps/pycharm-community_85.snap.partial".
Oct 12 14:17:02 desktop snapd[27087]: retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/download/Qo9GiW9eyzgN1tXmWpQ9gdstdFsj4K7E_85.snap, attempt 1, elapsed time=7.092µs
Oct 12 14:17:02 desktop snapd[27087]: logger.go:69: DEBUG: > "GET /api/v1/snaps/download/Qo9GiW9eyzgN1tXmWpQ9gdstdFsj4K7E_85.snap HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.35.2 (series 16; classic)
Oct 12 14:17:03 desktop snapd[27087]: logger.go:76: DEBUG: < "HTTP/1.1 302 FOUND\r\nContent-Length: 513\r\nContent-Type: text/html; charset=utf-8\r\nDate: Fri, 12 Oct 2018 12:17:05 GMT\r\nLocation: https://fastly.
Oct 12 14:17:03 desktop snapd[27087]: logger.go:69: DEBUG: > "GET /download-origin/fastly/Qo9GiW9eyzgN1tXmWpQ9gdstdFsj4K7E_85.snap?token=1539360000_b6a7874588475d503df2936a5a6c47b6c6e14118 HTTP/1.1\r\nHost: fastly
Oct 12 14:17:03 desktop snapd[27087]: logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 237490176\r\nAccept-Ranges: bytes\r\nAccept-Ranges: bytes\r\nAge: 524\r\nCache-Control: max-age=86400\r\nConnection:
Oct 12 14:44:54 desktop snapd[27087]: store.go:1559: DEBUG: Download succeeded in 1671.638s (142kB/s).
Oct 12 14:44:54 desktop snapd[27087]: taskrunner.go:418: DEBUG: Running task 2149 on Do: Fetch and check assertions for snap "pycharm-community" (85)
Oct 12 14:44:55 desktop snapd[27087]: retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/snap-revision/W2Oa4vkwI6c9jQIrL-FNpTYCsYPwvneW8h-CH9uDkebXjk7tvxxZQyIejrhtli70?max-format=0, atte
Oct 12 14:44:55 desktop snapd[27087]: logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/snap-revision/W2Oa4vkwI6c9jQIrL-FNpTYCsYPwvneW8h-CH9uDkebXjk7tvxxZQyIejrhtli70?max-format=0 HTTP/1.1\r\nHost: api.snapcraf
Oct 12 14:44:55 desktop snapd[27087]: logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1098\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Fri, 12 Oct 2018 12:44:57 GMT\r\nServer: gunicorn/19.7
Oct 12 14:44:55 desktop snapd[27087]: retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/snap-revision/W2Oa4vkwI6c9jQIrL-FNpTYCsYPwvneW8h-CH9uDkebXjk7tvxxZQyIejrhtli70?max-form
Oct 12 14:44:55 desktop snapd[27087]: retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/Qo9GiW9eyzgN1tXmWpQ9gdstdFsj4K7E?max-format=2, attempt 1, elapsed time=3.266µ
Oct 12 14:44:55 desktop snapd[27087]: logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/snap-declaration/16/Qo9GiW9eyzgN1tXmWpQ9gdstdFsj4K7E?max-format=2 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/
Oct 12 14:44:55 desktop snapd[27087]: logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1034\r\nAge: 7\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Fri, 12 Oct 2018 12:44:50 GMT\r\nServer: gun
Oct 12 14:44:55 desktop snapd[27087]: retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/Qo9GiW9eyzgN1tXmWpQ9gdstdFsj4K7E?max-format=2 finished after 1 retr
Oct 12 14:44:55 desktop snapd[27087]: retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/account/28zEonXNoBLvIB7xneRbltOsp0Nf7DwS?max-format=0, attempt 1, elapsed time=5.225µs
Oct 12 14:44:55 desktop snapd[27087]: logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/account/28zEonXNoBLvIB7xneRbltOsp0Nf7DwS?max-format=0 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.35.2 (seri
Oct 12 14:44:55 desktop snapd[27087]: logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1006\r\nAge: 1\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Fri, 12 Oct 2018 12:44:56 GMT\r\nServer: gun
Oct 12 14:44:55 desktop snapd[27087]: retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/account/28zEonXNoBLvIB7xneRbltOsp0Nf7DwS?max-format=0 finished after 1 retries, elapsed
Oct 12 14:44:55 desktop snapd[27087]: retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/account-key/BWDEoaqyr25nF5SNCvEv2v7QnM9QsfCc0PBMYD_i2NGSQ32EF2d4D0hqUel3m8ul?max-format=0, attemp
Oct 12 14:44:55 desktop snapd[27087]: logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/account-key/BWDEoaqyr25nF5SNCvEv2v7QnM9QsfCc0PBMYD_i2NGSQ32EF2d4D0hqUel3m8ul?max-format=0 HTTP/1.1\r\nHost: api.snapcraft.
Oct 12 14:44:55 desktop snapd[27087]: logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 2452\r\nAge: 63\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Fri, 12 Oct 2018 12:43:54 GMT\r\nServer: gu
Oct 12 14:44:55 desktop snapd[27087]: retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/account-key/BWDEoaqyr25nF5SNCvEv2v7QnM9QsfCc0PBMYD_i2NGSQ32EF2d4D0hqUel3m8ul?max-format
Oct 12 14:44:55 desktop snapd[27087]: taskrunner.go:418: DEBUG: Running task 2150 on Do: Mount snap "pycharm-community" (85)
Oct 12 14:44:56 desktop snapd[27087]: taskrunner.go:418: DEBUG: Running task 2151 on Do: Copy snap "pycharm-community" data
Oct 12 14:44:56 desktop snapd[27087]: taskrunner.go:418: DEBUG: Running task 2152 on Do: Setup snap "pycharm-community" (85) security profiles
Oct 12 14:44:56 desktop snapd[27087]: taskrunner.go:418: DEBUG: Running task 2153 on Do: Make snap "pycharm-community" (85) available to the system
Oct 12 14:44:56 desktop snapd[27087]: desktop.go:188: DEBUG: update-desktop-database successful
Oct 12 14:44:56 desktop snapd[27087]: taskrunner.go:418: DEBUG: Running task 2154 on Do: Automatically connect eligible plugs and slots of snap "pycharm-community"
Oct 12 14:44:56 desktop snapd[27087]: taskrunner.go:418: DEBUG: Running task 2155 on Do: Set automatic aliases for snap "pycharm-community"
Oct 12 14:44:56 desktop snapd[27087]: taskrunner.go:418: DEBUG: Running task 2156 on Do: Setup snap "pycharm-community" aliases
Oct 12 14:44:56 desktop snapd[27087]: taskrunner.go:418: DEBUG: Running task 2157 on Do: Run install hook of "pycharm-community" snap if present
Oct 12 14:44:56 desktop snapd[27087]: taskrunner.go:418: DEBUG: Running task 2158 on Do: Start snap "pycharm-community" (85) services
Oct 12 14:44:56 desktop snapd[27087]: taskrunner.go:418: DEBUG: Running task 2159 on Do: Run configure hook of "pycharm-community" snap if present
Oct 12 14:44:56 desktop snapd[27087]: daemon.go:273: DEBUG: pid=27604;uid=0;socket=/run/snapd.socket;@ GET /v2/snaps?snaps=pycharm-community 1.231917ms 200

ISP

I’m located in Budapest, Hungary and my ISP is Magyar Telekom (subsidiary of Deutsche Telekom). Internet speed in Hungary is overall pretty good, so I doubt that this is ISP-related (and I only get these 2MBit caps when downloading from the snap store.

fastly

I let it run for a couple of minutes but it doesn’t seem to finish (I don’t know how long I’m supposed to wait). The closest server is FRA.

image

(I redacted my public IP)

mtr output:

[I] ➜ mtr -c 10 -w -r fastly.cdn.snapcraft.io
Start: 2018-10-12T14:56:47+0200
HOST: desktop                             Loss%   Snt   Last   Avg  Best  Wrst StDev
  1.|-- _gateway                             0.0%    10    0.2   0.2   0.2   0.3   0.0
  2.|-- 192.168.1.254                        0.0%    10    0.4   0.6   0.4   2.0   0.5
  3.|-- 145.236.238.131                      0.0%    10   16.0  16.5  15.0  18.7   1.3
  4.|-- 81.183.0.37                          0.0%    10   15.7  16.7  15.3  18.7   1.5
  5.|-- 81.183.0.37                          0.0%    10   18.2  17.7  15.6  19.7   1.4
  6.|-- 81.183.3.129                         0.0%    10   15.3  16.1  15.0  18.3   1.4
  7.|-- 80.157.204.37                        0.0%    10   25.3  26.3  25.0  28.7   1.4
  8.|-- 217.239.55.138                       0.0%    10   29.1  28.1  26.0  30.3   1.3
  9.|-- 80.150.168.122                       0.0%    10   33.9  35.4  33.9  37.2   1.1
 10.|-- prag-bb1-link.telia.net              0.0%    10   31.0  32.5  30.8  35.6   1.6
 11.|-- ffm-bb3-link.telia.net               0.0%    10   40.0  39.2  37.3  40.8   1.4
 12.|-- ffm-b1-link.telia.net                0.0%    10   38.2  40.2  37.5  44.2   2.3
 13.|-- fastly-ic-328448-ffm-b1.c.telia.net  0.0%    10   39.9  40.3  36.8  47.1   3.3
 14.|-- 151.101.14.217                       0.0%    10   47.6  45.9  44.5  47.6   1.3

192.168.1.254 is my broadband modem.


#8

Do you have an adblocker enabled? The domain that fastly-debug.com uses for testing is fastly-analytics.com, which is blocked by eg. uBlock Origin.


#9

Good hunch, that’s exactly what the problem was. Here’s the full output:

On that note, I also have DNS blocking via pihole; I checked the logs but I didn’t find anything fastly or snap-related.