I have a simple systemd service in /etc/systemd/system/logtest.service, which creates a Podman container that outputs some text:
[Unit]
Description=Systemd log test
[Service]
Type=oneshot
ExecStart=podman run --rm busybox echo This should get logged.
When I start the service, I see the line of text:
# systemctl start logtest
# journalctl -u logtest --since '1 min ago'
Mar 28 20:55:31 testserver systemd[1]: Starting Systemd log test...
Mar 28 20:55:32 testserver podman[435178]: 2022-03-28 20:55:32.027215747 +0000 UTC m=+0.084992872 image pull busybox
Mar 28 20:55:32 testserver podman[435178]:
Mar 28 20:55:32 testserver podman[435178]: 2022-03-28 20:55:32.27963909 +0000 UTC m=+0.337416181 container create f08d9eb3e843f601873c1b3db721c42175a56b27b9680dbd123781ca3ff7b808 (image=docker.io/library/busybox:latest, name=stupefied_gould)
Mar 28 20:55:32 testserver podman[435178]: 2022-03-28 20:55:32.611727831 +0000 UTC m=+0.669504926 container init f08d9eb3e843f601873c1b3db721c42175a56b27b9680dbd123781ca3ff7b808 (image=docker.io/library/busybox:latest, name=stupefied_gould)
Mar 28 20:55:32 testserver stupefied_gould[435330]: This should get logged.
Mar 28 20:55:32 testserver podman[435178]: 2022-03-28 20:55:32.674571326 +0000 UTC m=+0.732348424 container start f08d9eb3e843f601873c1b3db721c42175a56b27b9680dbd123781ca3ff7b808 (image=docker.io/library/busybox:latest, name=stupefied_gould)
Mar 28 20:55:32 testserver podman[435178]: 2022-03-28 20:55:32.674724261 +0000 UTC m=+0.732501430 container attach f08d9eb3e843f601873c1b3db721c42175a56b27b9680dbd123781ca3ff7b808 (image=docker.io/library/busybox:latest, name=stupefied_gould)
Mar 28 20:55:32 testserver podman[435178]: This should get logged.
Mar 28 20:55:32 testserver podman[435178]: 2022-03-28 20:55:32.707256608 +0000 UTC m=+0.765033742 container died f08d9eb3e843f601873c1b3db721c42175a56b27b9680dbd123781ca3ff7b808 (image=docker.io/library/busybox:latest, name=stupefied_gould)
Mar 28 20:55:33 testserver podman[435178]: 2022-03-28 20:55:33.291714221 +0000 UTC m=+1.349491334 container remove f08d9eb3e843f601873c1b3db721c42175a56b27b9680dbd123781ca3ff7b808 (image=docker.io/library/busybox:latest, name=stupefied_gould)
Mar 28 20:55:33 testserver systemd[1]: logtest.service: Deactivated successfully.
Mar 28 20:55:33 testserver systemd[1]: Finished Systemd log test.
The same can also be seen in systemctl status logtest.
But if I create the container in rootless mode under another user by adding User=logtestuser to the [Service] section, I no longer see the message by using the two methods above:
# systemctl start logtest
# journalctl -u logtest --since '1 min ago'
Mar 28 20:29:24 testserver systemd[1]: Starting Systemd log test...
Mar 28 20:29:26 testserver systemd[1]: logtest.service: Deactivated successfully.
Mar 28 20:29:26 testserver systemd[1]: Finished Systemd log test.
However, the log message is not lost. I can see it in the full journalctl output if I don't use -u:
# journalctl --since '1 min ago'
Mar 28 20:29:24 testserver systemd[1]: Starting Systemd log test...
Mar 28 20:29:25 testserver systemd[393984]: Started podman-434593.scope.
Mar 28 20:29:25 testserver podman[434593]: 2022-03-28 20:29:25.026488198 +0000 UTC m=+0.171108223 image pull busybox
Mar 28 20:29:25 testserver podman[434593]:
Mar 28 20:29:25 testserver podman[434593]: 2022-03-28 20:29:25.29202509 +0000 UTC m=+0.436645186 container create 4d81454621f7b0629bb72047e7e0df6490bfb6bf50dd09d5fe5c59de123c4fb9 (image=docker.io/library/busybox:latest, name=cool_leavitt)
Mar 28 20:29:25 testserver systemd[393984]: Started libcrun container.
Mar 28 20:29:25 testserver podman[434593]: 2022-03-28 20:29:25.575793516 +0000 UTC m=+0.720413681 container init 4d81454621f7b0629bb72047e7e0df6490bfb6bf50dd09d5fe5c59de123c4fb9 (image=docker.io/library/busybox:latest, name=cool_leavitt)
Mar 28 20:29:25 testserver cool_leavitt[434664]: This should get logged.
Mar 28 20:29:25 testserver podman[434593]: 2022-03-28 20:29:25.668965604 +0000 UTC m=+0.813585693 container start 4d81454621f7b0629bb72047e7e0df6490bfb6bf50dd09d5fe5c59de123c4fb9 (image=docker.io/library/busybox:latest, name=cool_leavitt)
Mar 28 20:29:25 testserver podman[434593]: 2022-03-28 20:29:25.669194055 +0000 UTC m=+0.813814093 container attach 4d81454621f7b0629bb72047e7e0df6490bfb6bf50dd09d5fe5c59de123c4fb9 (image=docker.io/library/busybox:latest, name=cool_leavitt)
Mar 28 20:29:25 testserver podman[434593]: This should get logged.
Mar 28 20:29:25 testserver podman[434593]: 2022-03-28 20:29:25.715669116 +0000 UTC m=+0.860289157 container died 4d81454621f7b0629bb72047e7e0df6490bfb6bf50dd09d5fe5c59de123c4fb9 (image=docker.io/library/busybox:latest, name=cool_leavitt)
Mar 28 20:29:26 testserver podman[434593]: 2022-03-28 20:29:26.417620766 +0000 UTC m=+1.562240892 container remove 4d81454621f7b0629bb72047e7e0df6490bfb6bf50dd09d5fe5c59de123c4fb9 (image=docker.io/library/busybox:latest, name=cool_leavitt)
Mar 28 20:29:26 testserver systemd[1]: logtest.service: Deactivated successfully.
Mar 28 20:29:26 testserver systemd[1]: Finished Systemd log test.
So it only gets disassociated from the service somehow. Why does this happen? Is there a proper way or at least a nice workaround to look at logs from services with rootless containers?
When I run the container directly from the shell, the message appears:
# sudo -u logtestuser podman run --rm busybox echo This should get logged.
This should get logged.
I would think that this command is very similar to how systemd starts the service. And evidently there is output coming out of the podman run process. So I don't understand why it wouldn't be associated with the service.
This is on a fairly up-to-date Fedora 35 with loginctl enable-linger logtestuser.
User=is currently not supportedsudo systemd-run -M logtestuser@ --quiet --user --collect --pipe --wait podman ...oversudo -u logtestuser podman ...(see troublehooting.md)