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.


#10

Right now I’m getting ~ 6 MB/s. I guess this is fixed now - I hope it stays that way.


#11

Fwiw, I had the same problem today. Fastly was slow downloading the “brave” snap. After hitting “www.fastly-debug.com” things were good again.


#12

Hi there, I just signed up to confirm that the issue you encountered actually has to do with Internet Service Providers. And it has been plaguing other people in Europe as well, for instance customers of the German Telecom and Telia. The trace route you posted contains a certain fastly-ic address that looks very familiar to me. In fact and in my case, I’m a customer of the German Telecom and literally all Fastly traffic goes over Telia nodes. Here is one log I had been running for a good while:

WinMTR statistics

Host % Sent Recv Best Avrg Wrst Last
fritz.box 0 3631 3631 1 6 84 7
62.155.246.101 0 3631 3631 4 6 83 6
f-ed12-i.F.DE.NET.DTAG.DE 1 3623 3621 5 5 56 5
ffm-b4-link.telia.net 1 3619 3616 0 7 202 5
ffm-bb4-link.telia.net 0 3631 3631 5 5 33 5
ffm-b1-link.telia.net 1 3588 3577 5 8 50 6
fastly-ic-328449-ffm-b1.c.telia.net 5 3072 2931 5 8 57 6
151.101.129.140 4 3143 3020 13 14 695 14

Other Telia “fastly-ic” names that show up are fastly-ic-319195-ffm-b4.c.telia.net and fastly-ic-328448-ffm-b1.c.telia.net. It seems that literally all customers from the Telecom in Hungary and in Germany get their Fastly traffic routed through the hopelessly overloaded nodes from Telia. I can tell from experience that this has been oftentimes a major nuisance in the past. Quite a few gaming forums, like the ones at WarGaming, are filled with complains about Telia. I had my fair share of packet loss experiences with connections that go through Telia nodes as well. Very recently - and I mean today - sites like Reddit, Vimeo, Stackexchange and more sites that use Fastly are all affected by major slowdowns by Telia. So, unfortunately this is a bigger issue than you expected. Frankly, bigger than we all expected. The goal of the providers is probably either to force content providers to purchase a premium traffic lane for them, or they just want to save money and squeeze every traffic through a few tiny nodes. There were and are attempts of the German Telecom in Germany, as their peering policy is absolutely restricted.
Therefore, all of this is sadly no coincidence. And I fear nothing will change until the Telia nodes are completely congested, a necessary big outcry happens, or another content network provider that isn’t affected is used for data transfers.


#13

I don’t know if it’s a related problem or not, but I often get error 503, especially when downloading large snaps (like recently 0ad). Usually I have to wait maybe half an hour or so before retrying for the download to succeed.


#14

for next time, note it stops thinking they’re links if you backtick (mark “preformatted text”) them, also :slight_smile:

(I’m going to edit your comment to do this, and also to clean up the table)