insufficient logging with snappy install errors

[Jamie Strandboge]

In trying to help with the docker packaging, I tried to install a docker snap and saw only 'error status 1':

$ sudo snappy install --allow-unauthenticated /tmp/docker_1.5.0.001_multi.snap
Installing /tmp/docker_1.5.0.001_multi.snap
2015/04/09 21:32:57 Signature check failed, but installing anyway as requested
exit status 1

Since this was clearly insufficient to diagnose the problem, I then looked in the logs, but all I had was (see http://paste.ubuntu.com/10785971/):

Apr 9 21:15:58 localhost kernel: [ 2077.204842] audit: type=1400 audit(1428614158.872:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="docker_docker_1.5.0.001" pid=967 comm="apparmor_parser"
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199:exit status 1
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199:Stack trace:
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199: /build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:94 (0x43902e)
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199: /build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:89 (0x438e50)
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199: /build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/github.com/juju/loggo/writer.go:132 (0x4f3646)
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199: /build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/github.com/juju/loggo/logger.go:350 (0x4f29bc)
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199: /build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/github.com/juju/loggo/logger.go:310 (0x4f273f)
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199: /build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/github.com/juju/loggo/logger.go:360 (0x4f2ac1)
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199: /build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199 (0x439bbc)
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199: /build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/snappy/install.go:70 (0x44b049)
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199: /build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/cmd/snappy/cmd_install.go:72 (0x404a08)
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199: /build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/github.com/jessevdk/go-flags/parser.go:241 (0x4c35ad)
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199: /build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/github.com/jessevdk/go-flags/parser.go:126 (0x4c2d93)
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199: /build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/cmd/snappy/main.go:52 (0x40999a)
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199: /usr/lib/go/src/pkg/runtime/proc.c:247 (0x41cdaa)
Apr 9 21:16:00 localhost snappy[952]: ERROR:snappy:/build/buildd/ubuntu-snappy-0.1.2/obj-x86_64-linux-gnu/src/launchpad.net/snappy/logger/logger.go:199: /usr/lib/go/src/pkg/runtime/proc.c:1445 (0x41f570)

This did not give enough information to show what the problem was. In addition, because the install failed, everything was garbage collected and so there was nothing to debug. This made it extremely difficult to diagnose. Ideally the error reporting from 'snappy install' would be improved, but at a minimum the logging to syslog should be improved.

Turned out, a bad commit to meta/docker-daemon.apparmor resulted in a syntactically incorrect apparmor profile. Once that was corrected, everything was fine.

[Michael Terry (mterry)]

I'm having a hard time reproducing. Every syntax error I introduce into an apparmor file gets caught at install time with an exception from /usr/bin/aa-profile-hook.

I tried to discover what code you were using when you filed this. So I went back to r15 of lp:~snappy-dev/snappy-hub/docker. But after fixing up its yaml (no longer valid), I was able to install it fine.

Can I have a sample package that reproduces this?

[Michael Vogt (mvo)]

I'm pretty sure this is fixed with the commits:
  http://bazaar.launchpad.net/~snappy-dev/snappy/15.04/revision/436
  http://bazaar.launchpad.net/~snappy-dev/snappy/15.04/revision/445

With the v2 of 15.04/stable the error is still pretty useless:
$ sudo snappy install --allow-unauthenticated ./docker_1.6.0.001_multi.snap
Installing ./docker_1.6.0.001_multi.snap
2015/06/16 08:56:13 Signature check failed, but installing anyway as requested
2015/06/16 08:56:14 Warning: failed to remove /apps/docker/1.6.0.001: %!s(<nil>)
./docker_1.6.0.001_multi.snap failed to install: exit status 1

With v3 of 15.04/stable I get:
$ sudo snappy install docker_1.6.0.001_multi.snap --allow-unauthenticated
Installing docker_1.6.0.001_multi.snap
2015/06/16 08:58:25 Signature check failed, but installing anyway as requested
docker_1.6.0.001_multi.snap failed to install: hook command /usr/bin/aa-profile-hook failed with exit status 1 (output: 'Traceback (most recent call last):
  File "/usr/bin/aa-profile-hook", line 147, in <module>
    sys.exit(main())
  File "/usr/bin/aa-profile-hook", line 114, in main
    '--cache-loc=%s' % apparmor_cache])
  File "/usr/lib/python3/dist-packages/apparmor/click.py", line 121, in load_profiles
    (rc, output))
apparmor.common.AppArmorException: "policy load failed with errno 1: b'AppArmor parser error for /var/lib/apparmor/profiles/profile_docker_docker-daemon_1.6.0.001 in /var/lib/apparmor/profiles/profile_docker_docker-daemon_1.6.0.001 at line 20: syntax error, unexpected TOK_ID, expecting TOK_OPEN\\n'"
')
which is much more useful.