Detection issues with systemd services executing podman

[apollo13]

Hello, I am running a service (haproxy) via podman and systemd. When starting the service the node-agent complains a bit:

Jan 30 19:38:48 host coroot-node-agent[1067661]: I0130 19:38:48.484649 1067661 registry.go:359] calculated container id 1067710 -> /system.slice/haproxy.service -> /system.slice/haproxy.service
Jan 30 19:38:48 host coroot-node-agent[1067661]: I0130 19:38:48.484882 1067661 container.go:1082] "started journald logparser" cg="/system.slice/haproxy.service"
Jan 30 19:38:48 host coroot-node-agent[1067661]: I0130 19:38:48.485665 1067661 registry.go:401] "detected a new container" pid=1067710 cg="/system.slice/haproxy.service" id="/system.slice/haproxy.service" app=""
Jan 30 19:38:48 host coroot-node-agent[1067661]: W0130 19:38:48.638268 1067661 systemd.go:97] failed to get systemd properties: Unit name runtime is neither a valid invocation ID nor unit name.
Jan 30 19:38:48 host coroot-node-agent[1067661]: W0130 19:38:48.638268 1067661 systemd.go:97] failed to get systemd properties: Unit name runtime is neither a valid invocation ID nor unit name.
Jan 30 19:38:48 host coroot-node-agent[1067661]: I0130 19:38:48.638307 1067661 registry.go:359] calculated container id 1067720 -> /system.slice/haproxy.service/runtime -> /system.slice/haproxy.service
Jan 30 19:38:48 host coroot-node-agent[1067661]: W0130 19:38:48.638325 1067661 registry.go:386] id conflict: /system.slice/haproxy.service
Jan 30 19:38:48 host coroot-node-agent[1067661]: W0130 19:38:48.638325 1067661 registry.go:386] id conflict: /system.slice/haproxy.service
Jan 30 19:38:48 host coroot-node-agent[1067661]: W0130 19:38:48.674612 1067661 systemd.go:97] failed to get systemd properties: Unit name libpod-payload-786f8b8d3873cd57e8c1313df53dc931ead2601b992bee96ff24ca6b20a43d31 is neither a valid invocation ID nor unit name.
Jan 30 19:38:48 host coroot-node-agent[1067661]: W0130 19:38:48.674612 1067661 systemd.go:97] failed to get systemd properties: Unit name libpod-payload-786f8b8d3873cd57e8c1313df53dc931ead2601b992bee96ff24ca6b20a43d31 is neither a valid invocation ID nor unit name.
Jan 30 19:38:48 host coroot-node-agent[1067661]: I0130 19:38:48.674650 1067661 registry.go:359] calculated container id 1067722 -> /system.slice/haproxy.service/libpod-payload-786f8b8d3873cd57e8c1313df53dc931ead2601b992bee96ff24ca6b20a43d31 -> /system.slice/haproxy.service
Jan 30 19:38:48 host coroot-node-agent[1067661]: W0130 19:38:48.674666 1067661 registry.go:386] id conflict: /system.slice/haproxy.service
Jan 30 19:38:48 host coroot-node-agent[1067661]: W0130 19:38:48.674666 1067661 registry.go:386] id conflict: /system.slice/haproxy.service
Jan 30 19:38:48 host coroot-node-agent[1067661]: I0130 19:38:48.829358 1067661 tls.go:132] pid=1067726 libssl_version=v3.5.1: libssl uprobes attached

Looking at systemd-cgls we get:

