on UC24, systemd warns about notification messages directed to snaps

[Alfonso Sanchez-Beato]

On UC24 (noble based) I see warnings like this on boot:

Apr 05 14:36:55 qemuname systemd[1]: snapd.service: Got notification message from PID 1002, but reception only permitted for main PID 917
Apr 05 14:36:56 qemuname systemd[1]: snapd.service: Got notification message from PID 1039, but reception only permitted for main PID 917
Apr 05 14:36:56 qemuname systemd[1]: snapd.service: Got notification message from PID 1040, but reception only permitted for main PID 917

where PID XXXX is the snapd pid. This seems to happen because some process is sending requests to the systemd-notify socket while not being the main snapd PID. This can be reproduced in scenarios where snapd is reexeced, but not for instance if we stop snapd and socket and launch snapd from the command line. If we just stop snapd and launch snapd from the command line the messages appear though.

On installation, quite a few of these happen, but they are seen also in run mode.

Adding "NotifyAccess=all" in snapd.service fixes the issue, but it is not clear if that is the right approach as we might be sending wrong notifications (like notifying a stop when snapd exits because another snapd process is already running).

So the right fix might be more in the direction of avoiding unnecessay systemd notifications.

References:

[1] systemd-notify(1)
[2] sd_notify(3)

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

Using bpftrace I have been able to see which processes trigger the warning:

$ sudo LD_LIBRARY_PATH=. ./bpftrace -e 'tracepoint:syscalls:sys_enter_exec*{ printf("pid: %d, ppid: %d, comm: %s, args: ", pid, curtask->parent->pid, comm); join(args->argv); }'

pid: 3174, ppid: 1, comm: (snapd), args: /snap/snapd/21589/usr/lib/snapd/snapd
pid: 3180, ppid: 3174, comm: snapd, args: systemctl --version
pid: 3181, ppid: 3174, comm: snapd, args: systemd-detect-virt
pid: 3215, ppid: 3176, comm: snapd, args: systemctl is-enabled snapd.apparmor
pid: 3217, ppid: 3176, comm: snapd, args: udevadm info -e

$ sudo journalctl | grep "but reception only permitted for main PID"
Apr 05 16:02:52 qemuname systemd[1]: snapd.service: Got notification message from PID 3180, but reception only permitted for main PID 3174
Apr 05 16:02:52 qemuname systemd[1]: snapd.service: Got notification message from PID 3181, but reception only permitted for main PID 3174
Apr 05 16:02:52 qemuname systemd[1]: snapd.service: Got notification message from PID 3215, but reception only permitted for main PID 3174
Apr 05 16:02:52 qemuname systemd[1]: snapd.service: Got notification message from PID 3217, but reception only permitted for main PID 3174

It is not clear what notification is being sent by these processes yet.

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

If setting "NotifyAccess=all" and with systemd debug traces enabled, it is possible to see the notifications sent from these processes to systemd in the journal:

Apr 05 17:14:57 qemuname systemd[1]: snapd.service: Got notification message from PID 5112 (EXIT_STATUS=0)
Apr 05 17:14:57 qemuname systemd[1]: snapd.service: Got notification message from PID 5113 (EXIT_STATUS=0)
Apr 05 17:14:57 qemuname systemd[1]: snapd.service: Got notification message from PID 5147 (EXIT_STATUS=0)
Apr 05 17:14:58 qemuname systemd[1]: snapd.service: Got notification message from PID 5149 (EXIT_STATUS=0)

Processes being:

pid: 5112, ppid: 5106, comm: snapd, args: systemctl --version
pid: 5113, ppid: 5106, comm: snapd, args: systemd-detect-virt
pid: 5147, ppid: 5108, comm: snapd, args: systemctl is-enabled snapd.apparmor
pid: 5149, ppid: 5114, comm: snapd, args: udevadm info -e

These EXIT_STATUS notifications have been introduced recently in systemd and seem to be informational for services at the moment [1].

[1] https://manpages.ubuntu.com/manpages/noble/en/man3/sd_notify.3.html

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

The change was introduced in systemd 254:

https://github.com/systemd/systemd/blob/v254/NEWS#L649-L655

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

https://github.com/snapcore/snapd/pull/13797 contains the fix

[Ernest Lotter (ernestl)]

Merged, will be available on edge tomorrow. snapd 2.63 build planned for 11 April.