Systemd services running snap apps fail to associate journal logs

I have systemd services that run snaps, e.g. powershell/pwsh. Those commands have output that should appear in the journal for the service, viewable by journalctl -u servicename.

This worked correctly with snapd 2.37.4 (shipped with debian buster) but not with 2.51.7 (debian bullseye/up-to-date).

It looks like snapd now does some extra confinement that prevents systemd from recognising the output as belonging to that service.

Is there anything that can be done about this? If I were to make a bug report, should that go to snapd or systemd?

snap install --edge busybox-static

/etc/systemd/service/snaptest.service =>

[Service]
ExecStart=/snap/bin/busybox-static sh -c 'echo foo'
systemctl start snaptest

With 2.37, foo appears in journalctl -u snaptest. The full fields associated with that entry are:

{
        "MESSAGE" : "foo",
        "_UID" : "0",
        "_BOOT_ID" : "2e6fa81dddd842b2ac5e3838412e970b",
        "_SYSTEMD_UNIT" : "snaptest.service",
        "_COMM" : "busybox",
        "_PID" : "6043",
        "__CURSOR" : "s=c1aeeb5ed05340fb84c46664873a0b51;i=83;b=2e6fa81dddd842b2ac5e3838412e970b;m=dfa92282545;t=5cca0dc086d2e;x=43d5f95cd63aaf1e",
        "_CAP_EFFECTIVE" : "3fffffffff",
        "__REALTIME_TIMESTAMP" : "1632366141926702",
        "_TRANSPORT" : "stdout",
        "_SYSTEMD_SLICE" : "system.slice",
        "SYSLOG_IDENTIFIER" : "busybox-static",
        "_SYSTEMD_CGROUP" : "/system.slice/snaptest.service",
        "PRIORITY" : "6",
        "SYSLOG_FACILITY" : "3",
        "_HOSTNAME" : "c",
        "_GID" : "0",
        "_STREAM_ID" : "b0429f0e00e344bfa91ccb04f3712829",
        "_SYSTEMD_INVOCATION_ID" : "717c2ca6265944a5ba547062cd8b140c",
        "__MONOTONIC_TIMESTAMP" : "15369845089605",
        "_MACHINE_ID" : "2cc4d0c85a9a484fb42c489ee5b0e913",
        "_SELINUX_CONTEXT" : "snap.busybox-static.busybox-static (enforce)\n"
}

With 2.51, the output is instead associated with a snapd cgroup and does not appear in journalctl -u snaptest (it does appear in the full journal, separately):

{
        "__MONOTONIC_TIMESTAMP" : "15369631957517",
        "_STREAM_ID" : "a26eeda4f59949c890f2cd6ca3410505",
        "_PID" : "20117",
        "PRIORITY" : "6",
        "_SYSTEMD_CGROUP" : "/system.slice/snap.busybox-static.busybox-static.c889d950-11a0-473e-a626-50a8280461ef.scope",
        "SYSLOG_IDENTIFIER" : "busybox-static",
        "_HOSTNAME" : "a",
        "_TRANSPORT" : "stdout",
        "__CURSOR" : "s=37337bba1c144be7814349efd4162f89;i=962;b=051664d31ebd4419adf074ae102628fa;m=dfa8574020d;t=5cca0cf5449f7;x=745eb32aeea2309e",
        "_GID" : "0",
        "_CAP_EFFECTIVE" : "3fffffffff",
        "_COMM" : "busybox",
        "_MACHINE_ID" : "57173e2c16aa4fe89022909d66dbe099",
        "__REALTIME_TIMESTAMP" : "1632365928794615",
        "_BOOT_ID" : "051664d31ebd4419adf074ae102628fa",
        "MESSAGE" : "foo",
        "_SYSTEMD_INVOCATION_ID" : "51026c541a20497d95024690044fdacd",
        "_SYSTEMD_UNIT" : "snap.busybox-static.busybox-static.c889d950-11a0-473e-a626-50a8280461ef.scope",
        "_UID" : "0",
        "SYSLOG_FACILITY" : "3",
        "_SYSTEMD_SLICE" : "system.slice"
}
2 Likes

I think I’m seeing the same thing. Have you found a solution?

Unfortunately, I have not. Ended up ditching snap and going with the deb package of pwsh instead. at the end of the day, reliable logging was more important to me than packaging convenience.

I’m still not sure if this counts as a snapd issue or a systemd issue.

Thanks for the confirmation. I’m going to head in the same direction - install powershell myself (direct binaries in my case) so I can get the “free” logging that comes with systemd.