Tests broken in master

I’m not sure if that’s related to the changes that just landed in master, but the spread test fails on upgrade/basic test on core-support-plug, it’s apparently not recognized:

2017-05-02 08:50:59 Error executing linode:debian-unstable-64:tests/upgrade/basic : 
-----
+ '[' production = staging ']'
+ . /home/gopath/src/github.com/snapcore/snapd/tests/lib/apt.sh
+ echo Install previous version...
Install previous version...
+ dpkg -l snapd snap-confine
dpkg-query: no packages found matching snapd
dpkg-query: no packages found matching snap-confine
+ true
+ apt-get install -y snapd
Reading package lists...
Building dependency tree...
Reading state information...
The following additional packages will be installed:
  apparmor libapparmor-perl snap-confine ubuntu-core-launcher
Suggested packages:
  apparmor-profiles apparmor-profiles-extra apparmor-utils
The following NEW packages will be installed:
  apparmor libapparmor-perl snap-confine snapd ubuntu-core-launcher
0 upgraded, 5 newly installed, 0 to remove and 42 not upgraded.
Need to get 6,088 kB of archives.
After this operation, 32.3 MB of additional disk space will be used.
Get:1 http://mirrors.linode.com/debian unstable/main amd64 libapparmor-perl amd64 2.11.0-3 [82.1 kB]
Get:2 http://mirrors.linode.com/debian unstable/main amd64 apparmor amd64 2.11.0-3 [525 kB]
Get:3 http://mirrors.linode.com/debian unstable/main amd64 snap-confine amd64 2.21-2+b1 [65.2 kB]
Get:4 http://mirrors.linode.com/debian unstable/main amd64 ubuntu-core-launcher amd64 2.21-2+b1 [36.0 kB]
Get:5 http://mirrors.linode.com/debian unstable/main amd64 snapd amd64 2.21-2+b1 [5,380 kB]
Preconfiguring packages ...
Fetched 6,088 kB in 0s (57.2 MB/s)
Selecting previously unselected package libapparmor-perl.
(Reading database ... 54124 files and directories currently installed.)
Preparing to unpack .../libapparmor-perl_2.11.0-3_amd64.deb ...
Unpacking libapparmor-perl (2.11.0-3) ...
Selecting previously unselected package apparmor.
Preparing to unpack .../apparmor_2.11.0-3_amd64.deb ...
Unpacking apparmor (2.11.0-3) ...
Selecting previously unselected package snap-confine.
Preparing to unpack .../snap-confine_2.21-2+b1_amd64.deb ...
Unpacking snap-confine (2.21-2+b1) ...
Selecting previously unselected package ubuntu-core-launcher.
Preparing to unpack .../ubuntu-core-launcher_2.21-2+b1_amd64.deb ...
Unpacking ubuntu-core-launcher (2.21-2+b1) ...
Selecting previously unselected package snapd.
Preparing to unpack .../snapd_2.21-2+b1_amd64.deb ...
Unpacking snapd (2.21-2+b1) ...
Processing triggers for systemd (232-22) ...
Processing triggers for man-db (2.7.6.1-2) ...
Setting up libapparmor-perl (2.11.0-3) ...
Setting up apparmor (2.11.0-3) ...
Created symlink /etc/systemd/system/sysinit.target.wants/apparmor.service → /lib/systemd/system/apparmor.service.
update-rc.d: warning: start and stop actions are no longer supported; falling back to defaults
diff: /var/lib/apparmor/profiles/.apparmor.md5sums: No such file or directory
Setting up snap-confine (2.21-2+b1) ...
Setting up ubuntu-core-launcher (2.21-2+b1) ...
Setting up snapd (2.21-2+b1) ...
Created symlink /etc/systemd/system/multi-user.target.wants/snapd.autoimport.service → /lib/systemd/system/snapd.autoimport.service.
Created symlink /etc/systemd/system/timers.target.wants/snapd.refresh.timer → /lib/systemd/system/snapd.refresh.timer.
Created symlink /etc/systemd/system/sockets.target.wants/snapd.socket → /lib/systemd/system/snapd.socket.
Created symlink /etc/systemd/system/multi-user.target.wants/snapd.service → /lib/systemd/system/snapd.service.
Processing triggers for systemd (232-22) ...
++ grep 'snapd '
++ snap --version
+ prevsnapdver='snapd   2.21-2+b1'
+ echo Install sanity check snaps with it
Install sanity check snaps with it
+ snap install test-snapd-tools
2017-05-02T08:36:12Z INFO snap "core" has bad plugs or slots: core-support-plug (unknown interface)
[|] Run configure hook of "core" snap if present
<kill-timeout reached>
-----
travis_time:end:6048f58c:start=1493714160293836172,finish=1493715059353195394,duration=899059359222
travis_fold:end:fold-6048f58c
.
travis_fold:start:fold-b4b96f17
travis_time:start:b4b96f17
2017-05-02 08:50:59 Debug output for linode:debian-unstable-64:tests/upgrade/basic : 
-----
+ echo '# journal messages for snapd'
# journal messages for snapd
+ journalctl -u snapd
-- Logs begin at Tue 2017-05-02 08:36:00 UTC, end at Tue 2017-05-02 08:46:39 UTC. --
May 02 08:36:07 debian systemd[1]: Started Snappy daemon.
May 02 08:36:07 debian /usr/lib/snapd/snapd[25691]: daemon.go:250: DEBUG: init done in 700.593µs
May 02 08:36:07 debian /usr/lib/snapd/snapd[25691]: daemon.go:251: started snapd/2.21-2+b1 (series 16; classic; devmode) debian/9 (amd64).
May 02 08:36:07 debian snapd[25691]: 2017/05/02 08:36:07.554935 daemon.go:251: started snapd/2.21-2+b1 (series 16; classic; devmode) debian/9 (amd64).
May 02 08:36:07 debian /usr/lib/snapd/snapd[25691]: daemon.go:176: DEBUG: uid=0;@ GET /v2/system-info 331.058µs 200
May 02 08:36:07 debian /usr/lib/snapd/snapd[25691]: api.go:879: Installing snap "test-snapd-tools" revision unset
May 02 08:36:07 debian snapd[25691]: 2017/05/02 08:36:07.987671 api.go:879: Installing snap "test-snapd-tools" revision unset
May 02 08:36:08 debian /usr/lib/snapd/snapd[25691]: daemon.go:176: DEBUG: uid=0;@ POST /v2/snaps/test-snapd-tools 993.095813ms 202
May 02 08:36:08 debian /usr/lib/snapd/snapd[25691]: taskrunner.go:353: DEBUG: Running task 1 on Do: Download snap "core" (1689) from channel "stable"
May 02 08:36:11 debian /usr/lib/snapd/snapd[25691]: taskrunner.go:353: DEBUG: Running task 2 on Do: Fetch and check assertions for snap "core" (1689)
May 02 08:36:12 debian /usr/lib/snapd/snapd[25691]: taskrunner.go:353: DEBUG: Running task 3 on Do: Mount snap "core" (1689)
May 02 08:36:12 debian /usr/lib/snapd/snapd[25691]: taskrunner.go:353: DEBUG: Running task 4 on Do: Copy snap "core" data
May 02 08:36:12 debian /usr/lib/snapd/snapd[25691]: taskrunner.go:353: DEBUG: Running task 5 on Do: Setup snap "core" (1689) security profiles
May 02 08:36:12 debian /usr/lib/snapd/snapd[25691]: task.go:303: DEBUG: 2017-05-02T08:36:12Z INFO snap "core" has bad plugs or slots: core-support-plug (unknown interface)
May 02 08:36:12 debian /usr/lib/snapd/snapd[25691]: taskrunner.go:353: DEBUG: Running task 6 on Do: Make snap "core" (1689) available to the system
May 02 08:36:12 debian /usr/lib/snapd/snapd[25691]: task.go:303: DEBUG: 2017-05-02T08:36:12Z INFO Requested daemon restart.
May 02 08:36:13 debian systemd[1]: snapd.service: Service hold-off time over, scheduling restart.
May 02 08:36:13 debian systemd[1]: Stopped Snappy daemon.
May 02 08:36:13 debian systemd[1]: Started Snappy daemon.
May 02 08:36:13 debian /usr/lib/snapd/snapd[25870]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/lib/snapd/snapd"
May 02 08:36:13 debian /usr/lib/snapd/snapd[25870]: cmd.go:59: DEBUG: re-exec disabled by user
May 02 08:36:13 debian /usr/lib/snapd/snapd[25870]: snapmgr.go:309: DEBUG: snapmgr refresh randomness 40m31.149146106s
May 02 08:36:13 debian /usr/lib/snapd/snapd[25870]: daemon.go:250: DEBUG: init done in 920.82µs
May 02 08:36:13 debian /usr/lib/snapd/snapd[25870]: daemon.go:251: started snapd/2.24 (series 16; classic; devmode) debian/9 (amd64) linux/4.9.0-2-amd64.
May 02 08:36:13 debian snapd[25870]: 2017/05/02 08:36:13.861920 daemon.go:251: started snapd/2.24 (series 16; classic; devmode) debian/9 (amd64) linux/4.9.0-2-amd64.
May 02 08:36:13 debian /usr/lib/snapd/snapd[25870]: taskrunner.go:367: DEBUG: Running task 7 on Do: Set automatic aliases for snap "core"
May 02 08:36:13 debian /usr/lib/snapd/snapd[25870]: taskrunner.go:367: DEBUG: Running task 21 on Do: Mark system seeded
May 02 08:36:14 debian /usr/lib/snapd/snapd[25870]: store.go:1214: DEBUG: Deltas enabled. Adding header X-Ubuntu-Delta-Formats: xdelta3
May 02 08:36:14 debian /usr/lib/snapd/snapd[25870]: snapmgr.go:450: No snaps to auto-refresh found
May 02 08:36:14 debian snapd[25870]: 2017/05/02 08:36:14.770971 snapmgr.go:450: No snaps to auto-refresh found
May 02 08:36:14 debian /usr/lib/snapd/snapd[25870]: taskrunner.go:367: DEBUG: Running task 8 on Do: Setup snap "core" aliases
May 02 08:36:14 debian /usr/lib/snapd/snapd[25870]: taskrunner.go:367: DEBUG: Running task 9 on Do: Start snap "core" (1689) services
May 02 08:36:14 debian /usr/lib/snapd/snapd[25870]: taskrunner.go:367: DEBUG: Running task 10 on Do: Run configure hook of "core" snap if present
May 02 08:36:15 debian /snap/core/1689/usr/bin/snap[25892]: cmd.go:59: DEBUG: re-exec disabled by user
+ echo '# apparmor denials '
# apparmor denials 
+ grep DENIED
+ dmesg --ctime
+ true
+ echo '# seccomp denials (kills) '
# seccomp denials (kills) 
+ grep type=1326
+ dmesg --ctime
+ true
+ echo '# snap interfaces'
# snap interfaces
+ snap interfaces
Slot                      Plug
:account-control          -
:alsa                     -
:autopilot-introspection  -
:avahi-observe            -
:bluetooth-control        -
:browser-support          -
:camera                   -
:classic-support          -
:core-support             -
:cups-control             -
:dcdbas-control           -
:docker-support           -
:firewall-control         -
:framebuffer              -
:fuse-support             -
:gsettings                -
:hardware-observe         -
:home                     -
:io-ports-control         -
:joystick                 -
:kernel-module-control    -
:libvirt                  -
:locale-control           -
:log-observe              -
:lxd-support              -
:modem-manager            -
:mount-observe            -
:network                  -
:network-bind             -
:network-control          -
:network-manager          -
:network-observe          -
:network-setup-control    -
:network-setup-observe    -
:ofono                    -
:opengl                   -
:openvswitch              -
:openvswitch-support      -
:optical-drive            -
:physical-memory-control  -
:physical-memory-observe  -
:ppp                      -
:process-control          -
:pulseaudio               -
:raw-usb                  -
:removable-media          -
:screen-inhibit-control   -
:shutdown                 -
:snapd-control            -
:system-observe           -
:system-trace             -
:time-control             -
:timeserver-control       -
:timezone-control         -
:tpm                      -
:uhid                     -
:unity7                   -
:upower-observe           -
:x11                      -
-                         core:core-support-plug
-----
travis_time:end:b4b96f17:start=1493715059358658327,finish=1493715059510029071,duration=151370744
travis_fold:end:fold-b4b96f17
.
travis_time:start:bdca4fe6
2017-05-02 08:50:59 Restoring linode:debian-unstable-64:tests/upgrade/basic...

