canonical-livepatch snap not working

[Sascha Möller]

I installed snap and canonical-livepatch on my Ubuntu 18.04 LTS Server.

When i pass:

canonical-livepatch enable [My-Key]

i get following output after a few seconds:

sh: echo: I/O error
child exited with status 1

Trying again:

sh: echo: I/O error
child exited with status 1: File exists

Re installation of the snap is not working, also not resetting the machine-id.

snap info canonical-livepatch:

name: canonical-livepatch
summary: Canonical Livepatch Client
publisher: Canonical✓
store-url: https://snapcraft.io/canonical-livepatch
contact: <email address hidden>
license: unset
description: |
  Canonical Livepatch Client
commands:
  - canonical-livepatch
services:
  canonical-livepatch.canonical-livepatchd: simple, enabled, inactive
snap-id: b96UJ4vttpNhpbaCWctVzfduQcPwQ5wn
tracking: latest/stable
refresh-date: gestern um 16:05 CEST
channels:
  latest/stable: 9.5.5 2020-03-16 (95) 9MB -
  latest/candidate: ↑
  latest/beta: ↑
  latest/edge: 9.5.5 2020-03-16 (95) 9MB -
installed: 9.5.5 (95) 9MB -

canonical-livepatch status --verbose:

sh: echo: I/O error
child exited with status 1: File exists

lsb_release -a:

No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 18.04.5 LTS
Release: 18.04
Codename: bionic

uname -a:

Linux h2906342.stratoserver.net 4.15.0 #1 SMP Tue Jun 9 12:58:54 MSK 2020 x86_64 x86_64 x86_64 GNU/Linux

journalctl -t canonical-livepatch:

No journal files were found.
-- No entries --

snap interfaces:

Slot Plug
:account-control -
:accounts-service -
:adb-support -
:alsa -
:appstream-metadata -
:audio-playback -
:audio-record -
:autopilot-introspection -
:avahi-control -
:avahi-observe -
:block-devices -
:bluetooth-control -
:bluez -
:broadcom-asic-control -
:browser-support -
:calendar-service -
:camera -
:can-bus -
:cifs-mount -
:classic-support -
:contacts-service -
:core-support -
:cpu-control -
:cups-control -
:daemon-notify -
:dcdbas-control -
:desktop -
:desktop-legacy -
:device-buttons -
:display-control -
:docker-support -
:dvb -
:firewall-control -
:framebuffer -
:fuse-support -
:fwupd -
:gconf -
:gpg-keys -
:gpg-public-keys -
:gpio-control -
:gpio-memory-control -
:greengrass-support -
:gsettings -
:hardware-observe canonical-livepatch
:hardware-random-control -
:hardware-random-observe -
:home -
:hostname-control -
:hugepages-control -
:intel-mei -
:io-ports-control -
:jack1 -
:joystick -
:juju-client-observe -
:kernel-crypto-api -
:kernel-module-control canonical-livepatch
:kernel-module-observe -
:kubernetes-support -
:kvm -
:libvirt -
:locale-control -
:log-observe -
:login-session-control -
:login-session-observe -
:lxd-support -
:modem-manager -
:mount-observe -
:multipass-support -
:netlink-audit -
:netlink-connector -
:network -
:network-bind canonical-livepatch
:network-control canonical-livepatch
:network-manager canonical-livepatch
:network-manager-observe -
:network-observe -
:network-setup-control -
:network-setup-observe -
:network-status -
:ofono -
:opengl -
:openvswitch -
:openvswitch-support -
:optical-drive -
:packagekit-control -
:password-manager-service -
:personal-files -
:physical-memory-control -
:physical-memory-observe -
:power-control -
:ppp -
:process-control -
:pulseaudio -
:raw-usb -
:removable-media -
:screen-inhibit-control -
:screencast-legacy -
:shutdown -
:snapd-control -
:ssh-keys -
:ssh-public-keys -
:system-backup -
:system-files -
:system-observe canonical-livepatch
:system-packages-doc -
:system-source-code -
:system-trace -
:time-control -
:timeserver-control -
:timezone-control -
:tpm -
:u2f-devices -
:udisks2 -
:uhid -
:uinput -
:unity7 -
:upower-observe -
:vcio -
:wayland -
:x11 -

»snap interfaces« ist veraltet; bitte »snap connectionsx verwenden.

dmesg :

