Refresh causes download of full snap file instead of delta

svet · January 10, 2018, 8:37am

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 and confinement: 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

ogra · January 10, 2018, 12:30pm

i think i seem to remember that snapd has deltas disabled in general on arm because this can cause slowness (i might be wrong though, @mvo or @niemeyer should be able to confirm though)

svet · January 10, 2018, 11:09pm

You may be right. I just tried an amd64 version of the snap on a VM and the delta seemed to go through as expected.

Is there any way to enable/force deltas on ARM? We’re using our devices in remote locations with poor internet connectivity, so minimizing download sizes is critical for updates to work. On the other hand, the Raspberry Pi didn’t seem to have too hard a time with generating the delta for the snap, so I imagine applying deltas should be fine too for the snap sizes we’re using.

svet · January 11, 2018, 2:53pm

For reference, here’s the log output on an amd64 desktop machine

username@ubuntu:~$ sudo SNAPD_DEBUG=1 SNAPD_DEBUG_HTTP=3 /usr/lib/snapd/snapd
AppArmor status: apparmor is enabled and all features are available
2018/01/11 16:26:54.470761 cmd.go:212: DEBUG: restarting into "/snap/core/current/usr/lib/snapd/snapd"
AppArmor status: apparmor is enabled and all features are available
2018/01/11 16:26:55.497982 daemon.go:268: DEBUG: socket "/run/snapd.socket" was not activated; listening
2018/01/11 16:26:55.498885 daemon.go:268: DEBUG: socket "/run/snapd-snap.socket" was not activated; listening
2018/01/11 16:26:55.502775 daemon.go:306: started snapd/2.30 (series 16; classic) ubuntu/16.04 (amd64) linux/4.4.0-109-generic.
2018/01/11 16:26:55.504859 main.go:72: DEBUG: activation done in 659ms
2018/01/11 16:26:55.507031 autorefresh.go:143: DEBUG: Next refresh scheduled for 2018-01-11 21:30:24.202674305 +0200 EET.
2018/01/11 16:26:55.507796 catalogrefresh.go:69: DEBUG: Catalog refresh starting now; next scheduled for 2018-01-12 16:26:55.507759171 +0200 EET.
2018/01/11 16:26:55.508473 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/sections, attempt 1, elapsed time=9.749µs
2018/01/11 16:26:55.510031 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; classic) ubuntu/16.04 (amd64) linux/4.4.0-109-generic\r\nAccept: application/hal+json\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: amd64\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"
2018/01/11 16:26:55.787073 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 263\r\nAge: 872\r\nCache-Control: public, max-age=3600\r\nContent-Type: application/hal+json\r\nDate: Thu, 11 Jan 2018 14: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: 4d6e8dee-c592-43f4-af27-9d85fe2b27d0\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/11 16:26:55.788229 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/sections finished after 1 retries, elapsed time=279.757701ms, status: 200
2018/01/11 16:26:55.792726 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/names?confinement=strict%2Cclassic, attempt 1, elapsed time=13.292µs
2018/01/11 16:26:55.796870 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.30 (series 16; classic) ubuntu/16.04 (amd64) linux/4.4.0-109-generic\r\nAccept: application/hal+json\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: amd64\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"
2018/01/11 16:26:55.987430 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 181189\r\nAge: 1484\r\nCache-Control: public, max-age=3600\r\nContent-Type: application/hal+json\r\nDate: Thu, 11 Jan 2018 14:02:16 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-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: 423e6d82-7fdd-46ac-bbdb-0f54d29a8f41\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/11 16:26:56.073066 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=280.363069ms, status: 200
2018/01/11 16:27:04.416906 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/99T7MUlRhtI3U0QFgl5mXXESAiSwt776?max-format=2, attempt 1, elapsed time=8.696µs
2018/01/11 16:27:04.418863 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; classic) ubuntu/16.04 (amd64) linux/4.4.0-109-generic\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: amd64\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"
2018/01/11 16:27:04.491736 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 986\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Thu, 11 Jan 2018 14:27:04 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 28e99f51-5f74-417c-af7b-cfe7362164dd\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/11 16:27:04.491901 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=75.00425ms, status: 200
2018/01/11 16:27:04.491975 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/account-key/BWDEoaqyr25nF5SNCvEv2v7QnM9QsfCc0PBMYD_i2NGSQ32EF2d4D0hqUel3m8ul?max-format=0, attempt 1, elapsed time=4.293µs
2018/01/11 16:27:04.492688 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; classic) ubuntu/16.04 (amd64) linux/4.4.0-109-generic\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: amd64\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"
2018/01/11 16:27:04.545696 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 2452\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Thu, 11 Jan 2018 14:27:04 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 3d3703c7-e3e2-4ac6-950c-4f472b36ef9b\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/11 16:27:04.547092 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=55.107895ms, status: 200
2018/01/11 16:27:04.548902 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0?max-format=2, attempt 1, elapsed time=10.093µs
2018/01/11 16:27:04.551231 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; classic) ubuntu/16.04 (amd64) linux/4.4.0-109-generic\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: amd64\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"
2018/01/11 16:27:04.616392 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1011\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Thu, 11 Jan 2018 14:27:04 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: c8f8ebe2-49b5-4822-a198-6701504b0ddc\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/11 16:27:04.616738 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=67.843136ms, status: 200
2018/01/11 16:27:04.616940 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/account/vAcsh9cdaK5UVGsEC3Z3XLgpFtj3ktu5?max-format=0, attempt 1, elapsed time=9.214µs
2018/01/11 16:27:04.619259 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; classic) ubuntu/16.04 (amd64) linux/4.4.0-109-generic\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: amd64\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"
2018/01/11 16:27:04.669877 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 993\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Thu, 11 Jan 2018 14:27:04 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: be260555-c9e8-41cb-ac1e-881be15c3631\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/11 16:27:04.671033 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=54.098865ms, status: 200
2018/01/11 16:27:04.701371 store.go:1315: DEBUG: Deltas enabled. Adding header X-Ubuntu-Delta-Formats: xdelta3
2018/01/11 16:27:04.702760 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/metadata, attempt 1, elapsed time=15.284µs
2018/01/11 16:27:04.704844 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; classic) ubuntu/16.04 (amd64) linux/4.4.0-109-generic\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: amd64\r\nX-Ubuntu-Classic: true\r\nX-Ubuntu-Delta-Formats: xdelta3\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/11 16:27:04.880251 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1533\r\nContent-Type: application/json\r\nDate: Thu, 11 Jan 2018 14:27:04 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 84e032b2-5a99-4c3f-b020-c7311931713b\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/11 16:27:04.880898 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/metadata finished after 1 retries, elapsed time=178.162146ms, status: 200
2018/01/11 16:27:04.891084 daemon.go:233: DEBUG: pid=26832;uid=1000;@ POST /v2/snaps/stromm 476.2655ms 202
2018/01/11 16:27:04.910054 taskrunner.go:370: DEBUG: Running task 159 on Do: Ensure prerequisites for "stromm" are available
2018/01/11 16:27:04.924833 taskrunner.go:370: DEBUG: Running task 160 on Do: Download snap "stromm" (15) from channel "edge"
2018/01/11 16:27:04.932324 store.go:1432: DEBUG: Available deltas returned by store: [{14 15 xdelta3 https://api.snapcraft.io/api/v1/snaps/download/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0_14_15_xdelta3.delta https://api.snapcraft.io/api/v1/snaps/download/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0_14_15_xdelta3.delta 151057 b0f6f6db5e9817111f6d72b5ad85aa300e3ecb571784986e283856a381e45c81a795dde617256a4eb43a3974eddd43a2}]
2018/01/11 16:27:04.933158 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/download/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0_14_15_xdelta3.delta, attempt 1, elapsed time=19.822µs
2018/01/11 16:27:04.934706 logger.go:69: DEBUG: > "GET /api/v1/snaps/download/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0_14_15_xdelta3.delta HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16; classic) ubuntu/16.04 (amd64) linux/4.4.0-109-generic\r\nAccept: \r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: amd64\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"
2018/01/11 16:27:05.224408 logger.go:76: DEBUG: < "HTTP/1.1 302 FOUND\r\nContent-Length: 559\r\nContent-Type: text/html; charset=utf-8\r\nDate: Thu, 11 Jan 2018 14:27:05 GMT\r\nLocation: https://068ed04f23.site.internapcdn.net/download-snap/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0_14_15_xdelta3.delta?t=2018-01-11T16:00:00Z&h=fb98c1cb95e1010b83cbebb2e72ad5daf9ded1e2\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 09a07ace-457e-4a34-827c-eeb94faf9e11\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/11 16:27:05.225948 logger.go:69: DEBUG: > "GET /download-snap/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0_14_15_xdelta3.delta?t=2018-01-11T16:00:00Z&h=fb98c1cb95e1010b83cbebb2e72ad5daf9ded1e2 HTTP/1.1\r\nHost: 068ed04f23.site.internapcdn.net\r\nUser-Agent: snapd/2.30 (series 16; classic) ubuntu/16.04 (amd64) linux/4.4.0-109-generic\r\nAccept: \r\nReferer: https://api.snapcraft.io/api/v1/snaps/download/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0_14_15_xdelta3.delta\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: amd64\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"
2018/01/11 16:27:05.677235 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 151057\r\nCache-Control: max-age=86400\r\nConnection: keep-alive\r\nContent-Disposition: attachment; filename=Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0_14_15_xdelta3.delta\r\nContent-Type: application/octet-stream\r\nDate: Thu, 11 Jan 2018 14:27:05 GMT\r\nEtag: 71bb0a82-c5ed-4cab-bf05-3f457b6fd275\r\nLast-Modified: Thu, 11 Jan 2018 14:27:05 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-003.fra004.internap.com\r\nX-Request-Id: Wld0OX8AAQEAAA11xZYAAABT1\r\n\r\n"
2018/01/11 16:27:05.745286 store.go:1723: DEBUG: Successfully downloaded delta for "stromm" at /var/lib/snapd/snaps/stromm_15.snap.xdelta3-14-to-15.partial
2018/01/11 16:27:06.763708 store.go:1728: DEBUG: Successfully applied delta for "stromm" at /var/lib/snapd/snaps/stromm_15.snap.xdelta3-14-to-15.partial, saving 25424367 bytes.
2018/01/11 16:27:06.775429 taskrunner.go:370: DEBUG: Running task 161 on Do: Fetch and check assertions for snap "stromm" (15)
2018/01/11 16:27:07.063794 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/snap-revision/fUyYzAXmoV-WPLbF3Q25wGPAVqaANejRpE1gPxBy3n0ub6DnXVu4ixGhgZAzPzhf?max-format=0, attempt 1, elapsed time=9.341µs
2018/01/11 16:27:07.078278 logger.go:69: DEBUG: > "GET /api/v1/snaps/assertions/snap-revision/fUyYzAXmoV-WPLbF3Q25wGPAVqaANejRpE1gPxBy3n0ub6DnXVu4ixGhgZAzPzhf?max-format=0 HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.30 (series 16; classic) ubuntu/16.04 (amd64) linux/4.4.0-109-generic\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: amd64\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"
2018/01/11 16:27:07.135158 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1097\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Thu, 11 Jan 2018 14:27:07 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: d1960af3-e80d-453c-93e5-80a60d6bd352\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/11 16:27:07.135499 retry.go:52: DEBUG: The retry loop for https://api.snapcraft.io/api/v1/snaps/assertions/snap-revision/fUyYzAXmoV-WPLbF3Q25wGPAVqaANejRpE1gPxBy3n0ub6DnXVu4ixGhgZAzPzhf?max-format=0 finished after 1 retries, elapsed time=71.70583ms, status: 200
2018/01/11 16:27:07.135693 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/snap-declaration/16/Ze464qJ8jNXrrgAcXmuYEgdy5pK7ROX0?max-format=2, attempt 1, elapsed time=8.225µs
2018/01/11 16:27:07.137813 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; classic) ubuntu/16.04 (amd64) linux/4.4.0-109-generic\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: amd64\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"
2018/01/11 16:27:07.199580 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 1011\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Thu, 11 Jan 2018 14:27:07 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: e0a4b62f-bed6-477e-a3ca-c079c42c5b60\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/11 16:27:07.199825 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=64.137ms, status: 200
2018/01/11 16:27:07.199934 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/account/vAcsh9cdaK5UVGsEC3Z3XLgpFtj3ktu5?max-format=0, attempt 1, elapsed time=6.293µs
2018/01/11 16:27:07.201223 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; classic) ubuntu/16.04 (amd64) linux/4.4.0-109-generic\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: amd64\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"
2018/01/11 16:27:07.254089 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 993\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Thu, 11 Jan 2018 14:27:07 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 7d5b40c5-697c-4f2d-924b-bc4d2629a806\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/11 16:27:07.254410 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=54.476617ms, status: 200
2018/01/11 16:27:07.254548 retry.go:40: DEBUG: Retrying https://api.snapcraft.io/api/v1/snaps/assertions/account-key/BWDEoaqyr25nF5SNCvEv2v7QnM9QsfCc0PBMYD_i2NGSQ32EF2d4D0hqUel3m8ul?max-format=0, attempt 1, elapsed time=7.07µs
2018/01/11 16:27:07.265923 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; classic) ubuntu/16.04 (amd64) linux/4.4.0-109-generic\r\nAccept: application/x.ubuntu.assertion\r\nAuthorization: Macaroon root=\"<redacted>\", discharge=\"<redacted>\"\r\nX-Device-Authorization: Macaroon root=\"<redacted>\"\r\nX-Ubuntu-Architecture: amd64\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"
2018/01/11 16:27:07.327086 logger.go:76: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 2452\r\nContent-Type: application/x.ubuntu.assertion\r\nDate: Thu, 11 Jan 2018 14:27:07 GMT\r\nServer: gunicorn/19.7.1\r\nX-Request-Id: 71933f9b-fef7-4f85-91cd-a0217e2c2b07\r\nX-Vcs-Revision: efa4de8\r\n\r\n"
2018/01/11 16:27:07.327698 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=73.153723ms, status: 200
2018/01/11 16:27:07.352181 taskrunner.go:370: DEBUG: Running task 162 on Do: Mount snap "stromm" (15)
2018/01/11 16:27:08.264405 taskrunner.go:370: DEBUG: Running task 163 on Do: Run pre-refresh hook of "stromm" snap if present
2018/01/11 16:27:08.290545 taskrunner.go:370: DEBUG: Running task 164 on Do: Stop snap "stromm" services
2018/01/11 16:27:08.308258 taskrunner.go:370: DEBUG: Running task 165 on Do: Remove aliases for snap "stromm"
2018/01/11 16:27:08.395494 taskrunner.go:370: DEBUG: Running task 166 on Do: Make current revision for snap "stromm" unavailable
2018/01/11 16:27:08.432241 taskrunner.go:370: DEBUG: Running task 167 on Do: Copy snap "stromm" data
2018/01/11 16:27:08.525694 taskrunner.go:370: DEBUG: Running task 168 on Do: Setup snap "stromm" (15) security profiles
2018/01/11 16:27:09.212121 taskrunner.go:370: DEBUG: Running task 169 on Do: Make snap "stromm" (15) available to the system
2018/01/11 16:27:09.223922 taskrunner.go:370: DEBUG: Running task 170 on Do: Set automatic aliases for snap "stromm"
2018/01/11 16:27:09.250537 taskrunner.go:370: DEBUG: Running task 171 on Do: Setup snap "stromm" aliases
2018/01/11 16:27:09.272851 taskrunner.go:370: DEBUG: Running task 172 on Do: Run post-refresh hook of "stromm" snap if present
2018/01/11 16:27:09.293530 taskrunner.go:370: DEBUG: Running task 173 on Do: Start snap "stromm" (15) services
2018/01/11 16:27:09.351425 taskrunner.go:370: DEBUG: Running task 174 on Do: Clean up "stromm" (15) install
2018/01/11 16:27:09.384144 taskrunner.go:370: DEBUG: Running task 175 on Do: Run configure hook of "stromm" snap if present
2018/01/11 16:27:09.439278 daemon.go:233: DEBUG: pid=26832;uid=1000;@ GET /v2/snaps?snaps=stromm 3.163177ms 200

