The problem is visible in spread runs on Travis. The problem happens when downloading snaps from the store.
The sequence of events is as follows:
- snapd sends GET HTTP/1.1 request to the store
- store responds with HTTP/1.1 302 FOUND and passes
Location: <fastly CDN> - snapd attempts GET HTTP/1.1 to the provided url
- CDN responds with 200 OK HTTP/2.0 (protocol got upgraded?)
- Golang’s net/http raises
http.http2StreamError{StreamID:0x1, Code:0x1, Cause:error(nil)}
It’s hard to catch the requests as the CDN URL carries a token that seems to expire after some time.
Example log:
Aug 07 06:03:20 aug070543-458654 snapd[2466]: store.go:1382: DEBUG: Starting download of "/var/lib/snapd/snaps/test-snapd-go-webserver_13.snap.partial".
Aug 07 06:03:20 aug070543-458654 snapd[2466]: retry.go:49: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/download/DVvhXhpa9oJjcm0rnxfxftH1oo5vTW1M_13.snap, attempt 1, elapsed time=12.903µs
Aug 07 06:03:20 aug070543-458654 snapd[2466]: logger.go:67: DEBUG: > "GET /api/v1/snaps/download/DVvhXhpa9oJjcm0rnxfxftH1oo5vTW1M_13.snap HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/1337.2.40 (series 16; classic; testing) ubuntu/16.04 (i386) linux/4.4.0-157-generic\r\nAccept: \r\nSnap-Cdn: cloud-name=\"gce\" region=\"us-east1\" availability-zone=\"us-east1-b\"\r\nX-Device-Authorization: Macaroon root=\"MDAxZWxvY2F0aW9uIGFwaS5zbmFwY3JhZnQuaW8KMDAxZWlkZW50aWZpZXIgZGV2aWNlLXNlc3Npb24KMDA0MGNpZCBhcGkuc25hcGNyYWZ0LmlvfHZhbGlkX3NpbmNlfDIwMTktMDgtMDdUMDU6NDk6NDcuNTkwOTAyCjAwNDZjaWQgYXBpLnNuYXBjcmFmdC5pb3xzZXNzaW9ufDRjYWYxZGVjLTY0YzYtNDUwMi05MGUwLTM4MmM5NTczYjY1YwowMDliY2lkIGFwaS5zbmFwY3JhZnQuaW98ZGV2aWNlfHsibW9kZWwiOiAiZ2VuZXJpYy1jbGFzc2ljIiwgInNlcmlhbCI6ICI1OGJjMWY0Yi0zZTQ3LTQ4M2QtYjJjYi1kYTczY2E0OWExNTkiLCAiYnJhbmQiOiAiZ2VuZXJpYyIsICJhdXRob3JpdHkiOiAiZ2VuZXJpYyJ9CjAwMjBjaWQgYXBpLnNuYXBjcmFmdC5pb3xzdG9yZXwKMDAyZnNpZ25hdHVyZSDgX_uK2dJieqLCL5WabHQvt9i1ECG5GUu9D5I7ffvYdAo\"\r\nX-Ubuntu-Architecture: i386\r\nX-Ubuntu-Classic: true\r\nX-Ubuntu-Series: 16\r\nX-Ubuntu-Wire-Protocol: 1\r\nAccept-Encoding: gzip\r\n\r\n"
Aug 07 06:03:20 aug070543-458654 snapd[2466]: logger.go:74: DEBUG: < "HTTP/1.1 302 FOUND\r\nContent-Length: 513\r\nContent-Type: text/html; charset=utf-8\r\nDate: Wed, 07 Aug 2019 06:03:20 GMT\r\nLocation: https://fastly.cdn.snapcraft.io/download-origin/fastly/DVvhXhpa9oJjcm0rnxfxftH1oo5vTW1M_13.snap?token=1565172000_65c986ad70720045b74b36859cd98ad98d39f92b\r\nServer: gunicorn/19.7.1\r\nSnap-Store-Version: 15\r\nX-Request-Id: 23E344FEAE2E0A325C8501BB5D4A69A83DF153A6\r\nX-Vcs-Revision: c0e0e44\r\nX-View-Name: snapdevicegw.webapi_download.snap_download\r\n\r\n"
Aug 07 06:03:20 aug070543-458654 snapd[2466]: logger.go:67: DEBUG: > "GET /download-origin/fastly/DVvhXhpa9oJjcm0rnxfxftH1oo5vTW1M_13.snap?token=1565172000_65c986ad70720045b74b36859cd98ad98d39f92b HTTP/1.1\r\nHost: fastly.cdn.snapcraft.io\r\nUser-Agent: snapd/1337.2.40 (series 16; classic; testing) ubuntu/16.04 (i386) linux/4.4.0-157-generic\r\nAccept: \r\nReferer: https://api.snapcraft.io/api/v1/snaps/download/DVvhXhpa9oJjcm0rnxfxftH1oo5vTW1M_13.snap\r\nSnap-Cdn: cloud-name=\"gce\" region=\"us-east1\" availability-zone=\"us-east1-b\"\r\nX-Device-Authorization: Macaroon root=\"MDAxZWxvY2F0aW9uIGFwaS5zbmFwY3JhZnQuaW8KMDAxZWlkZW50aWZpZXIgZGV2aWNlLXNlc3Npb24KMDA0MGNpZCBhcGkuc25hcGNyYWZ0LmlvfHZhbGlkX3NpbmNlfDIwMTktMDgtMDdUMDU6NDk6NDcuNTkwOTAyCjAwNDZjaWQgYXBpLnNuYXBjcmFmdC5pb3xzZXNzaW9ufDRjYWYxZGVjLTY0YzYtNDUwMi05MGUwLTM4MmM5NTczYjY1YwowMDliY2lkIGFwaS5zbmFwY3JhZnQuaW98ZGV2aWNlfHsibW9kZWwiOiAiZ2VuZXJpYy1jbGFzc2ljIiwgInNlcmlhbCI6ICI1OGJjMWY0Yi0zZTQ3LTQ4M2QtYjJjYi1kYTczY2E0OWExNTkiLCAiYnJhbmQiOiAiZ2VuZXJpYyIsICJhdXRob3JpdHkiOiAiZ2VuZXJpYyJ9CjAwMjBjaWQgYXBpLnNuYXBjcmFmdC5pb3xzdG9yZXwKMDAyZnNpZ25hdHVyZSDgX_uK2dJieqLCL5WabHQvt9i1ECG5GUu9D5I7ffvYdAo\"\r\nX-Ubuntu-Architecture: i386\r\nX-Ubuntu-Classic: true\r\nX-Ubuntu-Series: 16\r\nX-Ubuntu-Wire-Protocol: 1\r\nAccept-Encoding: gzip\r\n\r\n"
Aug 07 06:03:21 aug070543-458654 snapd[2466]: logger.go:74: DEBUG: < "HTTP/2.0 200 OK\r\nContent-Length: 1744896\r\nAccept-Ranges: bytes\r\nAge: 0\r\nCache-Control: max-age=86400\r\nContent-Disposition: attachment; filename=DVvhXhpa9oJjcm0rnxfxftH1oo5vTW1M_13.snap\r\nContent-Type: application/octet-stream\r\nDate: Wed, 07 Aug 2019 06:03:21 GMT\r\nEtag: 59ddab9f-ae17-4d7c-9fed-003b18b631a4\r\nLast-Modified: Wed, 07 Aug 2019 04:44:48 GMT\r\nServer: TwistedWeb/14.0.2\r\nStrict-Transport-Security: max-age=2592000\r\nVary: Accept-Encoding\r\nVia: 1.1 varnish\r\nVia: 1.1 varnish\r\nX-Bzr-Revision-Number: 7464\r\nX-Cache: MISS, MISS\r\nX-Cache-Hits: 0, 0\r\nX-Request-Id: XUpXQH8AAQEAAClijP8AAABO1\r\nX-Served-By: cache-lcy19245-LCY, cache-bwi5037-BWI\r\nX-Timer: S1565157801.925351,VS0,VE115\r\n\r\n"
Aug 07 06:03:21 aug070543-458654 snapd[2466]: retry.go:136: DEBUG: Not retrying: http.http2StreamError{StreamID:0x1, Code:0x1, Cause:error(nil)}
Aug 07 06:03:21 aug070543-458654 snapd[2466]: store.go:1398: DEBUG: download of "https://api.snapcraft.io/api/v1/snaps/download/DVvhXhpa9oJjcm0rnxfxftH1oo5vTW1M_13.snap" failed: http.http2StreamError{StreamID:0x1, Code:0x1, Cause:error(nil)}
Aug 07 06:03:21 aug070543-458654 snapd[2466]: task.go:337: DEBUG: 2019-08-07T06:03:21Z ERROR stream error: stream ID 1; PROTOCOL_ERROR
Since the job failed recently, I tried using curl with to retry the request, but curl did not raise anything suspicious. Full log for those interested:
maciek@galeon:~ curl -D - --compressed --output /dev/null -v -H 'Referrer: https://api.snapcraft.io/api/v1/snaps/download/DVvhXhpa9oJjcm0rnxfxftH1oo5vTW1M_13.snap' 'https://fastly.cdn.snapcraft.io/download-origin/
fastly/DVvhXhpa9oJjcm0rnxfxftH1oo5vTW1M_13.snap?token=1565172000_65c986ad70720045b74b36859cd98ad98d39f92b'
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0* Trying 151.101.14.217:443...
* TCP_NODELAY set
* Connected to fastly.cdn.snapcraft.io (151.101.14.217) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
* CAfile: /etc/ssl/certs/ca-certificates.crt
CApath: none
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [106 bytes data]
* TLSv1.2 (IN), TLS handshake, Certificate (11):
{ [5224 bytes data]
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
{ [300 bytes data]
* TLSv1.2 (IN), TLS handshake, Server finished (14):
{ [4 bytes data]
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
} [37 bytes data]
* TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* TLSv1.2 (OUT), TLS handshake, Finished (20):
} [16 bytes data]
* TLSv1.2 (IN), TLS handshake, Finished (20):
{ [16 bytes data]
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use h2
* Server certificate:
* subject: C=US; ST=California; L=San Francisco; O=Fastly, Inc.; CN=t2.shared.global.fastly.net
* start date: Aug 6 22:43:28 2019 GMT
* expire date: Feb 16 16:37:16 2020 GMT
* subjectAltName: host "fastly.cdn.snapcraft.io" matched cert's "fastly.cdn.snapcraft.io"
* issuer: C=BE; O=GlobalSign nv-sa; CN=GlobalSign CloudSSL CA - SHA256 - G3
* SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
} [5 bytes data]
* Using Stream ID: 1 (easy handle 0x5607fbc70f30)
} [5 bytes data]
> GET /download-origin/fastly/DVvhXhpa9oJjcm0rnxfxftH1oo5vTW1M_13.snap?token=1565172000_65c986ad70720045b74b36859cd98ad98d39f92b HTTP/2
> Host: fastly.cdn.snapcraft.io
> User-Agent: curl/7.65.3
> Accept: */*
> Accept-Encoding: deflate, gzip
> Referrer: https://api.snapcraft.io/api/v1/snaps/download/DVvhXhpa9oJjcm0rnxfxftH1oo5vTW1M_13.snap
>
{ [5 bytes data]
* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!
} [5 bytes data]
< HTTP/2 200
HTTP/2 200
< server: TwistedWeb/14.0.2
server: TwistedWeb/14.0.2
< content-disposition: attachment; filename=DVvhXhpa9oJjcm0rnxfxftH1oo5vTW1M_13.snap
content-disposition: attachment; filename=DVvhXhpa9oJjcm0rnxfxftH1oo5vTW1M_13.snap
< last-modified: Wed, 07 Aug 2019 06:41:26 GMT
last-modified: Wed, 07 Aug 2019 06:41:26 GMT
< etag: 59ddab9f-ae17-4d7c-9fed-003b18b631a4
etag: 59ddab9f-ae17-4d7c-9fed-003b18b631a4
< x-bzr-revision-number: 7464
x-bzr-revision-number: 7464
< cache-control: max-age=86400
cache-control: max-age=86400
< content-type: application/octet-stream
content-type: application/octet-stream
< strict-transport-security: max-age=2592000
strict-transport-security: max-age=2592000
< x-request-id: XUpyln8AAQEAACJluvQAAABz1
x-request-id: XUpyln8AAQEAACJluvQAAABz1
< via: 1.1 varnish
via: 1.1 varnish
< accept-ranges: bytes
accept-ranges: bytes
< date: Wed, 07 Aug 2019 07:13:44 GMT
date: Wed, 07 Aug 2019 07:13:44 GMT
< via: 1.1 varnish
via: 1.1 varnish
< age: 0
age: 0
< x-served-by: cache-lcy19240-LCY, cache-fra19128-FRA
x-served-by: cache-lcy19240-LCY, cache-fra19128-FRA
< x-cache: HIT, MISS
x-cache: HIT, MISS
< x-cache-hits: 1, 0
x-cache-hits: 1, 0
< x-timer: S1565162024.910748,VS0,VE181
x-timer: S1565162024.910748,VS0,VE181
< vary: Accept-Encoding
vary: Accept-Encoding
< content-length: 1744896
content-length: 1744896
<
{ [5 bytes data]
100 1704k 100 1704k 0 0 748k 0 0:00:02 0:00:02 --:--:-- 748k
* Connection #0 to host fastly.cdn.snapcraft.io left intact
One thing that makes me wonder is that curl negotiates h2 (HTTP/2.0) during TLS ALPN. Then curl sends GET like this:
GET /download-origin/fastly/DVvhXhpa9oJjcm0rnxfxftH1oo5vTW1M_13.snap?token=1565172000_65c986ad70720045b74b36859cd98ad98d39f92b HTTP/2
While when the request is done from snapd, it looks like the initial GET is with HTTP/1.1, but the response comes with HTTP/2. This would suggest that h2 was not negotiated by ALPN, but rather Golang’s net/http client passed an Upgrade: header in the request. Unfortunately, this is not included in the debug log from snapd.
I wasn’t able to convince curl to not expose h2 to ALPN but rather include an upgrade header in the request.
FYI, the logs are from the last Travis run on master: https://travis-ci.org/snapcore/snapd/jobs/568682345
ago 02 17:24:21 cachio - verterok, I am comparing the responses which make that fail
ago 02 17:24:26 cachio - with the others
ago 02 17:24:33 cachio - to see the diff
ago 02 17:24:40 cachio - both are 2.0
ago 02 17:27:33 cachio - verterok, the only diff I see is → X-Cache: HIT, MISS
ago 02 17:27:46 cachio - vs → X-Cache: MISS, MISS
ago 02 17:28:03 verterok - cachio: yeah, a MISS, MISS means it will stream the snap from our servers
ago 02 17:28:16 verterok - all is updown fault
ago 02 17:28:57 cachio - verterok, that could cause the protocol error?
ago 02 17:29:49 cachio - the error is reproduced when X-Cache: HIT, MISS
ago 02 17:29:49 verterok - cachio: no idea what causes a protocol error, but the diff there is that one is served directly by the CDN and the other streamed from our servers: updown → fastly → client
ago 02 17:29:57 verterok - cachio: oh
ago 02 17:30:04 verterok - I thought it was in the MISS, MISS case
ago 02 17:30:11 cachio - no
ago 02 17:30:30 verterok - then it’s faslty serving the content
ago 02 17:30:35 verterok - *fastly
ago 02 17:30:45 cachio - verterok, 
roadmr → ah, but this is HTTP/2.0, right?
roadmr → verterok: it does look fishy
cachio → verterok, error using debug=2