[694220.993059] device vethc826e85 entered promiscuous mode
[694221.416158] device vethc826e85 left promiscuous mode
[694221.715210] device veth1115972 entered promiscuous mode
[694222.207602] device veth1115972 left promiscuous mode
[694222.526499] device vethcc18ae1 entered promiscuous mode
[694222.981992] device vethcc18ae1 left promiscuous mode
[694223.302951] device veth1707633 entered promiscuous mode
[694223.743747] device veth1707633 left promiscuous mode
[694224.037116] device veth30f2ab1 entered promiscuous mode
[694224.428868] device veth30f2ab1 left promiscuous mode
[694224.722175] device veth6c9c16c entered promiscuous mode
[696860.345401] device vethbfb9c8f entered promiscuous mode
[696870.512587] device vethbfb9c8f left promiscuous mode
[703592.862587] device veth1b73f16 entered promiscuous mode
[703593.278316] device veth1b73f16 left promiscuous mode
[705110.321189] device veth9424779 entered promiscuous mode
[705110.735827] device veth9424779 left promiscuous mode
[705129.750070] device veth6c9c16c left promiscuous mode
[705130.892837] device vethd2827db entered promiscuous mode
[705131.418529] device vethd2827db left promiscuous mode
[705131.727864] device veth014a89f entered promiscuous mode
[705132.215231] device veth014a89f left promiscuous mode
[705132.480437] device veth760e55a entered promiscuous mode
[705132.952116] device veth760e55a left promiscuous mode
[705133.289842] device veth55e123c entered promiscuous mode
[705133.778311] device veth55e123c left promiscuous mode
[705134.064326] device vethf34178b entered promiscuous mode
[705134.555991] device vethf34178b left promiscuous mode
[705134.810170] device veth7a5d25c entered promiscuous mode
[705135.294897] device veth7a5d25c left promiscuous mode
[705135.523847] device vethdeba509 entered promiscuous mode
[705136.011912] device vethdeba509 left promiscuous mode
[705136.282774] device veth98b8e56 entered promiscuous mode
[705136.742014] device veth98b8e56 left promiscuous mode
[705136.972602] device veth230be3f entered promiscuous mode
[705137.504083] device veth230be3f left promiscuous mode
[705137.754746] device vethd338628 entered promiscuous mode
[705138.247883] device vethd338628 left promiscuous mode
[705138.479038] device veth4346d2e entered promiscuous mode
[705138.966543] device veth4346d2e left promiscuous mode
[705139.239642] device veth51bf225 entered promiscuous mode
[705376.607983] device veth51bf225 left promiscuous mode
[705502.034061] device veth16561d2 entered promiscuous mode
[705502.515700] device veth16561d2 left promiscuous mode
[705502.803703] device veth3385f67 entered promiscuous mode
[705503.313996] device veth3385f67 left promiscuous mode
[705503.585559] device veth53c60e3 entered promiscuous mode
[705504.091747] device veth53c60e3 left promiscuous mode
[705505.090134] device veth0367405 entered promiscuous mode
[705505.667656] device veth0367405 left promiscuous mode
[705506.163871] device vetha784d41 entered promiscuous mode
[705506.648791] device vetha784d41 left promiscuous mode
[705507.368928] device veth3c61827 entered promiscuous mode
[705507.907369] device veth3c61827 left promiscuous mode
[705508.213748] device vethf40ec07 entered promiscuous mode
[705508.718336] device vethf40ec07 left promiscuous mode
[705509.022551] device vethfcda8e2 entered promiscuous mode
[705509.493727] device vethfcda8e2 left promiscuous mode
[705509.768884] device vethd9bb4d1 entered promiscuous mode
[705510.257654] device vethd9bb4d1 left promiscuous mode
[705510.514111] device veth7240810 entered promiscuous mode
[705510.989010] device veth7240810 left promiscuous mode
[705511.247923] device vethe3acd3a entered promiscuous mode
[705511.683397] device vethe3acd3a left promiscuous mode
[705511.927507] device vethf7d031e entered promiscuous mode
[705512.401745] device vethf7d031e left promiscuous mode
[705512.695022] device veth0fb0ba0 entered promiscuous mode
[705513.074944] device veth0fb0ba0 left promiscuous mode
[705513.326566] device veth21ba283 entered promiscuous mode

[Ubuntu Foundations Team Bug Bot (crichton)]

Thank you for taking the time to report this bug and helping to make Ubuntu better. It seems that your bug report is not filed about a specific source package though, rather it is just filed against Ubuntu in general. It is important that bug reports be filed about source packages so that people interested in the package can find the bugs about it. You can find some hints about determining what package your bug might be about at https://wiki.ubuntu.com/Bugs/FindRightPackage. You might also ask for help in the #ubuntu-bugs irc channel on Freenode.