This is expected but should be harmless. I don’t know what is going on yet though.

So this part is the one that worries me. It should be connected.

Ok, some of the discussion about this problem took place on IRC, the summary is as follows:

  • can be reproduced manually with Debian and core image from stable.
  • works fine with core image from beta and edge.
  • the problem has been fixed in the code already and will go away once 2.25 is released.
  • for now though to unblock travis we will need to $ snap install --beta core for debian in the tests run - https://github.com/snapcore/snapd/pull/3259
1 Like

Thanks for summarizing the discussion!

11:52 < zyga_> morphis: hmm
11:52 < zyga_> morphis: so one question
11:52 < zyga_> morphis: after 2.25 is out it won’t change anything in debian
11:52 < zyga_> morphis: because debian is frozen, right?
11:52 < zyga_> morphis: so I’m trying to understand one thing there
11:52 < zyga_> morphis: the test installs some debs
11:52 < zyga_> morphis: are they not the same as snapd in edge?
11:52 < zyga_> morphis: (except for the name of the plug?)
11:53 < zyga_> morphis: what I’m trying to say is that perhaps, if we get this rigth, the change is not needed, no need to special-case debian
11:53 < zyga_> morphis: I think some code may be missing from master

I’m investigating this issue. I think the proposed PR hides a deeper problem. I’ll update this post with more data as I get it.

