spread auto-refresh test failing in snapd 2.23

The spread test auto-refresh is failing on images installed from candidate snaps using snapd 2.23:

2017/03/13 02:39:01 Preparing external:ubuntu-core-16-64:tests/main/auto-refresh...
2017/03/13 02:39:08 Executing external:ubuntu-core-16-64:tests/main/auto-refresh (52/120)...
2017/03/13 02:41:13 Error executing external:ubuntu-core-16-64:tests/main/auto-refresh :
-----
+ echo 'Install a snap from stable'
Install a snap from stable
+ snap install test-snapd-tools

[|] Download snap "test-snapd-tools" (3) from channel "stable"
[/] Download snap "test-snapd-tools" (3) from channel "stable"
[-] Download snap "test-snapd-tools" (3) from channel "stable"
[\] Fetch and check assertions for snap "test-snapd-tools" (3)
[|] Fetch and check assertions for snap "test-snapd-tools" (3)
[/] Fetch and check assertions for snap "test-snapd-tools" (3)
[-] Fetch and check assertions for snap "test-snapd-tools" (3)
[\] Mount snap "test-snapd-tools" (3)
[|] Mount snap "test-snapd-tools" (3)
[/] Setup snap "test-snapd-tools" (3) security profiles
[-] Setup snap "test-snapd-tools" (3) security profiles
[\] Setup snap "test-snapd-tools" (3) security profiles
[|] Setup snap "test-snapd-tools" (3) security profiles
test-snapd-tools 1.0 from 'canonical' installed
+ snap list
+ MATCH 'test-snapd-tools +[0-9]+\.[0-9]+'
+ '[' -e /snap/core/current/meta/hooks/configure ']'
+ snap set core refresh.disabled=false