Control group /:
-.slice
└─system.slice (#63)
  ├─haproxy.service … (#31504)
  │ → user.invocation_id: b29b03321bbe457aa656379f5444f9ef
  │ → user.delegate: 1
  │ → trusted.invocation_id: b29b03321bbe457aa656379f5444f9ef
  │ → trusted.delegate: 1
  │ ├─libpod-payload-786f8b8d3873cd57e8c1313df53dc931ead2601b992bee96ff24ca6b20a43d31 (#31593)
  │ │ ├─1067722 /run/podman-init -- docker-entrypoint.sh -Ws -f /usr/local/etc/haproxy
  │ │ ├─1067724 haproxy -W -db -Ws -f /usr/local/etc/haproxy
  │ │ └─1067726 haproxy -W -db -Ws -f /usr/local/etc/haproxy
  │ └─runtime (#31579)
  │   └─1067720 /usr/bin/conmon --api-version 1 -c 786f8b8d3873cd57e8c1313df53dc931ead2601b992bee96ff24ca6b20a43d31 -u 786f8b8d3873cd57e8c1313df53dc931ead2601b992bee96ff24ca6b20a43d31 -r /usr/bin/crun -b /var/lib/containers/storage/overlay-c>

This is a result of running podman with --cgroups=split so the service cgroup is split and systemd can track the processes nicely. We can see how this causes problems for the node-agent from the logs:

Jan 30 19:38:48 host coroot-node-agent[1067661]: W0130 19:38:48.638268 1067661 systemd.go:97] failed to get systemd properties: Unit name runtime is neither a valid invocation ID nor unit name.
Jan 30 19:38:48 host coroot-node-agent[1067661]: W0130 19:38:48.674612 1067661 systemd.go:97] failed to get systemd properties: Unit name libpod-payload-786f8b8d3873cd57e8c1313df53dc931ead2601b992bee96ff24ca6b20a43d31 is neither a valid invocation ID nor unit name.

The assumption in systemd.go about the unit name might be overly optimistic:

coroot-node-agent/containers/systemd.go

Line 93 in b7f7aef

unit := parts[len(parts)-1]

Maybe it would make sense to iterate from the end and take the first part ending in ".service" or similar?

As a followup in the logs we then see:

Jan 30 19:38:48 host coroot-node-agent[1067661]: W0130 19:38:48.674666 1067661 registry.go:386] id conflict: /system.slice/haproxy.service

I am not sure if that is a result from the previous errors or not.

[def]

Currently, Podman isn't supported. For systemd cgroups, the optimistic assumption generally works well. Variations like /system.slice/docker-cf87ba651579c9231db817909e7865e5747bd7abcac0c57ce23cf4abbaee046b.scope/... or /kubepod.slice/... are handled explicitly.

[apollo13]

I understand that podman isn't explicitly supported, but the detection as systemd service works fine otherwise. Please note that this does not only break for podman but any other service that does some cgroups magic as well. I am currently testing if something like:

diff --git a/containers/systemd.go b/containers/systemd.go
index cddcb8a..d0942bc 100644
--- a/containers/systemd.go
+++ b/containers/systemd.go
@@ -90,7 +90,16 @@ func getSystemdProperties(id string) SystemdProperties {
        ctx, cancel := context.WithTimeout(context.Background(), dbusTimeout)
        defer cancel()
        parts := strings.Split(id, "/")
-       unit := parts[len(parts)-1]
+       var unit string
+       for i := len(parts) - 1; i >= 0; i-- {
+               if strings.HasSuffix(parts[i], ".service") {
+                       unit = parts[i]
+                       break
+               }
+       }
+       if unit == "" {
+               unit = parts[len(parts)-1]
+       }
        props.Unit = unit
        properties, err := dbusConn.GetAllPropertiesContext(ctx, unit)
        if err != nil {

works. Would you be open to adding that? In the optimistic case it should find the unit in the first iteration anyways.

[def]

In fact, we only need getSystemdProperties for pure systemd services, mostly for filtering. I think we should just suppress logging errors here.

[apollo13]

Mhm, just tested with the code from above and now it gets the systemd properties just fine. I'd consider podman an implementation detail here, the podman systemd integration is ment to behave like a standard systemd service. Ie you'd want (like is done correctly currently) read from the journal for such a service etc… Anyways if you think my code is okay I can open a PR, if you still think you'd rather just surpress logging I can do that as well.

But even with my patch I am left with:

Jan 30 20:08:17 host coroot-node-agent[1070414]: W0130 20:08:17.050740 1070414 registry.go:386] id conflict: /system.slice/haproxy.service
Jan 30 20:08:17 host coroot-node-agent[1070414]: W0130 20:08:17.050740 1070414 registry.go:386] id conflict: /system.slice/haproxy.service

any ideas about that?

[apollo13]

Ah the id conflict is caused by podman running in the cgroup first, starting another program and then exiting itself. Wondering if this would happen for normal services as well if the forked around a bit?

EDIT:// Okay, the cgroup shenanigans also break the log parser since it (mostly) follows the wrong cgroup as well :D

[def]

Anyways if you think my code is okay I can open a PR, if you still think you'd rather just surpress logging I can do that as well.

Yes, your fix looks good, please open a PR

[apollo13]

Added in #278 and included the journald fixes as well (as mentioned in slack)

[apollo13]

PR got merged -> closing 🥳