To change the source package that this bug is filed about visit https://bugs.launchpad.net/ubuntu/+bug/1898473/+editstatus and add the package name in the text box next to the word Package.

[This is an automated message. I apologize if it reached you inappropriately; please just reply to this message indicating so.]

[Casey Marshall (cmars)]

Please include the output from the following commands in your report as plain text.

snap info canonical-livepatch
canonical-livepatch status --verbose
lsb_release -a
uname -a
journalctl -t canonical-livepatch
snap interfaces
dmesg

[Sascha Möller (sascha-speed)]

Edited my starting post and added the report of all said commands.

[Casey Marshall (cmars)]

Not really seeing anything helpful in the command output.

Could you try:

1) Rerunning the `canonical-livepatch enable` command
2) Attach a snippet of /var/log/syslog messages covering the time span when performing (1)

Thanks!

[Sascha Möller (sascha-speed)]

Nothing was added to the syslog when i run "canonical-livepatch enable [my-id]"

Basically i run the command at 16:30, but the last logs timestamp is 16:26.

[Sascha Möller (sascha-speed)]

In case you still want to see it:

Oct 5 16:26:03 h2906342 systemd[1]: <email address hidden>: Service has no hold-off time, scheduling restart.
Oct 5 16:26:03 h2906342 systemd[1]: <email address hidden>: Scheduled restart job, restart counter is at 96.
Oct 5 16:26:03 h2906342 systemd[1]: Stopped Getty on tty2.
Oct 5 16:26:05 h2906342 systemd[1]: Started Getty on tty2.
Oct 5 16:26:05 h2906342 systemd[1]: console-getty.service: Service hold-off time over, scheduling restart.
Oct 5 16:26:05 h2906342 systemd[1]: console-getty.service: Scheduled restart job, restart counter is at 96.
Oct 5 16:26:05 h2906342 systemd[1]: Stopped Console Getty.
Oct 5 16:26:12 h2906342 systemd[1]: Started Console Getty.

[Casey Marshall (cmars)]

Try `sudo snap restart canonical-livepatch` and then try `canonical-livepatch enable`.. is anything written to syslog then?

[Casey Marshall (cmars)]

To clarify, it needs to be `sudo canonical-livepatch enable {token}`.

[Sascha Möller (sascha-speed)]

Yup!

Oct 5 19:19:19 h2906342 systemd[1]: Started Service for snap application canonical-livepatch.canonical-livepatchd.
Oct 5 19:19:19 h2906342 canonical-livepatch.canonical-livepatchd[6000]: sh: echo: I/O error
Oct 5 19:19:19 h2906342 canonical-livepatch.canonical-livepatchd[6000]: child exited with status 1: File exists
Oct 5 19:19:19 h2906342 systemd[1]: snap.canonical-livepatch.canonical-livepatchd.service: Main process exited, code=exited, status=1/FAILURE
Oct 5 19:19:19 h2906342 systemd[1]: snap.canonical-livepatch.canonical-livepatchd.service: Failed with result 'exit-code'.
Oct 5 19:19:20 h2906342 systemd[1]: snap.canonical-livepatch.canonical-livepatchd.service: Service hold-off time over, scheduling restart.
Oct 5 19:19:20 h2906342 systemd[1]: snap.canonical-livepatch.canonical-livepatchd.service: Scheduled restart job, restart counter is at 1.
Oct 5 19:19:20 h2906342 systemd[1]: Stopped Service for snap application canonical-livepatch.canonical-livepatchd.
Oct 5 19:19:23 h2906342 systemd[1]: Started Service for snap application canonical-livepatch.canonical-livepatchd.
Oct 5 19:19:23 h2906342 canonical-livepatch.canonical-livepatchd[6023]: sh: echo: I/O error
Oct 5 19:19:23 h2906342 canonical-livepatch.canonical-livepatchd[6023]: child exited with status 1: File exists
Oct 5 19:19:23 h2906342 systemd[1]: snap.canonical-livepatch.canonical-livepatchd.service: Main process exited, code=exited, status=1/FAILURE
Oct 5 19:19:23 h2906342 systemd[1]: snap.canonical-livepatch.canonical-livepatchd.service: Failed with result 'exit-code'.
Oct 5 19:19:24 h2906342 systemd[1]: snap.canonical-livepatch.canonical-livepatchd.service: Service hold-off time over, scheduling restart.
Oct 5 19:19:24 h2906342 systemd[1]: snap.canonical-livepatch.canonical-livepatchd.service: Scheduled restart job, restart counter is at 2.
Oct 5 19:19:24 h2906342 systemd[1]: Stopped Service for snap application canonical-livepatch.canonical-livepatchd.
Oct 5 19:19:25 h2906342 systemd[1]: Started Service for snap application canonical-livepatch.canonical-livepatchd.
Oct 5 19:19:29 h2906342 canonical-livepatch.canonical-livepatchd[6055]: sh: echo: I/O error
Oct 5 19:19:29 h2906342 canonical-livepatch.canonical-livepatchd[6055]: child exited with status 1: File exists
Oct 5 19:19:29 h2906342 systemd[1]: snap.canonical-livepatch.canonical-livepatchd.service: Main process exited, code=exited, status=1/FAILURE
Oct 5 19:19:29 h2906342 systemd[1]: snap.canonical-livepatch.canonical-livepatchd.service: Failed with result 'exit-code'.
Oct 5 19:19:29 h2906342 systemd[1]: snap.canonical-livepatch.canonical-livepatchd.service: Service hold-off time over, scheduling restart.
Oct 5 19:19:29 h2906342 systemd[1]: snap.canonical-livepatch.canonical-livepatchd.service: Scheduled restart job, restart counter is at 3.
Oct 5 19:19:29 h2906342 systemd[1]: Stopped Service for snap application canonical-livepatch.canonical-livepatchd.
Oct 5 19:19:33 h2906342 systemd[1]: Started Service for snap application canonical-livepatch.canonical-livepatchd.
Oct 5 19:19:33 h2906342 canonical-livepatch.canonical-livepatchd[6107]: sh: echo: I/O error
Oct 5 19:19:33 h2906342 canon...