The key difference is the presence of the store.go-generated lines regarding availability of deltas. In the ARM log there’s nothing from store.go altogether. Per my previous post, would love to know what I need todo to enable deltas on armhf.

niemeyer · January 11, 2018, 7:22pm

We can implement a setting to force deltas to be used on ARM, but before going there, would anyone have some more precise background on why this setting was disabled? Did we actually test it before assuming it would be a problem?

@mvo @pedronis Do you recall anything around that subject?

svet · January 18, 2018, 8:24am

Thanks for the context (and confirmation), that makes sense! Would love to hear any follow-up on this.

ogra · January 18, 2018, 11:01am

IIRC @chipaca had me test it ages ago on a beaglebone (our lowest end HW, single core ARM, 512MB RAM) … and the snap install process took significantly longer on that HW … (i dont remember numbers, this was a back and forth conversation on IRC)

I am currently working with an even lower end board for a customer and would happily test it again if someone tells me how to force-enable it …

awe · February 8, 2018, 12:05am

There are some pretty powerful arm64 systems on the market now, so a switch that would allow deltas to be force enabled on ARM would be a good thing IMHOP.

niemeyer · February 8, 2018, 12:31am

Yeah, let’s move it on!

ogra · February 8, 2018, 12:26pm

arm64 should definitely have it always enabled … the problematic boards are armhf, low-speed single-core systems with not much cache where high CPU load simply blocks the whole device from operating for a while …
(i.e. beaglebone class), i agree this should be a gadget toggle, so we can turn it off on such devices only …

