Snap downloads 504

store
1

I am downloading a big snap (650mb), my internet is relatively slow but downloading from snap store is even slower (assuming slow servers is the cause).

What I see is that the download usually ends up being 504

om26er@IntelNUC:~$ snap download android-studio --candidate
Fetching snap "android-studio"
error: received an unexpected http response code (504) when trying to download https://068ed04f23.site.internapcdn.net/download-snap/VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap?t=2018-02-01T18:00:00Z&h=7bbc109159855cb9f983f36856443d48abf7447f

I believe the Ubuntu store expires the download url due to whatever reason. So please increase the URL expiry time from the server side. This is pretty big of an issue.

2

Thanks for reporting this issue.

In addition to increasing the expiry time, we may also be able to implement logic in the client side to retry the operation. The underlying transaction and task mechanism is already pretty good at supporting this… we’d just need to look into the specific error, and define how many times to attempt.

That said, yes, increasing the expiry time for the URL might be an easy first step. Can you please check how long that task took to error? You can find that information running snap changes.

3

I think its this change that took almost 1 hour

om26er@IntelNUC:~$ snap change 7
Status  Spawn                 Ready                 Summary
Done    2018-02-01T13:42:19Z  2018-02-01T14:41:58Z  Ensure prerequisites for "android-studio" are available
Undone  2018-02-01T13:42:19Z  2018-02-01T14:41:58Z  Download snap "android-studio" (30) from channel "candidate"
Done    2018-02-01T13:42:19Z  2018-02-01T14:41:57Z  Fetch and check assertions for snap "android-studio" (30)
Error   2018-02-01T13:42:19Z  2018-02-01T14:41:57Z  Mount snap "android-studio" (30)
Hold    2018-02-01T13:42:19Z  2018-02-01T14:41:57Z  Copy snap "android-studio" data
Hold    2018-02-01T13:42:19Z  2018-02-01T14:41:57Z  Setup snap "android-studio" (30) security profiles
Hold    2018-02-01T13:42:19Z  2018-02-01T14:41:57Z  Make snap "android-studio" (30) available to the system
Hold    2018-02-01T13:42:19Z  2018-02-01T14:41:57Z  Set automatic aliases for snap "android-studio"
Hold    2018-02-01T13:42:19Z  2018-02-01T14:41:57Z  Setup snap "android-studio" aliases
Hold    2018-02-01T13:42:19Z  2018-02-01T14:41:57Z  Run install hook of "android-studio" snap if present
Hold    2018-02-01T13:42:19Z  2018-02-01T14:41:57Z  Start snap "android-studio" (30) services
Hold    2018-02-01T13:42:19Z  2018-02-01T14:41:57Z  Run configure hook of "android-studio" snap if present

......................................................................
Mount snap "android-studio" (30)

2018-02-01T06:41:57-08:00 ERROR [start snap-android\x2dstudio-30.mount] failed with exit status 1: Job for snap-android\x2dstudio-30.mount failed.
See "systemctl  status "snap-android\\x2dstudio-30.mount"" and "journalctl  -xe" for details.

The interesting bit is that the download never succeeded and still snapd tried
Fetch and check assertions for snap "android-studio"
Which feels like another bug.

4

That one looks like it succeeded the download, and failed at mount time. That’s why the downloading of the assertions was done, which seems right.

Did you check to see what journalctl was reporting?

5

I restarted my system since then and journalctl doesn’t seem to have anything related to that time. Though systemctl status suggests there was some success

om26er@IntelNUC:~$ systemctl  status "snap-android\\x2dstudio-30.mount"
● snap-android\x2dstudio-30.mount - Mount unit for android-studio
   Loaded: loaded (/etc/systemd/system/snap-android\x2dstudio-30.mount; enabled; vendor preset: enabled)
   Active: active (mounted) since Thu 2018-02-01 06:48:47 PST; 2h 28min ago
    Where: /snap/android-studio/30
     What: /dev/loop0
    Tasks: 0 (limit: 4915)
   CGroup: /system.slice/snap-android\x2dstudio-30.mount

Feb 01 06:48:47 IntelNUC systemd[1]: Mounting Mount unit for android-studio...
Feb 01 06:48:47 IntelNUC systemd[1]: Mounted Mount unit for android-studio.