[Casey Marshall (cmars)]

Interesting. Could you run:

    sudo strace /snap/bin/canonical-livepatch enable {token} 2>&1 | tee strace.log

and attach strace.log?

Thanks again!

[Sascha Möller (sascha-speed)]

Here you go!

[Casey Marshall (cmars)]

This looks like a problem with snapd being unable to launch the process in a sandbox. Adding snapd developers to take a look.

[Zygmunt Krynicki (zyga)]

Dear Sascha, could you attach an output of strace -f?

In addition, please attach the output of:

cat /proc/cmdline

cat /proc/self/mountinfo

[Sascha Möller (sascha-speed)]

On the strace it didn't exit automatically (not sure if this is intended), i waited 5 minutes on the last line before canceling manually.

cat /proc/cmdline

quiet

cat /proc/self/mountinfo

2655 2517 182:696641 / / rw,relatime shared:2202 - ext4 /dev/ploop43540p1 rw,stripe=4096,data=ordered,balloon_ino=12,jqfmt=vfsv1,usrjquota=aquota.user,grpjquota=aquota.group
2656 2655 0:381 / /sys rw,relatime shared:2203 - sysfs none rw
2657 2656 0:382 / /sys/fs/cgroup ro,nosuid,nodev,noexec shared:2204 - tmpfs none ro
2658 2657 0:28 / /sys/fs/cgroup/cpu,cpuacct rw,nosuid,nodev,noexec,relatime shared:2205 - cgroup cgroup rw,cpuacct,cpu
2659 2657 0:30 / /sys/fs/cgroup/cpuset rw,nosuid,nodev,noexec,relatime shared:2206 - cgroup cgroup rw,cpuset
2660 2657 0:31 / /sys/fs/cgroup/net_cls,net_prio rw,nosuid,nodev,noexec,relatime shared:2207 - cgroup cgroup rw,net_prio,net_cls
2661 2657 0:18 / /sys/fs/cgroup/memory rw,nosuid,nodev,noexec,relatime shared:2208 - cgroup cgroup rw,memory
2662 2657 0:32 / /sys/fs/cgroup/devices rw,nosuid,nodev,noexec,relatime shared:2209 - cgroup cgroup rw,devices
2663 2657 0:17 / /sys/fs/cgroup/blkio rw,nosuid,nodev,noexec,relatime shared:2210 - cgroup cgroup rw,blkio
2664 2657 0:35 / /sys/fs/cgroup/freezer rw,nosuid,nodev,noexec,relatime shared:2211 - cgroup cgroup rw,freezer
2665 2657 0:29 / /sys/fs/cgroup/perf_event rw,nosuid,nodev,noexec,relatime shared:2212 - cgroup cgroup rw,perf_event
2666 2657 0:33 / /sys/fs/cgroup/hugetlb rw,nosuid,nodev,noexec,relatime shared:2213 - cgroup cgroup rw,hugetlb
2667 2657 0:19 / /sys/fs/cgroup/pids rw,nosuid,nodev,noexec,relatime shared:2214 - cgroup cgroup rw,pids
2668 2657 0:26 / /sys/fs/cgroup/systemd rw,nosuid,nodev,noexec,relatime shared:2215 - cgroup cgroup rw,xattr,release_agent=/usr/lib/systemd/systemd-cgroups-agent,name=systemd
2642 2655 0:380 / /proc rw,relatime shared:2216 - proc proc rw
2643 2655 0:383 / /dev rw,nosuid shared:2217 - devtmpfs none rw,mode=755
2518 2643 0:384 / /dev/shm rw,nosuid,nodev shared:2218 - tmpfs tmpfs rw
2519 2643 0:385 / /dev/pts rw,nosuid,noexec,relatime shared:2219 - devpts devpts rw,gid=5,mode=620,ptmxmode=000
2520 2655 0:386 / /run rw,nosuid,nodev shared:2220 - tmpfs tmpfs rw,mode=755
2521 2520 0:387 / /run/lock rw,nosuid,nodev,noexec,relatime shared:2221 - tmpfs tmpfs rw,size=5120k
2522 2642 0:388 / /proc/sys/fs/binfmt_misc rw,relatime shared:2222 - autofs systemd-1 rw,fd=24,pipe_ino=25250595,pgrp=1,timeout=0,minproto=5,maxproto=5,direct,pipe_ino=25250595
2523 2643 0:379 / /dev/mqueue rw,relatime shared:2223 - mqueue mqueue rw
2524 2520 0:389 / /run/shm rw,relatime shared:2224 - tmpfs none rw
2870 2655 0:410 / /var/lib/docker/overlay2/01668781ea05a993a005080efbec5554b7d1156190fe800b5b0e71edb0a269a5/merged rw,relatime shared:2940 - overlay overlay rw,lowerdir=/var/lib/docker/overlay2/l/4QDYPQDEJ57YRMCEFLPXILMWH7:/var/lib/docker/overlay2/l/ZIQFQ2WVX2RB7I3DO5YBX2SFY2:/var/lib/docker/overlay2/l/WD3BJDHR2AGYDQ3EO43N27TBOE:/var/lib/docker/overlay2/l/3LV3YBWVBS7ITQ4GRXTRMNP2PP,upperdir=/var/lib/docker/overlay2/01668781ea05a993a005080efbec5554b7d1156190fe800b5b0e71edb0a269a5/diff,workdir=/var/lib/docker/overlay2/01668781ea05a993a005080efbec5554b7d1156190fe800b5...

