Hey,
there now an error I see now the second time. This time it is in autopkgtest run for snapd on one of my PRs
error: cannot perform the following tasks:
- Download snap "core" (1688) from channel "stable" (Please buy core before installing it.)
The other time I saw this was when somebody reported this on IRC.
Any ideas what could be the problem here?
regards,
Simon
Looking a bit more through the logs shows
May 17 18:55:54 autopkgtest /usr/lib/snapd/snapd[9810]: logger.go:68: DEBUG: > "GET /anon/download-snap/99T7MUlRhtI3U0QFgl5mXXESAiSwt776_1688.snap HTTP/1.1\r\nHost: public.apps.ubuntu.com\r\nUser-Agent: snapd/2.26.3+git190.g198cb7d (series 16; classic; testing) ubuntu/16.04 (i386) linux/4.4.0-78-generic\r\nAccept: \r\nX-Ubuntu-Architecture: i386\r\nX-Ubuntu-Classic: true\r\nX-Ubuntu-No-Cdn: false\r\nX-Ubuntu-Series: 16\r\nX-Ubuntu-Wire-Protocol: 1\r\nAccept-Encoding: gzip\r\n\r\n"
May 17 18:55:54 autopkgtest snapd[9810]: 2017/05/17 18:55:54.846236 logger.go:68: DEBUG: > "GET /anon/download-snap/99T7MUlRhtI3U0QFgl5mXXESAiSwt776_1688.snap HTTP/1.1\r\nHost: public.apps.ubuntu.com\r\nUser-Agent: snapd/2.26.3+git190.g198cb7d (series 16; classic; testing) ubuntu/16.04 (i386) linux/4.4.0-78-generic\r\nAccept: \r\nX-Ubuntu-Architecture: i386\r\nX-Ubuntu-Classic: true\r\nX-Ubuntu-No-Cdn: false\r\nX-Ubuntu-Series: 16\r\nX-Ubuntu-Wire-Protocol: 1\r\nAccept-Encoding: gzip\r\n\r\n"
May 17 18:55:56 autopkgtest /usr/lib/snapd/snapd[9810]: logger.go:75: DEBUG: < "HTTP/1.1 401 UNAUTHORIZED\r\n"
May 17 18:55:56 autopkgtest snapd[9810]: 2017/05/17 18:55:56.099726 logger.go:75: DEBUG: < "HTTP/1.1 401 UNAUTHORIZED\r\n"
May 17 18:55:56 autopkgtest /usr/lib/snapd/snapd[9810]: task.go:303: DEBUG: 2017-05-17T18:55:56Z ERROR Please buy core before installing it.
May 17 18:55:56 autopkgtest snapd[9810]: 2017/05/17 18:55:56.103753 task.go:303: DEBUG: 2017-05-17T18:55:56Z ERROR Please buy core before installing it.
So for some reason we get a HTTP/1.1 401 UNAUTHORIZED back which actually should never haben for the core snap.
Fwiw, I saw a similar test failure in e.g. snap download tests and some other tests. It seems like the store had some issues in the last hours, I also noticed increased timeouts in our tests, e.g.:
May 17 18:49:56 autopkgtest snapd[16392]: 2017/05/17 18:49:56.988020 retry.go:61: DEBUG: The retry loop for https://search.apps.ubuntu.com/api/v1/snaps/details/test-snapd-control-consumer?channel=edge&fields=anon_download_url%2Carchitecture%2Cchannel%2Cdownload_sha3_384%2Csummary%2Cdescription%2Cdeltas%2Cbinary_filesize%2Cdownload_url%2Cepoch%2Cicon_url%2Clast_updated%2Cpackage_name%2Cprices%2Cpublisher%2Cratings_average%2Crevision%2Cscreenshot_urls%2Csnap_id%2Csupport_url%2Ccontact%2Ctitle%2Ccontent%2Cversion%2Corigin%2Cdeveloper_id%2Cprivate%2Cconfinement%2Cchannel_maps_list finished after 4 retries, elapsed time=40.008731626s, status: Get https://search.apps.ubuntu.com/api/v1/snaps/details/test-snapd-control-consumer?channel=edge&fields=anon_download_url%2Carchitecture%2Cchannel%2Cdownload_sha3_384%2Csummary%2Cdescription%2Cdeltas%2Cbinary_filesize%2Cdownload_url%2Cepoch%2Cicon_url%2Clast_updated%2Cpackage_name%2Cprices%2Cpublisher%2Cratings_average%2Crevision%2Cscreenshot_urls%2Csnap_id%2Csupport_url%2Ccontact%2Ctitle%2Ccontent%2Cversion%2Corigin%2Cdeveloper_id%2Cprivate%2Cconfinement%2Cchannel_maps_list: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)
the key is finished after 4 retries, elapsed time=40.008731626s, status: Get https://search.apps.ubuntu.com/api/v1/snaps/details/test-snapd-control-consumer?
i.e. snapd retried 4 times and for a total of 40s without success.
Interestingly your log and my log have similar timestamps.
At the moment a 401 is returned due to a network outage, and we know there was an outage at that time.
FYI, we have a fix to make a network outage return a more useful HTTP response but it has not been released yet. Hopefully soon.
We need to get this fixed into snapd itself right away. It felt like a bad idea at the time, and now it’s pretty obvious that it’s a bad idea to rely on general HTTP codes as meaning something specific.
We already had a discussion with you and Pete around fixing it somehow in snapd, we didn’t reach an agreement, we don’t have the right information at that point unless we shuffle some things in snap/info.go etc … otherwise the only cheap snapd approach is to make the error much more vague until the store does better. Of course here the store is turning what should be a 50x into a 401 , that’s an extreme case of bad error reporting.
Yeah, having the error more generic seems appropriate, and actually the only reasonable thing to do in such cases it seems.
Bug report here: https://bugs.launchpad.net/snapstore/+bug/1674879, fix includes proper response codes and auth headers and should be released soon.