Udev problem running app as daemon

snapd
1

I’m digging into a problem with udev device detection on Ubuntu Core. I’ve created a simple snap using udevadm which you can reproduce the issue with: http://pastebin.ubuntu.com/25817127/. Install with --devmode.

If I run the snap as an app, it works correctly:

snap run udevadm-monitor

and plug/unplug a USB mouse/keyboard. This is my output: http://pastebin.ubuntu.com/25817138/

If I run the same app as a daemon however, I see problems. Begin with the USB device unplugged, and start the daemon:

sudo systemctl start snap.udevadm-monitor.udevadm-monitor.service

Observe the live journalctl output (sudo journalctl -f) and plug/unplug the USB device. I see nothing being printed by udevadm. I do see the correct kernel messages indicating USB device plug/unplugged.

But when I stop the daemon with

sudo systemctl start snap.udevadm-monitor.udevadm-monitor.service

I get the output from udevadm that I was expecting. So it looks like udevadm was blocked somehow at startup, before it printed its usual message. Here is my journalctl output showing the strangeness: http://pastebin.ubuntu.com/25817184/

Or is journald doing some per-client buffering that is totally throwing me off?

I’m able to reproduce with a Raspberry Pi3, and Ubuntu Core in a VM. The reason I ask is that we’re seeing this problem with device detection for Mir, and the udevadm behaviour here exactly replicates how Mir behaves.

I’m here to ask for ideas. What kind of differences might exist in the environment between the unconfined app, and unconfined daemon? Devmode should mean confinement isn’t interfering, right? I’m going over straces:

Strace of udevadm run as snap app (working): http://pastebin.ubuntu.com/25817409/
Strace of udevadm run as snap daemon (bad): http://pastebin.ubuntu.com/25817423/

I see that the epoll calls are very different, which I’m looking into now. But I’d really appreciate if anyone had some suggestions.
Thanks
-G

2

I’ll watch this thread but nothing immediately obvious comes to mind.

3

I just tried this on 17.10 classic distro with a strict mode snap. I needed to plugs hardware-observe and network-control (for NET_ADMIN). I then added the following rules to the apparmor policy since they are not covered by existing policy:

@{PROC}/[0-9]*/environ r,                                                       
ptrace (trace) peer=unconfined,

(note, we could probably find a place for the first, but the second rule is super-privileged).

With that, I plugged in a usb3 device and saw lots of output:

Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: monitor will print the received events for:
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV - the event which udev sends out after rule processing
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL - the kernel uevent
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.684837] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0 (pci)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.684862] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/pci_bus/0000:02 (pci_bus)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.685188] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:00.0 (pci)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.685464] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:01.0 (pci)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.685701] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0 (pci)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.685805] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:00.0/pci_bus/0000:03 (pci_bus)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.685876] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:01.0/pci_bus/0000:04 (pci_bus)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.685948] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0/pci_bus/0000:39 (pci_bus)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.686272] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0/0000:39:00.0 (pci)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.686674] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:01:00.0:pcie108 (pci_express)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.686854] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:00.0/0000:02:00.0:pcie208 (pci_express)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.687031] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:01.0/0000:02:01.0:pcie208 (pci_express)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.687204] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0/0000:02:02.0:pcie208 (pci_express)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.688895] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0/0000:39:00.0/usb3 (usb)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.689078] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0/0000:39:00.0/usb3/3-0:1.0 (usb)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.689440] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0/0000:39:00.0/usb4 (usb)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.690763] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0/0000:39:00.0/usb4/4-0:1.0 (usb)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.720538] remove   /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0/0000:39:00.0/usb3/3-0:1.0 (usb)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.722187] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0 (pci)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: KERNEL[83017.722440] remove   /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0/0000:39:00.0/usb4/4-0:1.0 (usb)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.725367] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/pci_bus/0000:02 (pci_bus)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.736220] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:00.0 (pci)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.736334] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:01.0 (pci)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.736395] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:01:00.0:pcie108 (pci_express)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.736498] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0 (pci)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.736547] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:01.0/pci_bus/0000:04 (pci_bus)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.736592] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:00.0/pci_bus/0000:03 (pci_bus)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.736634] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0/pci_bus/0000:39 (pci_bus)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.736675] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:01.0/0000:02:01.0:pcie208 (pci_express)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.736716] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:00.0/0000:02:00.0:pcie208 (pci_express)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.737684] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0/0000:02:02.0:pcie208 (pci_express)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.737790] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0/0000:39:00.0 (pci)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.743498] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0/0000:39:00.0/usb3 (usb)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.743680] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0/0000:39:00.0/usb4 (usb)
Oct 26 16:01:46 iolanthe test-udevadm.udevadm-monitor[10463]: UDEV  [83017.748462] add      /devices/pci0000:00/0000:00:1c.0/0000:01:00.0/0000:02:02.0/0000:39:00.0/usb3/3-0:1.0 (usb)

One thing I did have going on is I was running snappy-debug, which disables kernel rate limiting. You can do the same with:

$ sudo sysctl -w kernel.printk_ratelimit=0
4

I white-lied. I only added ‘capability net_admin,’ to the policy instead of plugging network-control. network-control has an explicit deny rule for ptrace, so if you test this, plugs bluetooth-control instead (which also grants net_admin).

5

Just to update the thread, this approach was a wild goose chase.

The core bug I was investigating is that the Mir-kiosk snap has a bug where it fails to detect new input devices being plugged in.

I thought it best to reduce the problem scope to a simpler case, so tried reproducing with libinput/udev debug tooling. And I thought that they did indeed reproduce the issue, as when running as daemon the CLI tools were not printing out to the journal immediately on device plug, as they should.

But it turns out this was incorrect, the CLI tools were working fine, but this hit me:

Or is journald doing some per-client buffering that is totally throwing me off?

Systemd runs daemons in non-interactive shells, which causes the output of the daemon to be buffered. Therefore the CLI tool was printing on device plug, but that was being buffered and so wouldn’t hit the journal until much later. More advanced daemons log with a special API, which avoids this buffering issue.

Adjusting the kernel rate limiting is one solution. Another workaround is to use the “stdbuf” util in coreutils, which can disable buffering entirely. Use like so

stdbuf -o0 cli-tool

When I adjusted the snapcraft file to add this, the CLI tool worked and printed to the journal immediately on input device plug.

That doesn’t solve my Mir issue, but I’ve made progress on that (new device is detected, but the newly created /dev/input/event* node is unavailable to Mir for some reason) so will ask in another topic.

Thanks for the help so far
-G