[Zygmunt Krynicki (zyga)]

2655 2517 182:696641 / / rw,relatime shared:2202 - ext4 /dev/ploop43540p1 rw,stripe=4096,data=ordered,balloon_ino=12,jqfmt=vfsv1,usrjquota=aquota.user,grpjquota=aquota.group

This seems to suggest this is an open vz installation, can you provide the output of "uname -a" please?

In the case that you are using open-vz then I cannot help further than that. It is likely an unsupported kernel.

[Sascha Möller (sascha-speed)]

uname -a

Linux h2906342.stratoserver.net 4.15.0 #1 SMP Tue Jun 9 12:58:54 MSK 2020 x86_64 x86_64 x86_64 GNU/Linux

[Zygmunt Krynicki (zyga)]

I think this is not a stock Ubuntu kernel, as those usually have the -generic suffix. Can you please confirm which kernel you are using? Is that one of the standard Ubuntu kernel packages or is that a kernel provided by the cloud vendor.

[Sascha Möller (sascha-speed)]

Well Ubuntu 18.04 comes pre-installed, so i guess it's a cloud vendor kernel. Can't say for sure though.

[Casey Marshall (cmars)]

@Sascha If you don't mind disclosing, which cloud did you use to launch this instance, and which cloud image did you use?

Thanks,
Casey

[Sascha Möller (sascha-speed)]

It's a rented virtual server from a provider. They are using Virtuozzo as a VM. Besides that i don't know more, could be that they use a custom image.

[Zygmunt Krynicki (zyga)]

I think that is not supported as you are not running a Canonical kernel that can receive livepatch. Please use one of the other providers for the full Ubuntu experience, or just not use live patch.

[Sascha Möller (sascha-speed)]

I see, thanks for the help though! :)

[Launchpad Janitor (janitor)]

[Expired for Canonical Live Patch Client because there has been no activity for 60 days.]