Luap99
commented
1 month ago Please provide the full journal log for this service.
Closed Arcitec closed 1 month ago
Luap99
commented
1 month ago Please provide the full journal log for this service.
Arcitec
commented
1 month ago The service above was a minimal test case to show that everything is broken (no matter what service I try to create, they all fail via systemd). But here's the service I was actually trying to run.
Edit: Removed since it was not necessary for debugging this issue.
Verifying that it still isn't running:
$ podman ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES$ ls -al /sys/fs/cgroup/memory.events
ls: cannot access '/sys/fs/cgroup/memory.events': No such file or directory$ systemctl --user status syncthing | grep ExecStart=
Process: 1174086 ExecStart=/usr/bin/podman run --name=systemd-syncthing --cidfile=/run/user/1000/syncthing.cid --replace --rm --cgroups=split --sdnotify=conmon -d --security-opt label:disable --userns keep-id -v /home/johnny/.config/syncthing-container:/var/syncthing/config -v /home/johnny/Sync:/var/syncthing/Sync --label io.containers.autoupdate=registry --publish 127.0.0.1:8384:8384 --publish 22000:22000/tcp --publish 22000:22000/udp --publish 21027:21027/udp --env PGID=1000 --env PUID=1000 --hostname st-aurora docker.io/syncthing/syncthing:latest (code=exited, status=0/SUCCESS)Edit: Log was here. It ran successfully.
podman ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
f9ce69238142 docker.io/syncthing/syncthing:latest About a minute ago Up About a minute 127.0.0.1:8384->8384/tcp, 0.0.0.0:22000->22000/tcp, 0.0.0.0:21027->21027/udp, 0.0.0.0:22000->22000/udp, 8384/tcp, 21027/udp, 22000/tcp, 22000/udp systemd-syncthingPlease provide the full journal log for this service.
I shared my actual container spec file above and the full journal log for that (the syncthing service). Hope I haven't missed anything there.
Luap99
commented
1 month ago I would be interested in the full logs with the simple sleep example. The systemctl status truncated output I expect much more log lines (with --log-level debug that is) there that I would like to see.
The conmon /sys/fs/cgroup/memory.events can be ignored I think although I haven't looked to closely what conmon is doing there.
Sep 17 19:52:13 aurora systemd-syncthing[1174111]: [monitor] 2024/09/17 17:52:13 INFO: Signal 15 received; exiting
The looks like something is sending SIGTERM to the container.
Arcitec
commented
1 month ago The looks like something is sending SIGTERM to the container.
Hmm interesting. I'm not sure what that could be from. I have a normal Fedora Workstation 40 desktop and haven't installed some task killer. But whatever it is, it gets sent to every container that is started via systemd. But never when I start them manually on the terminal or with the Pods app.
My systemd services run at the user-level, and I can confirm that they are running as my user because the ExecStart command replaces %h with my home path, so systemd clearly runs it in the user context.
The conmon /sys/fs/cgroup/memory.events can be ignored I think although I haven't looked to closely what conmon is doing there.
Okay good. :)
I would be interested in the full logs with the simple sleep example.
Good idea. I'll capture those now:
Luap99
commented
1 month ago So the container is started fine but then something is causing us to stop it right away
Sep 17 20:07:36 aurora testquadlet[1177112]: time="2024-09-17T20:07:36+02:00" level=warning msg="StopSignal SIGTERM failed to stop container systemd-testquadlet in 10 seconds, resorting to SIGKILL" Sep 17 20:07:36 aurora conmon[1177107]: conmon 799bacc6b24d58f6a839
: container 1177109 exited with status 137
Given the StopSignal is a podman line it means something is triggering the podman rm -f ... (ExecStop=) to be run.
Arcitec
commented
1 month ago That makes sense. And it happens for every podman systemd service, but not for any of my other systemd services nor for manually executed podman run commands.
The service is generated as a Type=notify service (the default for podman quadlets). So I wonder if the service itself is breaking in the "notify" watcher? Perhaps the Notify detection thinks the container has immediately exited and then tells the service to ExecStop to clean up?
It's too suspicious that every quadlet service stops itself immediately. And I did see some line about a notify watcher failure.
PS: In the meantime I am installing Fedora 40 in a VM and will see if it works there. My current system started on Fedora 35 and has upgraded over the years and perhaps some core config is broken...
Arcitec
commented
1 month ago :/ Should I reinstall the entire operating system? Or is there a way to fix this on my real machine?
Here are the test results with a fresh Fedora 40 virtual machine:
liveuser@localhost-live:~$ podman ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
286a7af150d8 docker.io/library/alpine:latest sleep infinity 8 seconds ago Up 8 seconds systemd-testquadlet
liveuser@localhost-live:~$ podman ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
286a7af150d8 docker.io/library/alpine:latest sleep infinity 15 seconds ago Up 15 seconds systemd-testquadlet
liveuser@localhost-live:~$ podman ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
286a7af150d8 docker.io/library/alpine:latest sleep infinity 27 seconds ago Up 27 seconds systemd-testquadlet
liveuser@localhost-live:~$ podman ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
286a7af150d8 docker.io/library/alpine:latest sleep infinity 9 minutes ago Up 9 minutes systemd-testquadlet
liveuser@localhost-live:~$ I did a systemctl --user list-unit-files | grep -i pod and saw that podman.socket was enabled on the host but not on the VM, so I stopped it on the host too. That unfortunately didn't solve the issue.
I can't really think of any differences between the VM and host... I haven't changed anything manually.
rhatdan
commented
1 month ago Is this running as a logged in system. Might be systemd killing the service for some reason.
Arcitec
commented
1 month ago Yeah. It's at the GNOME desktop right now. I will try rebooting and logging in a runlevel 3 with a pure text terminal and running the container. Good idea for a test.
rhatdan
commented
1 month ago No I don't think that will matter.
Arcitec
commented
1 month ago I have now done these tests. None of them fixed the problem. Containers still exit immediately when using systemd.
podman system reset --force to clear all images and configurations.[Container] Network=none to the .container spec to avoid pasta/slirp. It did not use networking anymore but still got terminated with the exact same signal.sudo dnf reinstall podman conmon in case reinstalling would reset some system config for me.None of it solves the problem. I'm about to do one more test... I'll create a 2nd user and see if that one has more luck.
Arcitec
commented
1 month ago Tried two more things, but nothing solves it:
One thing hits me though. The Fedora virtual machine was made from the Fedora 40 ISO which uses packages from March 2024. I should install it and do a full system upgrade inside the VM to see if the VM still works on the latest packages, or if having the latest Fedora 40 packages is what breaks it.
Arcitec
commented
1 month ago Fedora 40 Workstation virtual machine results:
sudo dnf offline-upgrade download --refresh --exclude=kernel*): Kernel is 6.8.5-301.fc40.x86_64. Works.6.9.12-200.fc40.x86_64 (what I use on the host): Works.Here's the log from the last run, where I had upgraded the VM to the same kernel as the host. As mentioned, this is what a SUCCESSFUL run looks like:
I am soon out of ideas.
Arcitec
commented
1 month ago Everything points to:
Arcitec
commented
1 month ago I generated lists of all systemd system units for both the VM and the Host to compare and see if there's something here that could cause the conflict.
But I am more and more thinking that Fedora is just broken. It's not the first time something breaks permanently during OS-to-OS upgrades in this distro.
At least we've narrowed it down to the fact that the host receives a SIGTERM as soon as the systemd podman units start.
Any last advice or ideas? Maybe some idea for how to see which process sends SIGTERM? I have Pods and Podman Desktop on the machine. I might try removing those if they somehow interfere, but that's unlikely, especially since they are Flatpaks.
Generated via the command: systemctl --system list-unit-files | sort | sed -E 's@\s+@ @g'
Arcitec
commented
1 month ago Well I had some ideas with strace to capture all system signals (such as SIGTERM). This trace captures all incoming signals to the watched process... And this shows that there's actually nothing that sends SIGTERM to Podman. I re-ran these commands 30+ times just trying to get at least ONE incoming "hey, sigterm yourself!" signal, but it did not capture that even once.
It did capture various signals being output BY the podman process to terminate its child (the container). And also signals from conmon detecting that podman has exited.
But no sigterm "towards podman" was ever being received or sent by conmon or podman themselves.
Which means:
systemctl --user daemon-reload; systemctl --user restart testquadlet --no-block; ps aux | grep podman; POD_PID=$(pidof conmon); echo "PID=${POD_PID}"; strace -p $POD_PID -e signal
johnny 19847 0.0 0.0 231328 2068 ? Ss 22:35 0:00 /usr/bin/conmon --api-version 1 -c 030c5e181d7d6fbb5d76a50de51349065d694cce0f4582103b037d6aca08f7d9 -u 030c5e181d7d6fbb5d76a50de51349065d694cce0f4582103b037d6aca08f7d9 -r /usr/bin/crun -b /home/johnny/.local/share/containers/storage/overlay-containers/030c5e181d7d6fbb5d76a50de51349065d694cce0f4582103b037d6aca08f7d9/userdata -p /run/user/1000/containers/overlay-containers/030c5e181d7d6fbb5d76a50de51349065d694cce0f4582103b037d6aca08f7d9/userdata/pidfile -n systemd-testquadlet --exit-dir /run/user/1000/libpod/tmp/exits --persist-dir /run/user/1000/libpod/tmp/persist/030c5e181d7d6fbb5d76a50de51349065d694cce0f4582103b037d6aca08f7d9 --full-attach -l journald --log-level debug --syslog --conmon-pidfile /run/user/1000/containers/overlay-containers/030c5e181d7d6fbb5d76a50de51349065d694cce0f4582103b037d6aca08f7d9/userdata/conmon.pid --exit-command /usr/bin/podman --exit-command-arg --root --exit-command-arg /home/johnny/.local/share/containers/storage --exit-command-arg --runroot --exit-command-arg /run/user/1000/containers --exit-command-arg --log-level --exit-command-arg debug --exit-command-arg --cgroup-manager --exit-command-arg systemd --exit-command-arg --tmpdir --exit-command-arg /run/user/1000/libpod/tmp --exit-command-arg --network-config-dir --exit-command-arg --exit-command-arg --network-backend --exit-command-arg netavark --exit-command-arg --volumepath --exit-command-arg /home/johnny/.local/share/containers/storage/volumes --exit-command-arg --db-backend --exit-command-arg sqlite --exit-command-arg --transient-store=false --exit-command-arg --runtime --exit-command-arg crun --exit-command-arg --storage-driver --exit-command-arg overlay --exit-command-arg --events-backend --exit-command-arg journald --exit-command-arg --syslog --exit-command-arg container --exit-command-arg cleanup --exit-command-arg --rm --exit-command-arg 030c5e181d7d6fbb5d76a50de51349065d694cce0f4582103b037d6aca08f7d9
johnny 19852 0.7 0.0 2605668 43904 ? Ssl 22:35 0:00 /usr/bin/podman rm -v -f -i --cidfile=/run/user/1000/testquadlet.cid
johnny 19900 0.0 0.0 227924 2304 pts/6 S+ 22:35 0:00 grep --color=auto podman
PID=19847
strace: Process 19847 attached
rt_sigaction(SIGCHLD, {sa_handler=SIG_DFL, sa_mask=[CHLD], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f95c1bf2d00}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
+++ exited with 137 +++systemctl --user daemon-reload; systemctl --user restart testquadlet --no-block; ps aux | grep podman; POD_PID=$(pidof podman); echo "PID=${POD_PID}"; strace -p $POD_PID -e signal
johnny 23951 0.0 0.0 231328 2064 ? Ss 22:42 0:00 /usr/bin/conmon --api-version 1 -c c52c97b5dd2adba17b67c1de505fb912d05829312a437c131ed38384c4a71214 -u c52c97b5dd2adba17b67c1de505fb912d05829312a437c131ed38384c4a71214 -r /usr/bin/crun -b /home/johnny/.local/share/containers/storage/overlay-containers/c52c97b5dd2adba17b67c1de505fb912d05829312a437c131ed38384c4a71214/userdata -p /run/user/1000/containers/overlay-containers/c52c97b5dd2adba17b67c1de505fb912d05829312a437c131ed38384c4a71214/userdata/pidfile -n systemd-testquadlet --exit-dir /run/user/1000/libpod/tmp/exits --persist-dir /run/user/1000/libpod/tmp/persist/c52c97b5dd2adba17b67c1de505fb912d05829312a437c131ed38384c4a71214 --full-attach -l journald --log-level debug --syslog --conmon-pidfile /run/user/1000/containers/overlay-containers/c52c97b5dd2adba17b67c1de505fb912d05829312a437c131ed38384c4a71214/userdata/conmon.pid --exit-command /usr/bin/podman --exit-command-arg --root --exit-command-arg /home/johnny/.local/share/containers/storage --exit-command-arg --runroot --exit-command-arg /run/user/1000/containers --exit-command-arg --log-level --exit-command-arg debug --exit-command-arg --cgroup-manager --exit-command-arg systemd --exit-command-arg --tmpdir --exit-command-arg /run/user/1000/libpod/tmp --exit-command-arg --network-config-dir --exit-command-arg --exit-command-arg --network-backend --exit-command-arg netavark --exit-command-arg --volumepath --exit-command-arg /home/johnny/.local/share/containers/storage/volumes --exit-command-arg --db-backend --exit-command-arg sqlite --exit-command-arg --transient-store=false --exit-command-arg --runtime --exit-command-arg crun --exit-command-arg --storage-driver --exit-command-arg overlay --exit-command-arg --events-backend --exit-command-arg journald --exit-command-arg --syslog --exit-command-arg container --exit-command-arg cleanup --exit-command-arg --rm --exit-command-arg c52c97b5dd2adba17b67c1de505fb912d05829312a437c131ed38384c4a71214
johnny 23955 2.6 0.0 2458296 43008 ? Ssl 22:42 0:00 /usr/bin/podman rm -v -f -i --cidfile=/run/user/1000/testquadlet.cid
johnny 24002 0.0 0.0 227924 2048 pts/6 S+ 22:42 0:00 grep --color=auto podman
PID=23955
strace: Process 23955 attached
kill(23953, 0) = 0
kill(23953, 0) = 0
kill(23953, 0) = 0
kill(23953, 0) = 0
kill(23953, 0) = 0
kill(23953, 0) = 0
kill(23953, 0) = 0
kill(23953, 0) = 0
kill(23953, 0) = 0
kill(23953, 0) = 0
kill(23953, 0) = 0
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=24030, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
rt_sigreturn({mask=[]}) = 1
kill(23953, 0) = -1 ESRCH (No such process)
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=23955, si_uid=0} ---
rt_sigreturn({mask=[]}) = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=23955, si_uid=0} ---
rt_sigreturn({mask=[]}) = 1
rt_sigprocmask(SIG_SETMASK, NULL, [], 8) = 0
rt_sigprocmask(SIG_SETMASK, ~[], NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=24045, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
rt_sigreturn({mask=[]}) = 0
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=23955, si_uid=0} ---
rt_sigreturn({mask=[]}) = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=23955, si_uid=0} ---
rt_sigreturn({mask=[]}) = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=23955, si_uid=0} ---
rt_sigreturn({mask=[]}) = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=23955, si_uid=0} ---
rt_sigreturn({mask=[]}) = 1
+++ exited with 0 +++The 23955 PID is podman itself.
I was also quick to capture what kill(23953, 0) = 0 referred to and it turns out that was just podman trying to kill the infinitely sleeping container process:
ps aux | rg 23953
johnny 23953 0.0 0.0 1612 640 ? Ss 22:42 0:00 sleep infinityEdit: I even simplified the command to cut out the ps aux | grep delay to minimize the pause between systemd startup and strace; still wasn't able to see any sigterm being forced onto podman:
systemctl --user daemon-reload; systemctl --user restart testquadlet --no-block; POD_PID=$(pidof podman); echo "PID=${POD_PID}"; strace -p $POD_PID -e signal~/.config/systemd/user/testquadletmanual.service and filled its contents as follows:/usr/libexec/podman/quadlet --user --dryrun to get the correct service file contents.ExecStart= line to remove -d to tell podman to stay resident instead of daemonizing (which otherwise immediately exits with status 0).-d flag:
[Unit]
Wants=network-online.target
After=network-online.target
Description=Sleep Container
SourcePath=/home/johnny/.config/containers/systemd/testquadlet.container
RequiresMountsFor=%t/containers[X-Container] Image=docker.io/alpine PodmanArgs=--log-level=debug Exec=sleep infinity
[Install] WantedBy=default.target
[Service] Environment=PODMAN_SYSTEMD_UNIT=%n KillMode=mixed ExecStop=/usr/bin/podman rm -v -f -i --cidfile=%t/%N.cid ExecStopPost=-/usr/bin/podman rm -v -f -i --cidfile=%t/%N.cid Delegate=yes Type=notify NotifyAccess=all SyslogIdentifier=%N ExecStart=/usr/bin/podman run --name=systemd-%N --cidfile=%t/%N.cid --replace --rm --cgroups=split --sdnotify=conmon --log-level=debug docker.io/alpine sleep infinity
- Then I started the custom service and watched the system log:
<details>
<summary>Click for details</summary>
$ systemctl --user restart testquadletmanual --no-block; journalctl --user -f
Sep 17 23:04:27 aurora gnome-shell[5424]: Can't update stage views actor unnamed [Gjs_dash-to-dock_micxgx_gmail_com_docking_DashSlideContainer] is on because it needs an allocation.
Sep 17 23:04:27 aurora gnome-shell[5424]: Can't update stage views actor dashtodockBox [StBoxLayout] is on because it needs an allocation.
Sep 17 23:04:27 aurora gnome-shell[5424]: Can't update stage views actor bms-dash-backgroundgroup [MetaBackgroundGroup] is on because it needs an allocation.
Sep 17 23:04:27 aurora gnome-shell[5424]: Can't update stage views actor bms-dash-blurred-widget [StWidget] is on because it needs an allocation.
Sep 17 23:04:27 aurora gnome-shell[5424]: Can't update stage views actor dashtodockContainer [Gjs_dash-to-dock_micxgx_gmail_com_docking_DashToDock] is on because it needs an allocation.
Sep 17 23:04:27 aurora gnome-shell[5424]: Can't update stage views actor unnamed [Gjs_dash-to-dock_micxgx_gmail_com_docking_DashSlideContainer] is on because it needs an allocation.
Sep 17 23:04:27 aurora gnome-shell[5424]: Can't update stage views actor dashtodockBox [StBoxLayout] is on because it needs an allocation.
Sep 17 23:04:27 aurora gnome-shell[5424]: Can't update stage views actor bms-dash-backgroundgroup [MetaBackgroundGroup] is on because it needs an allocation.
Sep 17 23:04:27 aurora gnome-shell[5424]: Can't update stage views actor bms-dash-blurred-widget [StWidget] is on because it needs an allocation.
Sep 17 23:04:27 aurora systemd[5025]: Starting testquadletmanual.service - Sleep Container...
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=info msg="/usr/bin/podman filtering at log level debug"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Called run.PersistentPreRunE(/usr/bin/podman run --name=systemd-testquadletmanual --cidfile=/run/user/1000/testquadletmanual.cid --replace --rm --cgroups=split --sdnotify=conmon --log-level=debug docker.io/alpine sleep infinity)"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Using conmon: \"/usr/bin/conmon\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=info msg="Using sqlite as database backend"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Using graph driver overlay"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Using graph root /home/johnny/.local/share/containers/storage"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Using run root /run/user/1000/containers"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Using static dir /home/johnny/.local/share/containers/storage/libpod"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Using tmp dir /run/user/1000/libpod/tmp"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Using volume path /home/johnny/.local/share/containers/storage/volumes"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Using transient store: false"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="[graphdriver] trying provided driver \"overlay\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Cached value indicated that overlay is supported"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Cached value indicated that overlay is supported"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Cached value indicated that metacopy is not being used"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Cached value indicated that native-diff is usable"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="backingFs=btrfs, projectQuotaSupported=false, useNativeDiff=true, usingMetacopy=false"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Initializing event backend journald"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Configured OCI runtime youki initialization failed: no valid executable found for OCI runtime youki: invalid argument"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Configured OCI runtime crun-vm initialization failed: no valid executable found for OCI runtime crun-vm: invalid argument"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Configured OCI runtime crun-wasm initialization failed: no valid executable found for OCI runtime crun-wasm: invalid argument"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Configured OCI runtime runc initialization failed: no valid executable found for OCI runtime runc: invalid argument"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Configured OCI runtime runj initialization failed: no valid executable found for OCI runtime runj: invalid argument"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Configured OCI runtime kata initialization failed: no valid executable found for OCI runtime kata: invalid argument"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Configured OCI runtime runsc initialization failed: no valid executable found for OCI runtime runsc: invalid argument"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Configured OCI runtime krun initialization failed: no valid executable found for OCI runtime krun: invalid argument"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Configured OCI runtime ocijail initialization failed: no valid executable found for OCI runtime ocijail: invalid argument"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Using OCI runtime \"/usr/bin/crun\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=info msg="Setting parallel job count to 49"
Sep 17 23:04:27 aurora systemd[5025]: Started podman-30394.scope.
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Pulling image docker.io/alpine (policy: missing)"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Looking up image \"docker.io/alpine\" in local containers storage"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Normalized platform linux/amd64 to {amd64 linux [] }"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Trying \"docker.io/library/alpine:latest\" ..."
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="parsed reference into \"[overlay@/home/johnny/.local/share/containers/storage+/run/user/1000/containers]@91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Found image \"docker.io/alpine\" as \"docker.io/library/alpine:latest\" in local containers storage"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Found image \"docker.io/alpine\" as \"docker.io/library/alpine:latest\" in local containers storage ([overlay@/home/johnny/.local/share/containers/storage+/run/user/1000/containers]@91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b)"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="exporting opaque data as blob \"sha256:91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Looking up image \"docker.io/library/alpine:latest\" in local containers storage"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Normalized platform linux/amd64 to {amd64 linux [] }"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Trying \"docker.io/library/alpine:latest\" ..."
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="parsed reference into \"[overlay@/home/johnny/.local/share/containers/storage+/run/user/1000/containers]@91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Found image \"docker.io/library/alpine:latest\" as \"docker.io/library/alpine:latest\" in local containers storage"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Found image \"docker.io/library/alpine:latest\" as \"docker.io/library/alpine:latest\" in local containers storage ([overlay@/home/johnny/.local/share/containers/storage+/run/user/1000/containers]@91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b)"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="exporting opaque data as blob \"sha256:91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Looking up image \"docker.io/alpine\" in local containers storage"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Normalized platform linux/amd64 to {amd64 linux [] }"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Trying \"docker.io/library/alpine:latest\" ..."
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="parsed reference into \"[overlay@/home/johnny/.local/share/containers/storage+/run/user/1000/containers]@91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Found image \"docker.io/alpine\" as \"docker.io/library/alpine:latest\" in local containers storage"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Found image \"docker.io/alpine\" as \"docker.io/library/alpine:latest\" in local containers storage ([overlay@/home/johnny/.local/share/containers/storage+/run/user/1000/containers]@91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b)"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="exporting opaque data as blob \"sha256:91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Inspecting image 91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="exporting opaque data as blob \"sha256:91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="exporting opaque data as blob \"sha256:91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Inspecting image 91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Inspecting image 91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Inspecting image 91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="using systemd mode: false"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="setting container name systemd-testquadletmanual"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="No hostname set; container's hostname will default to runtime default"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Loading seccomp profile from \"/usr/share/containers/seccomp.json\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Allocated lock 0 for container 4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="exporting opaque data as blob \"sha256:91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Cached value indicated that idmapped mounts for overlay are not supported"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Check for idmapped mounts support "
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Created container \"4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Container \"4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb\" has work directory \"/home/johnny/.local/share/containers/storage/overlay-containers/4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb/userdata\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Container \"4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb\" has run directory \"/run/user/1000/containers/overlay-containers/4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb/userdata\""
Sep 17 23:04:27 aurora podman[30394]: 2024-09-17 23:04:27.83295267 +0200 CEST m=+0.033580016 container create 4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb (image=docker.io/library/alpine:latest, name=systemd-testquadletmanual, PODMAN_SYSTEMD_UNIT=testquadletmanual.service)
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Not attaching to stdin"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=info msg="Received shutdown.Stop(), terminating!" PID=30394
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Enabling signal proxying"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Cached value indicated that volatile is being used"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="overlay: mount_data=lowerdir=/home/johnny/.local/share/containers/storage/overlay/l/RMGDGIAGZTBD6WW47XCMRD57TR,upperdir=/home/johnny/.local/share/containers/storage/overlay/034c0e17f0002101986aa61fcbafbfe6ae5198d9b22a8762b38527bf7c9a14eb/diff,workdir=/home/johnny/.local/share/containers/storage/overlay/034c0e17f0002101986aa61fcbafbfe6ae5198d9b22a8762b38527bf7c9a14eb/work,userxattr,volatile,context=\"system_u:object_r:container_file_t:s0:c521,c622\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Made network namespace at /run/user/1000/netns/netns-59c96dc8-4d12-27f9-eadf-017afaa7a2ad for container 4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="pasta arguments: --config-net --dns-forward 169.254.0.1 -t none -u none -T none -U none --no-map-gw --quiet --netns /run/user/1000/netns/netns-59c96dc8-4d12-27f9-eadf-017afaa7a2ad"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Mounted container \"4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb\" at \"/home/johnny/.local/share/containers/storage/overlay/034c0e17f0002101986aa61fcbafbfe6ae5198d9b22a8762b38527bf7c9a14eb/merged\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Created root filesystem for container 4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb at /home/johnny/.local/share/containers/storage/overlay/034c0e17f0002101986aa61fcbafbfe6ae5198d9b22a8762b38527bf7c9a14eb/merged"
Sep 17 23:04:27 aurora pasta[30420]: Couldn't get any nameserver address
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=info msg="pasta logged warnings: \"Couldn't get any nameserver address\n\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="/etc/system-fips does not exist on host, not mounting FIPS mode subscription"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="reading hooks from /usr/share/containers/oci/hooks.d"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Workdir \"/\" resolved to host path \"/home/johnny/.local/share/containers/storage/overlay/034c0e17f0002101986aa61fcbafbfe6ae5198d9b22a8762b38527bf7c9a14eb/merged\""
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="Created OCI spec for container 4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb at /home/johnny/.local/share/containers/storage/overlay-containers/4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb/userdata/config.json"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="/usr/bin/conmon messages will be logged to syslog"
Sep 17 23:04:27 aurora testquadletmanual[30394]: time="2024-09-17T23:04:27+02:00" level=debug msg="running conmon: /usr/bin/conmon" args="[--api-version 1 -c 4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb -u 4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb -r /usr/bin/crun -b /home/johnny/.local/share/containers/storage/overlay-containers/4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb/userdata -p /run/user/1000/containers/overlay-containers/4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb/userdata/pidfile -n systemd-testquadletmanual --exit-dir /run/user/1000/libpod/tmp/exits --persist-dir /run/user/1000/libpod/tmp/persist/4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb --full-attach -l journald --log-level debug --syslog --conmon-pidfile /run/user/1000/containers/overlay-containers/4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb/userdata/conmon.pid --exit-command /usr/bin/podman --exit-command-arg --root --exit-command-arg /home/johnny/.local/share/containers/storage --exit-command-arg --runroot --exit-command-arg /run/user/1000/containers --exit-command-arg --log-level --exit-command-arg debug --exit-command-arg --cgroup-manager --exit-command-arg systemd --exit-command-arg --tmpdir --exit-command-arg /run/user/1000/libpod/tmp --exit-command-arg --network-config-dir --exit-command-arg --exit-command-arg --network-backend --exit-command-arg netavark --exit-command-arg --volumepath --exit-command-arg /home/johnny/.local/share/containers/storage/volumes --exit-command-arg --db-backend --exit-command-arg sqlite --exit-command-arg --transient-store=false --exit-command-arg --runtime --exit-command-arg crun --exit-command-arg --storage-driver --exit-command-arg overlay --exit-command-arg --events-backend --exit-command-arg journald --exit-command-arg --syslog --exit-command-arg container --exit-command-arg cleanup --exit-command-arg --rm --exit-command-arg 4bb29585c3dd878377d6d36be64065ff193273f0931e9ab8fbfc12efa4b564bb]"
Sep 17 23:04:27 aurora testquadletmanual[30431]: [conmon:d]: failed to write to /proc/self/oom_score_adj: Permission denied
Sep 17 23:04:27 aurora conmon[30431]: conmon 4bb29585c3dd878377d6
</details>
- And checked `podman ps` (success):
podman ps CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES 4bb29585c3dd docker.io/library/alpine:latest sleep infinity 8 minutes ago Up 8 minutes systemd-testquadletmanual
Conclusion so far:
- Nothing was ever sending sigterm.
- When podman exits immediately due to `-d` then the systemd service assumes that the service itself has stopped. Why does this happen, when it doesn't happen in a fresh VM? I used a difftool to 100% verify that the ONLY difference between my host and VM services was the `-d` flag. Why doesn't `-d` work on the host?
- Why does podman terminate the container when `-d` flag is used? Is it caused by conmon? It is caused by podman?
- My strongest theory is that systemd executes `ExecStart=`, then sees that it exits with code 0, doesn't understand that it's a daemon/notify-based service, so it then runs `ExecStop=` automatically to clean up (which is what terminated things via "sigterm" in the earlier logs).
Since I got this far, it might be worth investigating more and finding if this is a bug in podman in certain systems. Any ideas based on this finding, @Luap99 @rhatdan ?Since everything is pointing towards a notify-related bug, I have taken a quick look at the VM logs where -d is successful, and searched for all lines with the word "notify":
https://github.com/containers/podman/issues/23990#issuecomment-2356794976
Sep 17 22:00:11 localhost-live testquadlet[3040]: time="2024-09-17T22:00:11+02:00" level=debug msg="Called run.PersistentPreRunE(/usr/bin/podman run --name=systemd-testquadlet --cidfile=/run/user/1000/testquadlet.cid --replace --rm --cgroups=split --sdnotify=conmon -d --log-level=debug docker.io/alpine sleep infinity)"
Sep 17 22:00:11 localhost-live testquadlet[3047]: time="2024-09-17T22:00:11+02:00" level=debug msg="Called run.PersistentPreRunE(/usr/bin/podman run --name=systemd-testquadlet --cidfile=/run/user/1000/testquadlet.cid --replace --rm --cgroups=split --sdnotify=conmon -d --log-level=debug docker.io/alpine sleep infinity)"
Sep 17 22:00:11 localhost-live testquadlet[3047]: time="2024-09-17T22:00:11+02:00" level=debug msg="Notify sent successfully"
Sep 17 22:00:11 localhost-live testquadlet[3047]: time="2024-09-17T22:00:11+02:00" level=debug msg="Called run.PersistentPostRunE(/usr/bin/podman run --name=systemd-testquadlet --cidfile=/run/user/1000/testquadlet.cid --replace --rm --cgroups=split --sdnotify=conmon -d --log-level=debug docker.io/alpine sleep infinity)"And compared it to the host logs where -d fails:
https://github.com/containers/podman/issues/23990#issuecomment-2356588344
Sep 17 20:07:26 aurora testquadlet[1177076]: time="2024-09-17T20:07:26+02:00" level=debug msg="Called run.PersistentPreRunE(/usr/bin/podman run --name=systemd-testquadlet --cidfile=/run/user/1000/testquadlet.cid --replace --rm --cgroups=split --sdnotify=conmon -d --log-level=debug docker.io/alpine sleep infinity)"
Sep 17 20:07:26 aurora conmon[1177107]: conmon 799bacc6b24d58f6a839 <nwarn>: Failed to add inotify watch for /sys/fs/cgroup/memory.events
Sep 17 20:07:26 aurora testquadlet[1177076]: time="2024-09-17T20:07:26+02:00" level=debug msg="Notify sent successfully"
Sep 17 20:07:26 aurora testquadlet[1177076]: time="2024-09-17T20:07:26+02:00" level=debug msg="Called run.PersistentPostRunE(/usr/bin/podman run --name=systemd-testquadlet --cidfile=/run/user/1000/testquadlet.cid --replace --rm --cgroups=split --sdnotify=conmon -d --log-level=debug docker.io/alpine sleep infinity)"Sep 17 20:07:26 aurora conmon[1177107]: conmon 799bacc6b24d58f6a839 <nwarn>: Failed to add inotify watch for /sys/fs/cgroup/memory.eventsI was curious, so I tried ls /sys/fs/cgroup/memory.events on the host and inside the VM and see that this directory does NOT exist on either of them. Meaning that it looks like conmon ONLY tries to access that non-existent file on the HOST.
So far, there's some pretty strong hints that there's a bug, in which conmon on my host is trying to watch a non-existent file (/sys/fs/cgroup/memory.events), whereas on the VM (fresh Fedora 40 installation) conmon doesn't try to watch that file. And when the host fails to watch that non-existent signal file, conmon exits everything.
This is my strongest theory at the moment. I would have to debug differences in cgroup settings between guest and host.
Here's a comparison of host and VM podman info:
I compared them in Meld and the only real differences are:
/run/user/1000/podman/podman.sock) exits: Host=yes, VM=no.Any ideas for how to debug the Failed to add inotify watch for /sys/fs/cgroup/memory.events reason? There could be differences in the cgroups settings between a fresh Fedora Workstation 40 and one that has been upgraded, but I don't know how to check that. All I know so far is that the file doesn't exist on either VM or host, and that conmon only tries to access it on the Host, and that this is the most likely reason why the podman quadlet service is terminating.
Arcitec
commented
1 month ago @Luap99 @rhatdan @giuseppe
There is a bug in either conmon, podman, systemd or pia-vpn.
The issue is extremely easy to reproduce:
~/.config/containers/systemd/testquadlet.container with the following contents:
[Unit]
Description=Sleep Container[Container] Image=docker.io/alpine PodmanArgs=--log-level=debug Exec=sleep infinity
[Install] WantedBy=default.target
- Generate the updated service and run it with system logging visible:
```sh
$ systemctl --user daemon-reload; systemctl --user restart testquadlet --no-block; journalctl --user -f$ podman ps$ systemctl --user stop testquadlet$ cd ~/Downloads
$ chmod +x pia-linux-3.6.1-08339.run
$ ./pia-linux-3.6.1-08339.run$ systemctl --user daemon-reload; systemctl --user restart testquadlet --no-block; journalctl --user -f$ sudo umount /opt/piavpn/etc/cgroup/net_cls$ mount | grep -i cgroup
cgroup2 on /sys/fs/cgroup type cgroup2 (rw,nosuid,nodev,noexec,relatime,seclabel,nsdelegate,memory_recursiveprot)
none on /opt/piavpn/etc/cgroup/net_cls type cgroup (rw,relatime,seclabel,net_cls)net_cls and may be related. It's a ticket where a bug was fixed in systemd so that it properly ignores legacy app cgroup v1s./opt/piavpn/etc/cgroup/net_cls so the above issue does not seem relevant in that aspect.IMPORTANT Edit: I found the kernel documentation for cgroups which confirms that the "do not break userspace" rule of kernel development is still in effect, and means that mounting cgroup v1 and cgroup v2 at the same time is 100% supported and valid.
"All controllers which support v2 and are not bound to a v1 hierarchy are automatically bound to the v2 hierarchy and show up at the root. Controllers which are not in active use in the v2 hierarchy can be bound to other hierarchies. This allows mixing v2 hierarchy with the legacy v1 multiple hierarchies in a fully backward compatible way."
From what I've been able to understand so far, their cgroupv1 at /opt/piavpn/etc/cgroup/net_cls is totally fine since it's at a different path, and the kernel and systemd doesn't mind at all, and that this is a bug in podman which misdetects the cgroup filesystems when there are multiple kinds of cgroups mounted?
While it's regrettable that PIA VPN creates a legacy Cgroup v1, it's totally valid to do so, and it places it in a non-conflicting location at /opt/piavpn/etc/cgroup/net_cls where there's no mixing with the core system cgroups.
Systemd themselves added support for legacy Cgroup v1s on Cgroup v2 systems in one of the tickets I linked to above, which is their own acknowledgement that this is valid. The kernel docs confirm it too.
And then we have tools such as LXC, which is another container runner technology which supports systems that have Cgroup v1 mounts at various locations on a Cgroup v2 system, as seen when people ensured that the v1 net_cls simply wasn't mounted under the v2 path: here and another reference here
Therefore it seems pretty clear that the bug is in podman or conmon. I see so many people in other tickets who wasted days on debugging this situation. Would it perhaps be possible to revisit this issue and code cgroup detection into podman so that it tries to add itself to the system's cgroup v2 rather than getting confused by cgroup v1s from other apps?
The issue doesn't seem to exist in systemd, since I have around 1000 services in total between my system and user units, and all of them run and properly use cgroupv2, except for podman's quadlets which fails to start when systems contain both cgroup v1 and cgroup v2 mounts.
The small test-case in this message could be helpful for coding some detection to avoid cgroup v1s in podman. Furthermore, the systemd ticket links to some commits which show the techniques that systemd used for properly filtering and supporting mixed Cgroup v1 and v2 systems.
It would be such a big improvement if Podman detects Cgroup v2 and registers itself to that while ignoring backwards-compatible v1 groups created by various other apps.
I'm looking forward to hearing your feedback. :)
giuseppe
commented
1 month ago I've tried to manually mount a cgroup v1 hierarchy and everything seems to work fine. I don't think it is a podman/conmon/crun issue if the container runs. The cgroup somehow confuses systemd, that terminates the container.
Please try to replace the ExecStop directive with a /usr/bin/sleep 600 and restart the service. While the ExecStop command runs, can you check what systemctl status reports for the service?
Do you get the same behaviour if you stop the VPN service (the cgroup tree is still present but there is no process running)? That could also manage the cgroup and terminate processes that are not recognized
Luap99
commented
1 month ago Just to be clear here regarding the sequence,
podman starts the container fine, podman writes to the systemd notify socket the the mainpid of conmon and signals the ready status which also seems to work fine
Then something is causing systemd to stop the unit as ExecStop= is triggered, one way this happens if the mainpid conmon exited (which isn't the case here because then the container would have died already and no stop signal would be delivered by podman). So something else is confused by the cgroup setup which triggers the ExecStop= to be run.
giuseppe
commented
1 month ago I think I found the reason, we have a wrong check for the ownership for the current cgroup that causes the current process to be moved to a different scope. I've opened a PR:
Arcitec
commented
1 month ago @giuseppe Thank you so much. All of you are absolutely brilliant. Podman is one of the most important projects in the world and I am grateful to all of you. :)
atagen
commented
1 month ago is this fix in 5.2.4 or only forthcoming 5.3.0?
giuseppe
commented
1 month ago the fix is not in 5.2.4
(Edit: The exact issue has been found.)
Issue Description
The quadlet service exits immediately. The same command runs perfectly when executed manually outside of systemd.
Steps to reproduce the issue
I have spent 5 hours trying everything I can think of and doing painstaking research, but I cannot figure out why the service exits immediately when run via systemd, but works perfectly when run manually.
Steps to reproduce the issue:
~/.config/containers/systemd/testquadlet.containerwith the following contents:[Container] Image=docker.io/alpine PodmanArgs=--log-level=debug Exec=sleep infinity
[Install] WantedBy=default.target
systemctl --user daemon-reloadto generate the service andsystemctl --user start testquadletto start it, followed bysystemctl --user status testquadlet:Sep 17 19:34:15 aurora testquadlet[1170019]: time="2024-09-17T19:34:15+02:00" level=debug msg="No hostname set; container's hostname will default to runtime default" Sep 17 19:34:15 aurora testquadlet[1170019]: time="2024-09-17T19:34:15+02:00" level=debug msg="Loading seccomp profile from \"/usr/share/containers/seccomp.json\"" Sep 17 19:34:15 aurora testquadlet[1170019]: time="2024-09-17T19:34:15+02:00" level=debug msg="Allocated lock 6 for container c68529ebce9c0b8185535904dcaa4cdf2274783161e75558be5dbd64932b8abb" Sep 17 19:34:15 aurora testquadlet[1170019]: time="2024-09-17T19:34:15+02:00" level=debug msg="exporting opaque data as blob \"sha256:91ef0af61f39ece4d6710e465df5ed6ca12112358344fd51ae6a3b886634148b\"" Sep 17 19:34:15 aurora testquadlet[1170019]: time="2024-09-17T19:34:15+02:00" level=debug msg="Cached value indicated that idmapped mounts for overlay are not supported" Sep 17 19:34:15 aurora testquadlet[1170019]: time="2024-09-17T19:34:15+02:00" level=debug msg="Check for idmapped mounts support " Sep 17 19:34:15 aurora testquadlet[1170019]: time="2024-09-17T19:34:15+02:00" level=debug msg="Created container \"c68529ebce9c0b8185535904dcaa4cdf2274783161e75558be5dbd64932b8abb\"" Sep 17 19:34:15 aurora testquadlet[1170019]: time="2024-09-17T19:34:15+02:00" level=debug msg="Container \"c68529ebce9c0b8185535904dcaa4cdf2274783161e75558be5dbd64932b8abb\" has work directory \"/home/johnny/.local/share/containers/storage/overlay-containers/c68529ebce9c0b8185535904dcaa4cdf2274783161e75558be5dbd64932b8abb/userdata\"" Sep 17 19:34:15 aurora testquadlet[1170019]: time="2024-09-17T19:34:15+02:00" level=debug msg="Container \"c68529ebce9c0b8185535904dcaa4cdf2274783161e75558be5dbd64932b8abb\" has run directory \"/run/user/1000/containers/overlay-containers/c68529ebce9c0b8185535904dcaa4cdf2274783161e75558be5dbd64932b8abb/userdata\"" Sep 17 19:34:15 aurora systemd[4838]: Started testquadlet.service - Sleep Container.
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
podman psagain:podman info output
Podman in a container
No
Privileged Or Rootless
Rootless
Upstream Latest Release
No
Additional environment details
Fedora Workstation 40
Additional information
It happens to every container service. I have tried several others and they all fail to start when using the systemd service, but start perfectly when running the command manually.