svet · February 8, 2018, 12:59pm

Could this be implemented as a configuration switch (environment variable or the like) so that deltas can for example be force-enabled on an armhf device also (even if they’re left as disabled by default)?

I understand that very large deltas can cause low-power devices to choke, but I’d rather have a device that slows down temporarily during updates, over than one that simply can’t update at all, due to the low likelihood of being able to download a 50MB snap over a low-quality GPRS link. Same goes for IoT devices with roaming M2M SIMs, where the data caps are usually in the 10s of MB per month, and frugality with respect to data transfer is more important than CPU load management.

ogra · February 8, 2018, 1:35pm

I think it should be on by default everywhere but there should be a core configuration option to turn it off…

such settings can then be set to a sane default via a gadget.yaml entry in the gadget snap on systems affected …

along with that you would be able to call something like:

snap set core deltas=off|on

to en/disable it at runtime.
(it is just essential that we do not turn it on by default without any way to disable it for this device class)

ogra · February 8, 2018, 1:56pm

I just dug through the snapd source, if we set SNAPD_USE_DELTAS_EXPERIMENTAL=true in /etc/environment (not sure why the var is still called experimental), that forces deltas on …

i’ll do some testing over the weekend on a customer low-end device i have around here … and will collect some numbers

mvo · February 8, 2018, 2:05pm

