Rootless container startup failure at bootup, launches fine manually
We've got a Ubuntu 22.04 server running a rootless container as a systemd user service on Podman 4.4.2, using Quadlet. Podman and its dependencies are installed from binary releases on GitHub and/or from source. Last night the server required a reboot due to some security updates, but the service/container failed to come back up after the boot. In the morning, I was able to manually start it up with `systemctl --user start cms_backend` with no changes to any configuration in the meantime. Here's the full journalctl output for this unit from last night after the reboot (timestamps removed for brevity): systemd[746]: cms_backend.service: unit configures an IP firewall, but not running as root. systemd[746]: (This warning is only shown for the first unit using IP firewalling.) systemd[746]: Starting CMS Backend... cms_backend[787]: time="2023-05-25T03:01:58+03:00" level=error msg="Refreshing container 8f03c9c90e6f8aab02344284ba760fe8ddbf52becb7ba95c383fb80c3bd04405: retrieving temporary directory for container 8f03c9c90e6f8aab02344284ba760fe8ddbf52becb7ba95c383fb80c3bd04405: no such container" podman[787]: 2023-05-25 03:01:59.000295722 +0300 EEST m=+0.107418901 system refresh cms_backend[787]: time="2023-05-25T03:01:59+03:00" level=warning msg="Found incomplete layer \"b767c3f7da27350a451d15f1e972cdd874ea0e6f4c38fad1f644686f0831786f\", deleting it" cms_backend[787]: time="2023-05-25T03:01:59+03:00" level=error msg="Free container lock: no such file or directory" podman[787]: 2023-05-25 03:01:59.037410032 +0300 EEST m=+0.144533221 container remove 8f03c9c90e6f8aab02344284ba760fe8ddbf52becb7ba95c383fb80c3bd04405 (image=<redacted>:latest, name=cms_backend, com.<redacted>.cms.commit_sha=99d36804, com.<redacted>.cms.component=server, com.<redacted>.cms.pipeline_id=25445, PODMAN_SYSTEMD_UNIT=cms_backend.service) cms_backend[787]: Error: remove /run/user/1001/cms_backend.cid: no such file or directory podman[787]: 2023-05-25 03:01:59.00150107 +0300 EEST m=+0.108624239 image pull <redacted>:latest systemd[746]: cms_backend.service: Main process exited, code=exited, status=125/n/a systemd[746]: cms_backend.service: Failed with result 'exit-code'. systemd[746]: Failed to start CMS Backend. Here's the Quadlet generator we use: [Unit] Description=CMS Backend Wants=network-online.target After=network-online.target [Container] Image=<redacted>:latest ContainerName=cms_backend Exec=/bin/bash -c "pip install -q -e . \ && python project/manage.py migrate -v 1 \ && python project/manage.py tailwind install \ && python project/manage.py tailwind build \ && python project/manage.py collectstatic --noinput \ && python -Wd project/manage.py check \ && exec gunicorn --workers 8 --threads 4 --worker-class gthread --worker-tmp-dir /dev/shm --error-logfile - --bind 0.0.0.0:8000 --pythonpath project cms_site.wsgi:application EnvironmentFile=/home/cms/.cms_backend.env RemapUsers=manual RemapUid=0:0:1 RemapUid=100:1:1 RemapGid=0:0:1 RemapGid=65534:1:1 Network=pasta:-t,auto,-T,auto # TODO change to native format after Podman 4.5 upgrade PodmanArgs=--log-driver=journald \ --mount type=bind,source=/var/log/cms,target=/logs \ --mount type=bind,source=/srv/cms/staticfiles,target=/staticfiles [Install] WantedBy=default.target - - - - - The container itself is a lightly customized official Python 3.11 image running a Django application, practically identical to others that we're running with no similar issues. The entry point of the image is ["/usr/bin/dumb-init", "--"]. Like I said, the service came up manually just fine several hours after the initial failure, so it doesn't seem likely that this is a problem in our application code. I can't decipher the error messages, can someone?
On 5/25/23 08:03, jklaiho@iki.fi wrote:
systemd[746]: cms_backend.service: unit configures an IP firewall, but not running as root. systemd[746]: (This warning is only shown for the first unit using IP firewalling.)
I'm not an expert, but to my untrained eye, this message seems to be the root-cause indicator. I can't say for sure where/why that error is generated but it seems like it could be some kind of bug in quadlet interactions w/ the rest of systemd. Maybe try changing the dependencies (Wants/After) might make a difference? That's a total guess though. --- Chris Evich (he/him), RHCA III Senior Quality Assurance Engineer If it ain't broke, your hammer isn't wide 'nough.
The IP firewall warning seems to be unrelated. On another server where we didn't get this problem on a reboot, the same warning is emitted for one of the several rootless containers running there. It's interesting on its own, and I found where it happens in the systemd code here: https://github.com/systemd/systemd/blob/e30b4c13570a5e4ec794d480d5371e9c7395... ...but that seems like another, likely benign issue with rootless Podman and systemd/cgroups, maybe? The later errors seem to be the actual failure here, but I don't know what to make of them. - JK
On Thursday, May 25, 2023 at 7:21 PM, Chris Evich <cevich@redhat.com (mailto:cevich@redhat.com)> wrote: On 5/25/23 08:03, jklaiho@iki.fi wrote:
systemd[746]: cms_backend.service: unit configures an IP firewall, but not running as root. systemd[746]: (This warning is only shown for the first unit using IP firewalling.)
I'm not an expert, but to my untrained eye, this message seems to be the root-cause indicator. I can't say for sure where/why that error is generated but it seems like it could be some kind of bug in quadlet interactions w/ the rest of systemd. Maybe try changing the dependencies (Wants/After) might make a difference? That's a total guess though.
--- Chris Evich (he/him), RHCA III Senior Quality Assurance Engineer If it ain't broke, your hammer isn't wide 'nough. _______________________________________________ Podman mailing list -- podman@lists.podman.io To unsubscribe send an email to podman-leave@lists.podman.io
Hrmmm. Looking at the logs you provided more (again, I'm not a quadlet or systemd expert), I'm wondering if most of the warnings/errors are also harmless because I see toward the end: podman[787]: 2023-05-25 03:01:59.00150107 +0300 EEST m=+0.108624239 image pull <redacted>:latest If any of the prior messages were significant, I can't imagine podman bothering to try and pull the image. If the prior messages are harmless, it suggests troubleshooting should start with: systemd[746]: cms_backend.service: Main process exited, code=exited, status=125/n/a Looking at your quadlet files, I noticed: Exec=/bin/bash -c "pip install -q -e . \ ...cut... but cannot see a closing " (quote) anywhere in that big Exec string. Hopefully this is copy-paste error. I can't imagine how it could work manually with a missing quote like that. Chris Evich (he/him), RHCA III Senior Quality Assurance Engineer If it ain't broke, your hammer isn't wide 'nough. On 5/29/23 03:32, jklaiho@iki.fi wrote:
The IP firewall warning seems to be unrelated. On another server where we didn't get this problem on a reboot, the same warning is emitted for one of the several rootless containers running there. It's interesting on its own, and I found where it happens in the systemd code here:
https://github.com/systemd/systemd/blob/e30b4c13570a5e4ec794d480d5371e9c7395... <https://github.com/systemd/systemd/blob/e30b4c13570a5e4ec794d480d5371e9c739570d9/src/core/cgroup.c#L2034>
...but that seems like another, likely benign issue with rootless Podman and systemd/cgroups, maybe?
The later errors seem to be the actual failure here, but I don't know what to make of them.
- JK
On Thursday, May 25, 2023 at 7:21 PM, Chris Evich <cevich@redhat.com <mailto:cevich@redhat.com>> wrote: On 5/25/23 08:03, jklaiho@iki.fi wrote:
systemd[746]: cms_backend.service: unit configures an IP firewall, but not running as root. systemd[746]: (This warning is only shown for the first unit using IP firewalling.)
I'm not an expert, but to my untrained eye, this message seems to be the root-cause indicator. I can't say for sure where/why that error is generated but it seems like it could be some kind of bug in quadlet interactions w/ the rest of systemd. Maybe try changing the dependencies (Wants/After) might make a difference? That's a total guess though.
--- Chris Evich (he/him), RHCA III Senior Quality Assurance Engineer If it ain't broke, your hammer isn't wide 'nough. _______________________________________________ Podman mailing list -- podman@lists.podman.io To unsubscribe send an email to podman-leave@lists.podman.io
participants (2)
-
Chris Evich -
jklaiho＠iki.fi