It looks like https://bugs.launchpad.net/snappy/+bug/1674193 came back with 2.24 after the fix was merged into 2.23.6. 2.25 seems to fix this again. Looks very much like some hiccup with picking the relevant changes into the right release and we somehow missed it to have them in 2.24

Yes, that seems to be it.

Currently the configure hook for core at revision 1689 does this:

# check if we have core support and exit cleanly if not
if ! systemctl --version >/dev/null 2>&1; then
    echo "Cannot run systemctl - is core-support available?"
    exit 0
fi

This check is insufficient for systems that don’t have apparmor enabled. The later versions of snapd have a fix so regardless if we update core to fix the script (to make the check more generic) or if we update it not to need the check in the first place, the result is the same.

EDIT: For some more context, this is the state of the system when this happens:

qemu:debian-9-64 .../tests/upgrade/basic# snap version
snap    2.24
snapd   2.24
series  16
debian  9
kernel  4.9.0-2-amd64
qemu:debian-9-64 .../tests/upgrade/basic# snap list
Name  Version  Rev   Developer  Notes
core  16-2     1689  canonical  -
qemu:debian-9-64 .../tests/upgrade/basic# snap changes
ID   Status  Spawn                 Ready                 Summary
1    Doing   2017-05-02T21:11:42Z  -                     Install "test-snapd-tools" snap
2    Done    2017-05-02T21:12:41Z  2017-05-02T21:12:41Z  Initialize system state
qemu:debian-9-64 .../tests/upgrade/basic# snap change 1
Status  Spawn                 Ready                 Summary
Done    2017-05-02T21:11:42Z  2017-05-02T21:12:40Z  Download snap "core" (1689) from channel "stable"
Done    2017-05-02T21:11:42Z  2017-05-02T21:12:40Z  Fetch and check assertions for snap "core" (1689)
Done    2017-05-02T21:11:42Z  2017-05-02T21:12:41Z  Mount snap "core" (1689)
Done    2017-05-02T21:11:42Z  2017-05-02T21:12:41Z  Copy snap "core" data
Done    2017-05-02T21:11:42Z  2017-05-02T21:12:41Z  Setup snap "core" (1689) security profiles
Done    2017-05-02T21:11:42Z  2017-05-02T21:12:41Z  Make snap "core" (1689) available to the system
Done    2017-05-02T21:11:42Z  2017-05-02T21:12:41Z  Set automatic aliases for snap "core"
Done    2017-05-02T21:11:42Z  2017-05-02T21:12:42Z  Setup snap "core" aliases
Done    2017-05-02T21:11:42Z  2017-05-02T21:12:42Z  Start snap "core" (1689) services
Doing   2017-05-02T21:11:42Z  -                     Run configure hook of "core" snap if present
Do      2017-05-02T21:11:42Z  -                     Download snap "test-snapd-tools" (3) from channel "stable"
Do      2017-05-02T21:11:42Z  -                     Fetch and check assertions for snap "test-snapd-tools" (3)
Do      2017-05-02T21:11:42Z  -                     Mount snap "test-snapd-tools" (3)
Do      2017-05-02T21:11:42Z  -                     Copy snap "test-snapd-tools" data
Do      2017-05-02T21:11:42Z  -                     Setup snap "test-snapd-tools" (3) security profiles
Do      2017-05-02T21:11:42Z  -                     Make snap "test-snapd-tools" (3) available to the system
Do      2017-05-02T21:11:42Z  -                     Set automatic aliases for snap "test-snapd-tools"
Do      2017-05-02T21:11:42Z  -                     Setup snap "test-snapd-tools" aliases
Do      2017-05-02T21:11:42Z  -                     Start snap "test-snapd-tools" (3) services
Do      2017-05-02T21:11:42Z  -                     Run configure hook of "test-snapd-tools" snap if present

......................................................................
Setup snap "core" (1689) security profiles

2017-05-02T23:12:41+02:00 INFO snap "core" has bad plugs or slots: core-support-plug (unknown interface)

......................................................................
Make snap "core" (1689) available to the system

2017-05-02T23:12:41+02:00 INFO Requested daemon restart.

So looking at the 2.24 tag we had implemented timeout support for hooks. For some reason it is not working. Investigating. EDIT: This is now tracked in topic Hook timeout mechanism not working in 2.24