[|] Run configure hook of "core" snap
[/] Run configure hook of "core" snap
[-] Run configure hook of "core" snap
[\] Run configure hook of "core" snap
[|] Run configure hook of "core" snap
+ systemctl stop snapd.service snapd.socket
+ echo 'Modify the snap to track the edge channel'
Modify the snap to track the edge channel
+ jq '.data.snaps["test-snapd-tools"].channel = "edge"' /var/lib/snapd/state.json
+ mv /var/lib/snapd/state.json.new /var/lib/snapd/state.json
+ echo 'Modify the refresh.last'
Modify the refresh.last
+ jq '.data["config"]["core"]["refresh"]["last"] = "2007-08-22T09:30:44.449455783+01:00"' /var/lib/snapd/state.json
+ mv /var/lib/snapd/state.json.new /var/lib/snapd/state.json
+ systemctl start snapd.service snapd.socket
+ echo 'wait for auto-refresh to happen'
wait for auto-refresh to happen
++ seq 120
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ grep -q 'Done.*Refresh snap'
+ snap changes
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ grep -q 'Done.*Refresh snap'
+ snap changes
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ grep -q 'Done.*Refresh snap'
+ snap changes
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ grep -q 'Done.*Refresh snap'
+ snap changes
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ grep -q 'Done.*Refresh snap'
+ snap changes
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ grep -q 'Done.*Refresh snap'
+ snap changes
+ sleep 1
+ for i in '$(seq 120)'
+ grep -q 'Done.*Refresh snap'
+ snap changes
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ grep -q 'Done.*Refresh snap'
+ snap changes
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ grep -q 'Done.*Refresh snap'
+ snap changes
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ grep -q 'Done.*Refresh snap'
+ snap changes
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ grep -q 'Done.*Refresh snap'
+ snap changes
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ grep -q 'Done.*Refresh snap'
+ snap changes
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ grep -q 'Done.*Refresh snap'
+ snap changes
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ grep -q 'Done.*Refresh snap'
+ snap changes
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ snap changes
+ grep -q 'Done.*Refresh snap'
+ sleep 1
+ for i in '$(seq 120)'
+ grep -q 'Done.*Refresh snap'
+ snap changes
+ sleep 1
+ echo 'Ensure our snap got updated'
Ensure our snap got updated
+ snap list
+ MATCH 'test-snapd-tools +[0-9]+\.[0-9]+\+fake1'
error: pattern not found, got:
Name Version Rev Developer Notes
core 16-2 1441 canonical -
jq 1.5+dfsg-1 6 canonical devmode
pc 16.04-0.8 9 canonical -
pc-kernel 4.4.0-64.85 57 canonical -
test-snapd-tools 1.0 3 canonical -
-----
2017/03/13 02:41:13 Debug output for external:ubuntu-core-16-64:tests/main/auto-refresh :
-----
+ journalctl -u snapd
-- Logs begin at Mon 2017-03-13 06:39:01 UTC, end at Mon 2017-03-13 06:41:13 UTC. --
Mar 13 06:39:01 localhost.localdomain /usr/lib/snapd/snapd[1090]: daemon.go:176: DEBUG: uid=0;@ GET /v2/snaps 1.859269ms 200
Mar 13 06:39:01 localhost.localdomain /usr/lib/snapd/snapd[1090]: daemon.go:176: DEBUG: uid=0;@ GET /v2/snaps 1.670357ms 200
Mar 13 06:39:01 localhost.localdomain systemd[1]: Stopping Snappy daemon...
Mar 13 06:39:01 localhost.localdomain snapd[1090]: 2017/03/13 06:39:01.158029 main.go:71: Exiting on terminated signal.
Mar 13 06:39:01 localhost.localdomain systemd[1]: Stopped Snappy daemon.
Mar 13 06:39:03 localhost.localdomain systemd[1]: Started Snappy daemon.
Mar 13 06:39:03 localhost.localdomain /usr/lib/snapd/snapd[1384]: snapmgr.go:373: DEBUG: snapmgr refresh randomness 1h6m42.690457297s
Mar 13 06:39:03 localhost.localdomain /usr/lib/snapd/snapd[1384]: daemon.go:250: DEBUG: init done in 424.403µs
Mar 13 06:39:03 localhost.localdomain /usr/lib/snapd/snapd[1384]: daemon.go:251: started snapd/2.23.1 (series 16) ubuntu-core/16 (amd64) linux/4.4.0-64-generic.
Mar 13 06:39:03 localhost.localdomain snapd[1384]: 2017/03/13 06:39:03.679206 daemon.go:251: started snapd/2.23.1 (series 16) ubuntu-core/16 (amd64) linux/4.4.0-64-generic.
Mar 13 06:39:03 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 56 on Do: Generate device key
Mar 13 06:39:03 localhost.localdomain /usr/lib/snapd/snapd[1384]: api.go:891: Installing snap "jq" revision unset
Mar 13 06:39:03 localhost.localdomain snapd[1384]: 2017/03/13 06:39:03.686021 api.go:891: Installing snap "jq" revision unset
Mar 13 06:39:03 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 57 on Do: Request device serial
Mar 13 06:39:04 localhost.localdomain /usr/lib/snapd/snapd[1384]: daemon.go:176: DEBUG: uid=0;@ POST /v2/snaps/jq 729.824748ms 202
Mar 13 06:39:04 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 58 on Do: Download snap "jq" (6) from channel "stable"
Mar 13 06:39:05 localhost.localdomain /usr/lib/snapd/snapd[1384]: task.go:303: DEBUG: 2017-03-13T06:39:05Z ERROR cannot deliver device serial request: Cannot process serial request for device with brand "swkMRzrLrTFXa3s7m1Nfdn4OGU4tjbYA", store can sign serial only for brand "canonical"
Mar 13 06:39:06 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 59 on Do: Fetch and check assertions for snap "jq" (6)
Mar 13 06:39:07 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 60 on Do: Mount snap "jq" (6)
Mar 13 06:39:07 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 61 on Do: Copy snap "jq" data
Mar 13 06:39:07 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 62 on Do: Setup snap "jq" (6) security profiles
Mar 13 06:39:07 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 63 on Do: Make snap "jq" (6) available to the system
Mar 13 06:39:07 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 64 on Do: Set automatic aliases for snap "jq"
Mar 13 06:39:07 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 65 on Do: Setup snap "jq" aliases
Mar 13 06:39:07 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 66 on Do: Start snap "jq" (6) services
Mar 13 06:39:07 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 67 on Do: Run configure hook of "jq" snap if present
Mar 13 06:39:07 localhost.localdomain /usr/lib/snapd/snapd[1384]: daemon.go:176: DEBUG: uid=0;@ GET /v2/snaps 1.280345ms 200
Mar 13 06:39:07 localhost.localdomain /usr/lib/snapd/snapd[1384]: api.go:891: Installing snap "test-snapd-tools" revision unset
Mar 13 06:39:07 localhost.localdomain snapd[1384]: 2017/03/13 06:39:07.588637 api.go:891: Installing snap "test-snapd-tools" revision unset
Mar 13 06:39:07 localhost.localdomain /usr/lib/snapd/snapd[1384]: daemon.go:176: DEBUG: uid=0;@ POST /v2/snaps/test-snapd-tools 154.686418ms 202
Mar 13 06:39:07 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 68 on Do: Download snap "test-snapd-tools" (3) from channel "stable"
Mar 13 06:39:08 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 69 on Do: Fetch and check assertions for snap "test-snapd-tools" (3)
Mar 13 06:39:08 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 70 on Do: Mount snap "test-snapd-tools" (3)
Mar 13 06:39:08 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 71 on Do: Copy snap "test-snapd-tools" data
Mar 13 06:39:08 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 72 on Do: Setup snap "test-snapd-tools" (3) security profiles
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 73 on Do: Make snap "test-snapd-tools" (3) available to the system
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 74 on Do: Set automatic aliases for snap "test-snapd-tools"
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 75 on Do: Setup snap "test-snapd-tools" aliases
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 76 on Do: Start snap "test-snapd-tools" (3) services
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 77 on Do: Run configure hook of "test-snapd-tools" snap if present
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1384]: daemon.go:176: DEBUG: uid=0;@ GET /v2/snaps 1.967636ms 200
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1384]: daemon.go:176: DEBUG: uid=0;@ GET /v2/snaps 1.847184ms 200
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1384]: daemon.go:176: DEBUG: uid=0;@ PUT /v2/snaps/core/conf 14.060746ms 202
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1384]: taskrunner.go:353: DEBUG: Running task 78 on Do: Run configure hook of "core" snap
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1384]: daemon.go:176: DEBUG: @ POST /v2/snapctl 162.641µs 200
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1384]: daemon.go:176: DEBUG: @ POST /v2/snapctl 175.477µs 200
Mar 13 06:39:09 localhost.localdomain systemd[1]: Stopping Snappy daemon...
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1384]: main.go:71: Exiting on terminated signal.
Mar 13 06:39:09 localhost.localdomain snapd[1384]: 2017/03/13 06:39:09.671352 main.go:71: Exiting on terminated signal.
Mar 13 06:39:09 localhost.localdomain systemd[1]: Stopped Snappy daemon.
Mar 13 06:39:09 localhost.localdomain systemd[1]: Started Snappy daemon.
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1635]: snapmgr.go:373: DEBUG: snapmgr refresh randomness 1h50m48.351252206s
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:250: DEBUG: init done in 575.128µs
Mar 13 06:39:09 localhost.localdomain snapd[1635]: 2017/03/13 06:39:09.882957 daemon.go:251: started snapd/2.23.1 (series 16) ubuntu-core/16 (amd64) linux/4.4.0-64-generic.
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:251: started snapd/2.23.1 (series 16) ubuntu-core/16 (amd64) linux/4.4.0-64-generic.
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1635]: taskrunner.go:353: DEBUG: Running task 79 on Do: Generate device key
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 19.451154ms 200
Mar 13 06:39:09 localhost.localdomain /usr/lib/snapd/snapd[1635]: taskrunner.go:353: DEBUG: Running task 80 on Do: Request device serial
Mar 13 06:39:10 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.07443ms 200
Mar 13 06:39:11 localhost.localdomain /usr/lib/snapd/snapd[1635]: task.go:303: DEBUG: 2017-03-13T06:39:11Z ERROR cannot deliver device serial request: Cannot process serial request for device with brand "swkMRzrLrTFXa3s7m1Nfdn4OGU4tjbYA", store can sign serial only for brand "canonical"
Mar 13 06:39:11 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 7.113421ms 200
Mar 13 06:39:12 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.081175ms 200
Mar 13 06:39:13 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.476279ms 200
Mar 13 06:39:15 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.028726ms 200
Mar 13 06:39:16 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.33613ms 200
Mar 13 06:39:17 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.10627ms 200
Mar 13 06:39:18 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.249117ms 200
Mar 13 06:39:19 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.436449ms 200
Mar 13 06:39:20 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 990.935µs 200
Mar 13 06:39:21 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.305867ms 200
Mar 13 06:39:22 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.067254ms 200
Mar 13 06:39:23 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.456707ms 200
Mar 13 06:39:24 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.04694ms 200
Mar 13 06:39:25 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.537127ms 200
Mar 13 06:39:26 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.107063ms 200
Mar 13 06:39:27 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.592272ms 200
Mar 13 06:39:28 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 958.331µs 200
Mar 13 06:39:30 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.405888ms 200
Mar 13 06:39:31 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.072034ms 200
Mar 13 06:39:32 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.367448ms 200
Mar 13 06:39:33 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 972.655µs 200
Mar 13 06:39:34 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.325557ms 200
Mar 13 06:39:35 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.062845ms 200
Mar 13 06:39:36 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.369439ms 200
Mar 13 06:39:37 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.058808ms 200
Mar 13 06:39:38 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.326143ms 200
Mar 13 06:39:39 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.07325ms 200
Mar 13 06:39:40 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.455046ms 200
Mar 13 06:39:41 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.129437ms 200
Mar 13 06:39:42 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.360569ms 200
Mar 13 06:39:43 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.343277ms 200
Mar 13 06:39:44 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.478462ms 200
Mar 13 06:39:45 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.404049ms 200
Mar 13 06:39:46 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.467047ms 200
Mar 13 06:39:47 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.009664ms 200
Mar 13 06:39:48 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.03516ms 200
Mar 13 06:39:49 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.02211ms 200
Mar 13 06:39:50 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.02455ms 200
Mar 13 06:39:51 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.368632ms 200
Mar 13 06:39:52 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.022757ms 200
Mar 13 06:39:53 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.390086ms 200
Mar 13 06:39:54 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.057719ms 200
Mar 13 06:39:55 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 4.028362ms 200
Mar 13 06:39:56 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.122872ms 200
Mar 13 06:39:57 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.383948ms 200
Mar 13 06:39:58 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.127067ms 200
Mar 13 06:39:59 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.455495ms 200
Mar 13 06:40:00 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 914.679µs 200
Mar 13 06:40:01 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.401714ms 200
Mar 13 06:40:02 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.09965ms 200
Mar 13 06:40:03 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.322934ms 200
Mar 13 06:40:04 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.054437ms 200
Mar 13 06:40:05 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.338864ms 200
Mar 13 06:40:06 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.129452ms 200
Mar 13 06:40:07 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.240679ms 200
Mar 13 06:40:08 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.091751ms 200
Mar 13 06:40:09 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 4.018102ms 200
Mar 13 06:40:10 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.139436ms 200
Mar 13 06:40:11 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.334701ms 200
Mar 13 06:40:13 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.101234ms 200
Mar 13 06:40:14 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.350135ms 200
Mar 13 06:40:15 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.126708ms 200
Mar 13 06:40:16 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.344971ms 200
Mar 13 06:40:17 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.070457ms 200
Mar 13 06:40:18 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.435972ms 200
Mar 13 06:40:19 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.030718ms 200
Mar 13 06:40:20 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.150667ms 200
Mar 13 06:40:21 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.08668ms 200
Mar 13 06:40:22 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.076575ms 200
Mar 13 06:40:23 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.054608ms 200
Mar 13 06:40:24 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 3.686832ms 200
Mar 13 06:40:25 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.084384ms 200
Mar 13 06:40:26 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.549112ms 200
Mar 13 06:40:27 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.016854ms 200
Mar 13 06:40:28 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.369289ms 200
Mar 13 06:40:29 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.012124ms 200
Mar 13 06:40:30 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.389985ms 200
Mar 13 06:40:31 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.048309ms 200
Mar 13 06:40:32 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.462977ms 200
Mar 13 06:40:33 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.023089ms 200
Mar 13 06:40:34 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.451709ms 200
Mar 13 06:40:35 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.057861ms 200
Mar 13 06:40:36 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.410186ms 200
Mar 13 06:40:37 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.014713ms 200
Mar 13 06:40:38 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 3.924559ms 200
Mar 13 06:40:39 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 959.598µs 200
Mar 13 06:40:40 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.404956ms 200
Mar 13 06:40:41 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.452571ms 200
Mar 13 06:40:42 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.068063ms 200
Mar 13 06:40:43 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.308556ms 200
Mar 13 06:40:44 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.066855ms 200
Mar 13 06:40:45 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.416114ms 200
Mar 13 06:40:46 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.091656ms 200
Mar 13 06:40:47 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.33137ms 200
Mar 13 06:40:48 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.022017ms 200
Mar 13 06:40:49 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.441205ms 200
Mar 13 06:40:50 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 929.793µs 200
Mar 13 06:40:51 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.487387ms 200
Mar 13 06:40:52 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 3.350074ms 200
Mar 13 06:40:53 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.375078ms 200
Mar 13 06:40:54 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.109495ms 200
Mar 13 06:40:55 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.460384ms 200
Mar 13 06:40:56 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.085409ms 200
Mar 13 06:40:57 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.305745ms 200
Mar 13 06:40:58 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.124246ms 200
Mar 13 06:40:59 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.450213ms 200
Mar 13 06:41:00 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 972.551µs 200
Mar 13 06:41:01 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.323813ms 200
Mar 13 06:41:03 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.049947ms 200
Mar 13 06:41:04 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.300789ms 200
Mar 13 06:41:05 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.011783ms 200
Mar 13 06:41:06 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.462001ms 200
Mar 13 06:41:07 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.100137ms 200
Mar 13 06:41:08 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 3.983045ms 200
Mar 13 06:41:09 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.058616ms 200
Mar 13 06:41:10 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.313061ms 200
Mar 13 06:41:11 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.014254ms 200
Mar 13 06:41:12 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/changes?select=all 1.355213ms 200
Mar 13 06:41:13 localhost.localdomain /usr/lib/snapd/snapd[1635]: daemon.go:176: DEBUG: uid=0;@ GET /v2/snaps 2.16409ms 200
+ dmesg
+ grep DENIED
[ 18.634167] audit: type=1400 audit(1489387149.560:20): apparmor="DENIED" operation="create" profile="snap.core.hook.configure" pid=1604 comm="snapctl" family="inet" sock_type="stream" protocol=6 requested_mask="create" denied_mask="create"
-----
2017/03/13 02:41:13 Restoring external:ubuntu-core-16-64:tests/main/auto-refresh...