Checking the source code we currently only enable deltas on classic. I think we should enable deltas everywhere, at least as an experiment on edge. I pushed https://github.com/snapcore/snapd/pull/4639 for this.

noise · February 8, 2018, 3:25pm

@mvo @ogra @awe we should ensure that device customers are notified to test this out for their particular devices. Hopefully it’s a good improvement for them but best to be sure.

niemeyer · February 8, 2018, 5:21pm

@ogra That variable is called experimental because it will go away, so please don’t use it anywhere where that name doesn’t make sense.

svet · February 8, 2018, 10:20pm

That sounds spot-on to me in terms of a way to manage it. I appreciate that some thought needs to go into ensuring it works in a predictable way for devices already out there. Thank you all for working on this!

svet · February 17, 2018, 2:09pm

I just got a chance to try this out, and it worked out great. Instead of downloading the whole 22MB snap, the 400KB delta was downloaded. Took about 5 seconds to apply on a RaspberryPi 3, which is perfectly reasonable. (FWIW, I also made the snap in question public: https://dashboard.snapcraft.io/snaps/stromm/)

2018/02/17 14:00:06.041390 store.go:1753: DEBUG: Successfully downloaded delta for "stromm" at /var/lib/snapd/snaps/stromm_27.snap.xdelta3-26-to-27.partial
2018/02/17 14:00:11.500543 store.go:1758: DEBUG: Successfully applied delta for "stromm" at /var/lib/snapd/snaps/stromm_27.snap.xdelta3-26-to-27.partial, saving 22772640 bytes.

So yes, as discussed before, if this deltas switch can be taken out of “experimental” mode that would be excellent!

anewman · March 1, 2018, 10:30pm

@mvo I’ve tested this on a low-end single-core ARM cortex-a7 device that we should consider our “worst case” using xdelta3 directly.

core 4020 -> 4114 (normal scenario ~8 seconds):

alextnewman@ricardo:~/delta-test$ ls -lh core_4*
-rw-r--r-- 1 alextnewman alextnewman 69M Mar  1 22:03 core_4020.snap
-rw-rw-r-- 1 alextnewman alextnewman 21M Mar  1 22:05 core_4020_to_4114.vcdiff
-rw-r--r-- 1 alextnewman alextnewman 69M Mar  1 21:47 core_4114.snap
alextnewman@ricardo:~/delta-test$ time xdelta3 -d -s core_4020.snap core_4020_to_4114.vcdiff core_out-2.snap

real	0m8.008s
user	0m0.790s
sys	0m2.710s

core 953 -> 4114 (huge diff ~9 seconds):

alextnewman@ricardo:~/delta-test$ ls -lh core_*
-rw-r--r-- 1 alextnewman alextnewman 69M Mar  1 21:47 core_4114.snap
-rw-r--r-- 1 alextnewman alextnewman 65M Mar  1 21:37 core_953.snap
-rw-rw-r-- 1 alextnewman alextnewman 53M Mar  1 21:52 core_953_to_4114.vcdiff
alextnewman@ricardo:~/delta-test$ time xdelta3 -d -s core_953.snap core_953_to_4114.vcdiff core_out.snap

real	0m9.162s
user	0m0.850s
sys	0m2.850s

rocketchat-server 1164 -> 1121 (normal diff, large snap ~21.3 seconds):

alextnewman@ricardo:~/delta-test$ ls -lh rocketchat*
-rw-r--r-- 1 alextnewman alextnewman 155M Mar  1 21:39 rocketchat-server_1164.snap
-rw-r--r-- 1 alextnewman alextnewman 162M Feb 28 21:07 rocketchat-server_1211.snap
-rw-rw-r-- 1 alextnewman alextnewman  47M Mar  1 21:46 rocketchat_1164_to_1211.vcdiff
alextnewman@ricardo:~/delta-test$ time xdelta3 -d -s rocketchat-server_1164.snap rocketchat_1164_to_1211.vcdiff rocketchat-server-out.snap

real	0m21.386s
user	0m1.860s
sys	0m6.240s

Considering this device is our “worst case” for performance, it looks to me like we’re not spending nearly the time reconstructing deltas that we are hashing, so I’m inclined to say that the trade-off is well worth the bandwidth saved. On x86, meanwhile, the performance hit appears to be fairly negligible (and this is where most of our current stakeholders are). So, I’m going to recommend this be “on” by default with the possibility to manually disable for bandwidth-rich time-critical deployments.