But snap list still does not show it as installed and neither does it appear in Gnome Shell’ apps list or in command line.

om26er@IntelNUC:/snap/android-studio$ snap list
Name   Version    Rev   Developer  Notes
core   16-2.30    3887  canonical  core
lxd    2.21       5522  canonical  -
skype  8.14.0.10  9     skype      classic

But it seems the directory /snap/android-studio/30 exists and it does have the actual source and I can launch the app from there.

Now I am totally confused. This is probably a bug in snapd in 18.04.

6

We’ll have a look into this this code path to ensure we don’t have anything leaving the mount unit around in the error path of the mount operation. That said, this is not a reason for the failure we observe, and it’s also not the error you got in the first console output you report in the top message. Something else happened in your system which is not listed above.

What is the actual change corresponding to the error you reported earlier?

7

Sorry, I was not able to find the change related to the issue (Listed all changes and none had that error) that I reported initially. I am trying to emulate that scenario again, will comment back.

8

Here, I timed it

om26er@IntelNUC:~$ time snap install android-studio --classic --candidate
Download snap "android-studio" (30) from channel "candidate"                                                                                                                                     55%  227kB/s 22.6merror: cannot perform the following tasks:
- Download snap "android-studio" (30) from channel "candidate" (received an unexpected http response code (504) when trying to download https://068ed04f23.site.internapcdn.net/download-snap/VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap?t=2018-02-01T19:00:00Z&h=ff83fb2dc692ff80a1e4614dcf57b0420b4a799c)

real	41m40.741s
user	0m27.726s
sys	0m10.506s

And the change is below

om26er@IntelNUC:~$ snap change 12
Status  Spawn                 Ready                 Summary
Done    2018-02-01T17:03:27Z  2018-02-01T17:45:07Z  Ensure prerequisites for "android-studio" are available
Error   2018-02-01T17:03:27Z  2018-02-01T17:45:07Z  Download snap "android-studio" (30) from channel "candidate"
Hold    2018-02-01T17:03:27Z  2018-02-01T17:45:07Z  Fetch and check assertions for snap "android-studio" (30)
Hold    2018-02-01T17:03:27Z  2018-02-01T17:45:07Z  Mount snap "android-studio" (30)
Hold    2018-02-01T17:03:27Z  2018-02-01T17:45:07Z  Copy snap "android-studio" data
Hold    2018-02-01T17:03:27Z  2018-02-01T17:45:07Z  Setup snap "android-studio" (30) security profiles
Hold    2018-02-01T17:03:27Z  2018-02-01T17:45:07Z  Make snap "android-studio" (30) available to the system
Hold    2018-02-01T17:03:27Z  2018-02-01T17:45:07Z  Set automatic aliases for snap "android-studio"
Hold    2018-02-01T17:03:27Z  2018-02-01T17:45:07Z  Setup snap "android-studio" aliases
Hold    2018-02-01T17:03:27Z  2018-02-01T17:45:07Z  Run install hook of "android-studio" snap if present
Hold    2018-02-01T17:03:27Z  2018-02-01T17:45:07Z  Start snap "android-studio" (30) services
Hold    2018-02-01T17:03:27Z  2018-02-01T17:45:07Z  Run configure hook of "android-studio" snap if present

......................................................................
Download snap "android-studio" (30) from channel "candidate"

2018-02-01T09:45:07-08:00 ERROR received an unexpected http response code (504) when trying to download https://068ed04f23.site.internapcdn.net/download-snap/VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap?t=2018-02-01T19:00:00Z&h=ff83fb2dc692ff80a1e4614dcf57b0420b4a799c
1 Like
9

Hmm, so you didn’t hit the 1 hr expiry in that case.

1 Like
10 
$ time snap install android-studio --classic --candidate
android-studio (candidate) 3.0.1.0 from 'snapcrafters' installed

real	4m16.708s
user	0m2.867s
sys	0m1.096s

So the snap itself is OK.

11

It does feel like a CDN issue.

12

Can you try with wget and debug+headers:

wget -dS --verbose https://api.snapcraft.io/api/v1/snaps/download/VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap
13

It wasn’t clear, do you want me to download that file completely and expect that to fail with a 504 or do you need the initial download information ?

14

I’m wondering if we we’ll see retries/etc if you attempt a full download w/wget. And the response headers will help if I need to raise a ticket w/the CDN provider.

15 
om26er@IntelNUC:~/Documents$ wget -dS --verbose https://api.snapcraft.io/api/v1/snaps/download/VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap
Setting --server-response (serverresponse) to 1
Setting --verbose (verbose) to 1
DEBUG output created by Wget 1.19.2 on linux-gnu.

Reading HSTS entries from /home/om26er/.wget-hsts
URI encoding = ‘UTF-8’
Converted file name 'VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap' (UTF-8) -> 'VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap' (UTF-8)
--2018-02-01 10:19:46--  https://api.snapcraft.io/api/v1/snaps/download/VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap
Resolving api.snapcraft.io (api.snapcraft.io)... 91.189.92.20, 91.189.92.19
Caching api.snapcraft.io => 91.189.92.20 91.189.92.19
Connecting to api.snapcraft.io (api.snapcraft.io)|91.189.92.20|:443... connected.
Created socket 3.
Releasing 0x00005573f9e74d60 (new refcount 1).
Initiating SSL handshake.
Handshake successful; connected socket 3 to SSL handle 0x00005573f9e74e80
certificate:
  subject: CN=api.snapcraft.io,OU=IS,O=Canonical Group Ltd,L=London,ST=London,C=GB
  issuer:  CN=DigiCert SHA2 Secure Server CA,O=DigiCert Inc,C=US
X509 certificate successfully verified and matches host api.snapcraft.io

---request begin---
GET /api/v1/snaps/download/VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap HTTP/1.1
User-Agent: Wget/1.19.2 (linux-gnu)
Accept: */*
Accept-Encoding: gzip
Host: api.snapcraft.io
Connection: Keep-Alive

---request end---
HTTP request sent, awaiting response... 
---response begin---
HTTP/1.1 302 FOUND
Server: gunicorn/19.7.1
Date: Thu, 01 Feb 2018 18:19:47 GMT
Content-Type: text/html; charset=utf-8
Content-Length: 535
Location: https://068ed04f23.site.internapcdn.net/download-snap/VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap?t=2018-02-01T22:00:00Z&h=87652663822aa979a0269310aae1623cfdfddb76
X-VCS-Revision: 5461845
X-Request-Id: 41b4f183-7d23-40f4-bf2d-822dd161e5af

---response end---

  HTTP/1.1 302 FOUND
  Server: gunicorn/19.7.1
  Date: Thu, 01 Feb 2018 18:19:47 GMT
  Content-Type: text/html; charset=utf-8
  Content-Length: 535
  Location: https://068ed04f23.site.internapcdn.net/download-snap/VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap?t=2018-02-01T22:00:00Z&h=87652663822aa979a0269310aae1623cfdfddb76
  X-VCS-Revision: 5461845
  X-Request-Id: 41b4f183-7d23-40f4-bf2d-822dd161e5af
Registered socket 3 for persistent reuse.
URI content encoding = ‘utf-8’
Location: https://068ed04f23.site.internapcdn.net/download-snap/VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap?t=2018-02-01T22:00:00Z&h=87652663822aa979a0269310aae1623cfdfddb76 [following]
Skipping 535 bytes of body: [<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 3.2 Final//EN">
<title>Redirecting...</title>
<h1>Redirecting...</h1>
<p>You should be redirected automatically to target URL: <a href="https://068ed04f23.site.internapcdn.net/download-snap/VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap?t=2018-02-01T22:00:00Z&amp;h=87652663822aa979a0269310aae1623cfdfddb76">https://068ed04f23.site.internapcdn.net/download-snap/VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap?t=2018-02-01T22:00:00Z&amp;h=87652663822aa979a0269310aae1623cfdfddb76</a>. Skipping 23 bytes of body: [ If not click the link.] done.
URI content encoding = None
Converted file name 'VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap' (UTF-8) -> 'VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap' (UTF-8)
--2018-02-01 10:19:47--  https://068ed04f23.site.internapcdn.net/download-snap/VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap?t=2018-02-01T22:00:00Z&h=87652663822aa979a0269310aae1623cfdfddb76
Resolving 068ed04f23.site.internapcdn.net (068ed04f23.site.internapcdn.net)... 203.190.126.15, 203.190.126.16, 203.190.126.13, ...
Caching 068ed04f23.site.internapcdn.net => 203.190.126.15 203.190.126.16 203.190.126.13 203.190.126.14
Connecting to 068ed04f23.site.internapcdn.net (068ed04f23.site.internapcdn.net)|203.190.126.15|:443... connected.
Created socket 4.
Releasing 0x00005573f9e8bf40 (new refcount 1).
Initiating SSL handshake.
Handshake successful; connected socket 4 to SSL handle 0x00005573f9e74740
certificate:
  subject: CN=*.https.internapcdn.net,O=Internap Network Services Corporation,L=Atlanta,ST=Georgia,C=US
  issuer:  CN=DigiCert SHA2 High Assurance Server CA,OU=www.digicert.com,O=DigiCert Inc,C=US
X509 certificate successfully verified and matches host 068ed04f23.site.internapcdn.net

---request begin---
GET /download-snap/VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap?t=2018-02-01T22:00:00Z&h=87652663822aa979a0269310aae1623cfdfddb76 HTTP/1.1
User-Agent: Wget/1.19.2 (linux-gnu)
Accept: */*
Accept-Encoding: gzip
Host: 068ed04f23.site.internapcdn.net
Connection: Keep-Alive

---request end---
HTTP request sent, awaiting response... 
---response begin---
HTTP/1.1 200 OK
Date: Thu, 01 Feb 2018 18:19:49 GMT
Content-Type: application/octet-stream
Content-Length: 681926656
Connection: keep-alive
Content-Disposition: attachment; filename=VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap
Vary: Accept-Encoding
Last-Modified: Thu, 01 Feb 2018 13:42:23 GMT
ETag: e8997b46-2bfc-4233-aac4-aa50b453c4ca
X-Bzr-Revision-Number: 7458
Cache-Control: max-age=86400
Strict-Transport-Security: max-age=2592000
X-Request-Id: WnMZP38AAQEAAFoF6dUAAABs1
Server: CDCE
X-INAP-Cache-Status: HIT
X-INAP-Server: cdce-hkg002-002.hkg002.internap.com
Accept-Ranges: bytes

---response end---

  HTTP/1.1 200 OK
  Date: Thu, 01 Feb 2018 18:19:49 GMT
  Content-Type: application/octet-stream
  Content-Length: 681926656
  Connection: keep-alive
  Content-Disposition: attachment; filename=VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap
  Vary: Accept-Encoding
  Last-Modified: Thu, 01 Feb 2018 13:42:23 GMT
  ETag: e8997b46-2bfc-4233-aac4-aa50b453c4ca
  X-Bzr-Revision-Number: 7458
  Cache-Control: max-age=86400
  Strict-Transport-Security: max-age=2592000
  X-Request-Id: WnMZP38AAQEAAFoF6dUAAABs1
  Server: CDCE
  X-INAP-Cache-Status: HIT
  X-INAP-Server: cdce-hkg002-002.hkg002.internap.com
  Accept-Ranges: bytes
Disabling further reuse of socket 3.
Closed 3/SSL 0x00005573f9e74e80
Registered socket 4 for persistent reuse.
Parsed Strict-Transport-Security max-age = 2592000, includeSubDomains = false
Added new HSTS host: 068ed04f23.site.internapcdn.net:443 (max-age: 2592000, includeSubdomains: false)
Length: 681926656 (650M) [application/octet-stream]
Saving to: ‘VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap’

VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap              10%[==========>                                                                                                           ]  65.10M   180KB/s    eta 81m 41s^VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap             100%[=====================================================================================================================>] 650.34M   416KB/s    in 35m 52s 

2018-02-01 10:55:41 (309 KB/s) - ‘VNTeIi51l6cIZ1gaWHwx0PoP7JaCb61c_30.snap’ saved [681926656/681926656]

Saving HSTS entries to /home/om26er/.wget-hsts
16

Of course it works when you want it to fail :confused: