Creating a separate thread for this, as the issue I initially mentioned in Download deltas feature write-up appears to be more convoluted than I originally suspected, and I don’t want to hijack that thread.
Context
- Environment: Raspberry Pi 3, running Ubuntu Core beta, with snapd version 2.30.
- Snap being installed: A snap I’m developing myself called “stromm” (released as private), with the following features:
- Consists of Python3 script + libraries; full snap weighs in at around 23MB
- My snapcraft.yaml file has
grade: devel
andconfinement: strict
set. Confinement is not overridden during install. - Snap is released to the edge channel
- When making a small changes to the codebase, deltas between sequential revisions weigh in at about ~300KB. These are generated and uploaded successfully by snapcraft during the push process.
- From the other thread, it sounds like deltas are also being successfull generated on the store server
Action
I have a client that has the snap installed, tracking the edge channel. When I publish a new release of the snap to that channel, I wait for 10-15 minutes and run snap refresh
on the client.
Observed behavior
The new snap version is picked up, and the full ~23MB snap package is downloaded and installed. I have done about 5 attempts with releasing new versions of the snap, and this is the behavior every time. The delta is never downloaded.
Expected behavior
When the new snap version is picked up, the ~300KB delta should be downloaded and installed.
Troubleshooting
As suggested by @roadmr in Download deltas feature write-up, in order to debug the snapd client’s behavior, I ran
sudo systemctl stop snapd.service snapd.socket
sudo SNAPD_DEBUG=1 SNAPD_DEBUG_HTTP=3 /usr/lib/snapd/snapd
for a few of the refresh attempts. The following is a representative example of the requests and responses that were logged in the process:
username@localhost:/usr/lib/snapd$ sudo SNAPD_DEBUG=1 SNAPD_DEBUG_HTTP=3 ./snapd
AppArmor status: apparmor is enabled and all features are available
2018/01/08 20:25:10.812053 daemon.go:268: DEBUG: socket "/run/snapd.socket" was not activated; listening
2018/01/08 20:25:10.812417 daemon.go:268: DEBUG: socket "/run/snapd-snap.socket" was not activated; listening
2018/01/08 20:25:10.816105 daemon.go:306: started snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2.
2018/01/08 20:25:10.816385 main.go:72: DEBUG: activation done in 644ms
2018/01/08 20:25:10.823281 autorefresh.go:143: DEBUG: Next refresh scheduled for 2018-01-09 04:50:41.636336128 +0000 UTC.
2018/01/08 20:25:10.823420 catalogrefresh.go:69: DEBUG: Catalog refresh starting now; next scheduled for 2018-01-09 20:25:10.823382507 +0000 UTC.
2018/01/08 20:25:10.823624 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/sections, attempt 1, elapsed time=32.76µs
2018/01/08 20:25:10.826855 logger.go:69: DEBUG: > "GET /api/v1/snaps/sections HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: application/hal+json\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:25:11.424475 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 263\r\nAge: 768\r\nCache-Control: public, max-age=3600\r\nContent-Type: application/hal+json\r\nDate: Mon, 08 Jan 2018 20:12:23 GMT\r\nServer: gunicorn/19.7.1\r\nVary: X-Ubuntu-Series\r\nVia: 1.1 juju-7794b8-prod-ols-snap-store-indep-398 (squid/3.5.12)\r\nX-Cache: HIT from juju-7794b8-prod-ols-snap-store-indep-398\r\nX-Cache-Lookup: HIT from juju-7794b8-prod-ols-snap-store-indep-398:3128\r\nX-Request-Id: 8f2c7ef2-11ac-4d18-ac5b-0e24f59581fe\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:25:11.425080 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/sections finished after 1 retries, elapsed time=601.485663ms, status: 200
2018/01/08 20:25:11.436111 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/names?confinement=strict, attempt 1, elapsed time=33.176µs
2018/01/08 20:25:11.438659 logger.go:69: DEBUG: > "GET /api/v1/snaps/names?confinement=strict HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: application/hal+json\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:25:11.739815 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 59275\r\nAge: 11\r\nCache-Control: public, max-age=3600\r\nContent-Type: application/hal+json\r\nDate: Mon, 08 Jan 2018 20:25:02 GMT\r\nServer: gunicorn/19.7.1\r\nVary: X-Ubuntu-Store, X-Ubuntu-Series, X-Ubuntu-Architecture\r\nVia: 1.1 juju-7794b8-prod-ols-snap-store-indep-397 (squid/3.5.23)\r\nX-Cache: HIT from juju-7794b8-prod-ols-snap-store-indep-397\r\nX-Cache-Lookup: HIT from juju-7794b8-prod-ols-snap-store-indep-397:3128\r\nX-Request-Id: ccd30599-4686-42ab-8b65-6a5b6dc1d52d\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:25:11.881469 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/names?confinement=strict finished after 1 retries, elapsed time=445.380835ms, status: 200
================= RAN `snap refresh stromm` ==============================
2018/01/08 20:27:48.324576 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/99T7MUlRhtI3U0QFgl5mXXESAiSwt776?max-format=2, attempt 1, elapsed time=42.865µs
2018/01/08 20:27:48.330816 logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/snap-declaration/16/99T7MUlRhtI3U0QFgl5mXXESAiSwt776?max-format=2 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:27:48.403946 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 986\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Mon, 08 Jan 2018 20:27:48 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: bf0cfe3e-fdec-48e0-b60b-4fe5a5cfc099\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:27:48.404802 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/99T7MUlRhtI3U0QFgl5mXXESAiSwt776?max-format=2 finished after 1 retries, elapsed time=80.280266ms, status: 200
2018/01/08 20:27:48.405330 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/account-key/BWDEoaqyr25nF5SNCvEv2v7QnM9QsfCc0PBMYD_i2NGSQ32EF2d4D0hqUel3m8ul?max-format=0, attempt 1, elapsed time=35.052µs
2018/01/08 20:27:48.411598 logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/account-key/BWDEoaqyr25nF5SNCvEv2v7QnM9QsfCc0PBMYD_i2NGSQ32EF2d4D0hqUel3m8ul?max-format=0 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:27:48.486034 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 2452\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Mon, 08 Jan 2018 20:27:48 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 82f54c9b-9404-4f16-8192-5d5ad658441f\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:27:48.487804 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/account-key/BWDEoaqyr25nF5SNCvEv2v7QnM9QsfCc0PBMYD_i2NGSQ32EF2d4D0hqUel3m8ul?max-format=0 finished after 1 retries, elapsed time=82.493373ms, status: 200
2018/01/08 20:27:48.489809 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/m0rvvnmRdDgexonz1XSP9a9U4K7vUbiy?max-format=2, attempt 1, elapsed time=40.208µs
2018/01/08 20:27:48.496560 logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/snap-declaration/16/m0rvvnmRdDgexonz1XSP9a9U4K7vUbiy?max-format=2 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:27:48.571045 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1004\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Mon, 08 Jan 2018 20:27:48 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 10e357d2-3e05-41f2-91ab-10e496ea9e79\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:27:48.572028 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/m0rvvnmRdDgexonz1XSP9a9U4K7vUbiy?max-format=2 finished after 1 retries, elapsed time=82.444467ms, status: 200
2018/01/08 20:27:48.573706 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/kHqvqCxMKWRDGGbxc3NZ13x00otcVry2?max-format=2, attempt 1, elapsed time=40.26µs
2018/01/08 20:27:48.579909 logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/snap-declaration/16/kHqvqCxMKWRDGGbxc3NZ13x00otcVry2?max-format=2 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:27:48.651835 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 997\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Mon, 08 Jan 2018 20:27:48 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: db44e3ae-e976-4be9-ab55-c9837b2941af\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:27:48.653437 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/kHqvqCxMKWRDGGbxc3NZ13x00otcVry2?max-format=2 finished after 1 retries, elapsed time=79.763968ms, status: 200
2018/01/08 20:27:48.655538 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/DVAzG29Avl1Cn5s1nLXGzyQ0vi9v87Jw?max-format=2, attempt 1, elapsed time=43.854µs
2018/01/08 20:27:48.661468 logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/snap-declaration/16/DVAzG29Avl1Cn5s1nLXGzyQ0vi9v87Jw?max-format=2 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:27:48.735107 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1070\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Mon, 08 Jan 2018 20:27:48 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 92e8c6cf-acec-4bed-9ae8-d1835914dcdc\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:27:48.736275 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/DVAzG29Avl1Cn5s1nLXGzyQ0vi9v87Jw?max-format=2 finished after 1 retries, elapsed time=80.777241ms, status: 200
2018/01/08 20:27:48.738866 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0?max-format=2, attempt 1, elapsed time=41.562µs
2018/01/08 20:27:48.744865 logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/snap-declaration/16/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0?max-format=2 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:27:48.819993 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1011\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Mon, 08 Jan 2018 20:27:48 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 0af7f320-c6b3-4897-9c12-deac3e8bb9e2\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:27:48.820941 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0?max-format=2 finished after 1 retries, elapsed time=82.232855ms, status: 200
2018/01/08 20:27:48.821458 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/account/vAcsh9cdaK5UVGsEC3Z3XLgpFtj3ktu5?max-format=0, attempt 1, elapsed time=35.261µs
2018/01/08 20:27:48.828278 logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/account/vAcsh9cdaK5UVGsEC3Z3XLgpFtj3ktu5?max-format=0 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:27:48.900296 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 993\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Mon, 08 Jan 2018 20:27:48 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 5932801c-b518-4385-8378-322a591ec7c7\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:27:48.901180 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/account/vAcsh9cdaK5UVGsEC3Z3XLgpFtj3ktu5?max-format=0 finished after 1 retries, elapsed time=79.740687ms, status: 200
2018/01/08 20:27:48.903391 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/TJoM6hAcUjQXPAti5vAKQZacAoJDNMBi?max-format=2, attempt 1, elapsed time=41.406µs
2018/01/08 20:27:48.910429 logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/snap-declaration/16/TJoM6hAcUjQXPAti5vAKQZacAoJDNMBi?max-format=2 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:27:48.984966 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1019\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Mon, 08 Jan 2018 20:27:48 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: dde3c962-ebc7-4bdb-a4b7-f757172ce428\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:27:48.985831 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/TJoM6hAcUjQXPAti5vAKQZacAoJDNMBi?max-format=2 finished after 1 retries, elapsed time=82.477436ms, status: 200
2018/01/08 20:27:48.988447 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/QbSFwGGAgvG8zHl9nWLY7vEee8lhgFsp?max-format=2, attempt 1, elapsed time=43.125µs
2018/01/08 20:27:48.994514 logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/snap-declaration/16/QbSFwGGAgvG8zHl9nWLY7vEee8lhgFsp?max-format=2 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:27:49.072070 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1098\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Mon, 08 Jan 2018 20:27:49 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 0e1e3853-9e0d-49a8-bc88-9978cdc01ccf\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:27:49.073237 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/QbSFwGGAgvG8zHl9nWLY7vEee8lhgFsp?max-format=2 finished after 1 retries, elapsed time=84.831694ms, status: 200
2018/01/08 20:27:49.327649 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/metadata, attempt 1, elapsed time=39.896µs
2018/01/08 20:27:49.333878 logger.go:69: DEBUG: > "POST /api/v1/snaps/metadata HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nContent-Length: 524\r\nAccept: application/hal+json\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nContent-Type: application/json\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:27:49.518499 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1094\r\nContent-Type: application/json\r\nDate: Mon, 08 Jan 2018 20:27:49 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: c36ddbf0-492d-464d-ba13-9762d1ddbf8f\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:27:49.519961 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/metadata finished after 1 retries, elapsed time=192.353789ms, status: 200
2018/01/08 20:27:49.679825 daemon.go:233: DEBUG: pid=1419;uid=1000;@ POST /v2/snaps/stromm 1.362475774s 202
2018/01/08 20:27:49.691373 taskrunner.go:370: DEBUG: Running task 771 on Do: Ensure prerequisites for "stromm" are available
2018/01/08 20:27:49.924628 taskrunner.go:370: DEBUG: Running task 772 on Do: Download snap "stromm" (12) from channel "edge"
2018/01/08 20:27:50.033861 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/download/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0_12.snap, attempt 1, elapsed time=52.343µs
2018/01/08 20:27:50.037569 logger.go:69: DEBUG: > "GET /api/v1/snaps/download/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0_12.snap HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: \r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:27:50.377259 logger.go:76: DEBUG: < "HTTP/1.1 302 FOUND\r\nContent-Length: 535\r\nContent-Type: text/html; charset=utf-8\r\nDate: Mon, 08 Jan 2018 20:27:50 GMT\r\nLocation: https://068ed04f23.site.internapcdn.net/download-snap/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0_12.snap?t=2018-01-08T22:00:00Z&h=a55e09c813b62a93bfc715ee32a28936458e2001\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: c9ebb811-339b-4031-a847-edfdd093e8e4\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:27:50.378471 logger.go:69: DEBUG: > "GET /download-snap/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0_12.snap?t=2018-01-08T22:00:00Z&h=a55e09c813b62a93bfc715ee32a28936458e2001 HTTP/1.1\r\nHost: 068ed04f23.site.internapcdn.net\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: \r\nReferer: https://api.snapcraft.io/api/v1/snaps/download/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0_12.snap\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:27:50.938943 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 22495232\r\nCache-Control: max-age=86400\r\nConnection: keep-alive\r\nContent-Disposition: attachment; filename=Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0_12.snap\r\nContent-Type: application/octet-stream\r\nDate: Mon, 08 Jan 2018 20:27:50 GMT\r\nEtag: feac19ad-017d-4c0c-a549-0272457270e9\r\nLast-Modified: Mon, 08 Jan 2018 20:27:50 GMT\r\nServer: CDCE\r\nStrict-Transport-Security: max-age=2592000\r\nVary: Accept-Encoding\r\nX-Bzr-Revision-Number: 7458\r\nX-Inap-Cache-Status: MISS\r\nX-Inap-Server: cdce-fra004-002.fra004.internap.com\r\nX-Request-Id: WlPURn8AAQEAAFex29gAAABy1\r\n\r\n"
2018/01/08 20:28:07.681692 taskrunner.go:370: DEBUG: Running task 773 on Do: Fetch and check assertions for snap "stromm" (12)
2018/01/08 20:28:12.992449 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/snap-revision/rGWWItmx-R2JNhb190nLdDHdm4SxO4lKvVHA7wLjg_z9zzA4gMACKJQjR0F8qq-V?max-format=0, attempt 1, elapsed time=31.302µs
2018/01/08 20:28:12.996879 logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/snap-revision/rGWWItmx-R2JNhb190nLdDHdm4SxO4lKvVHA7wLjg_z9zzA4gMACKJQjR0F8qq-V?max-format=0 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:28:13.071637 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1097\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Mon, 08 Jan 2018 20:28:13 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 44e20aa3-7ed0-4d53-b003-fa376c2ba96e\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:28:13.072230 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/snap-revision/rGWWItmx-R2JNhb190nLdDHdm4SxO4lKvVHA7wLjg_z9zzA4gMACKJQjR0F8qq-V?max-format=0 finished after 1 retries, elapsed time=79.834345ms, status: 200
2018/01/08 20:28:13.072520 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0?max-format=2, attempt 1, elapsed time=22.865µs
2018/01/08 20:28:13.075969 logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/snap-declaration/16/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0?max-format=2 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:28:13.151996 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1011\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Mon, 08 Jan 2018 20:28:13 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 18092490-7044-4805-bbbf-361530c55be5\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:28:13.152660 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0?max-format=2 finished after 1 retries, elapsed time=80.149396ms, status: 200
2018/01/08 20:28:13.152959 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/account/vAcsh9cdaK5UVGsEC3Z3XLgpFtj3ktu5?max-format=0, attempt 1, elapsed time=22.187µs
2018/01/08 20:28:13.156647 logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/account/vAcsh9cdaK5UVGsEC3Z3XLgpFtj3ktu5?max-format=0 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:28:13.228845 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 993\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Mon, 08 Jan 2018 20:28:13 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 7832a5df-538d-4a99-9397-18672b4dee9d\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:28:13.229375 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/account/vAcsh9cdaK5UVGsEC3Z3XLgpFtj3ktu5?max-format=0 finished after 1 retries, elapsed time=76.425773ms, status: 200
2018/01/08 20:28:13.229659 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/account-key/BWDEoaqyr25nF5SNCvEv2v7QnM9QsfCc0PBMYD_i2NGSQ32EF2d4D0hqUel3m8ul?max-format=0, attempt 1, elapsed time=21.771µs
2018/01/08 20:28:13.233253 logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/account-key/BWDEoaqyr25nF5SNCvEv2v7QnM9QsfCc0PBMYD_i2NGSQ32EF2d4D0hqUel3m8ul?max-format=0 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16) ubuntu-core/16 (armhf) linux/4.4.0-1080-raspi2\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: armhf\r\nX-Ubuntu-Classic: false\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"
2018/01/08 20:28:13.309003 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 2452\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Mon, 08 Jan 2018 20:28:13 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 8f4680fa-71f0-4642-a364-62bb504a95c4\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/08 20:28:13.312040 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/account-key/BWDEoaqyr25nF5SNCvEv2v7QnM9QsfCc0PBMYD_i2NGSQ32EF2d4D0hqUel3m8ul?max-format=0 finished after 1 retries, elapsed time=82.385684ms, status: 200
2018/01/08 20:28:13.521963 taskrunner.go:370: DEBUG: Running task 774 on Do: Mount snap "stromm" (12)
2018/01/08 20:28:15.828725 taskrunner.go:370: DEBUG: Running task 775 on Do: Run pre-refresh hook of "stromm" snap if present
2018/01/08 20:28:15.969203 taskrunner.go:370: DEBUG: Running task 776 on Do: Stop snap "stromm" services
2018/01/08 20:28:16.105285 taskrunner.go:370: DEBUG: Running task 777 on Do: Remove aliases for snap "stromm"
2018/01/08 20:28:16.594798 taskrunner.go:370: DEBUG: Running task 778 on Do: Make current revision for snap "stromm" unavailable
2018/01/08 20:28:16.792027 taskrunner.go:370: DEBUG: Running task 779 on Do: Copy snap "stromm" data
2018/01/08 20:28:17.424143 taskrunner.go:370: DEBUG: Running task 780 on Do: Setup snap "stromm" (12) security profiles
2018/01/08 20:28:18.689103 taskrunner.go:370: DEBUG: Running task 781 on Do: Make snap "stromm" (12) available to the system
2018/01/08 20:28:18.829266 taskrunner.go:370: DEBUG: Running task 782 on Do: Set automatic aliases for snap "stromm"
2018/01/08 20:28:19.031939 taskrunner.go:370: DEBUG: Running task 783 on Do: Setup snap "stromm" aliases
2018/01/08 20:28:19.349096 taskrunner.go:370: DEBUG: Running task 784 on Do: Run post-refresh hook of "stromm" snap if present
2018/01/08 20:28:19.593109 taskrunner.go:370: DEBUG: Running task 785 on Do: Start snap "stromm" (12) services
2018/01/08 20:28:19.861996 taskrunner.go:370: DEBUG: Running task 786 on Do: Remove data for snap "stromm" (8)
2018/01/08 20:28:20.099565 taskrunner.go:370: DEBUG: Running task 787 on Do: Remove snap "stromm" (8) from the system
2018/01/08 20:28:22.354932 taskrunner.go:370: DEBUG: Running task 788 on Do: Clean up "stromm" (12) install
2018/01/08 20:28:22.543345 taskrunner.go:370: DEBUG: Running task 789 on Do: Run configure hook of "stromm" snap if present
2018/01/08 20:28:22.807228 daemon.go:233: DEBUG: pid=1419;uid=1000;@ GET /v2/snaps?snaps=stromm 8.759793ms 200
All timestamps are UTC. This is for updating from revision 11 (which was installed) to revision 12. @thomir / @roadmr hopefully the above helps shed some light? (and hopefully I’ve successfully redacted out the sensitive bits)
If this doesn’t help, as a next step I can also run snapd it with HTTP debug level 4 which I believe should post the response bodies.
Any advice would be appreciated!
Svet