I'm not sure if this is a bug, but I have completely no clue, what happened here, so I would really appreciate I someone could take a look at it.
I'm running latest Debian 12 and podman 4.3.1. I used podman generate systemd --new --files --name to generate systemd services, because quadlet is not yet available in Debian.
Here are the systemd units where the issue appeared:
Here is what happend. On 2 AM podman auto-update automatically runs (systemd timer). Restarting the container after updating did not work because of a podman error I don't know where it came from:
Nov 14 02:00:00 secondary.cloud.example.de systemd[958]: Starting podman-auto-update.service - Podman auto-update service...
Nov 14 02:00:00 secondary.cloud.example.de podman[195885]: 2024-11-14 02:00:00.228384676 +0100 CET m=+0.049258391 system auto-update
Nov 14 02:00:02 secondary.cloud.example.de podman[195885]: Trying to pull docker.io/library/caddy:latest...
Nov 14 02:00:04 secondary.cloud.example.de podman[195885]: Getting image source signatures
Nov 14 02:00:04 secondary.cloud.example.de podman[195885]: Copying blob sha256:97f2636bb565977eac2181eb6f095824febc32cfb1fa8b5f2b74dbd664031638
Nov 14 02:00:04 secondary.cloud.example.de podman[195885]: Copying blob sha256:4f4fb700ef54461cfa02571ae0db9a0dc1e0cdb5577484a6d75e68dc38e8acc1
Nov 14 02:00:04 secondary.cloud.example.de podman[195885]: Copying blob sha256:b667dcdaab274461f78f562875abc47be7e3db2dcf2c9f5a2b331a3754fb35e4
Nov 14 02:00:04 secondary.cloud.example.de podman[195885]: Copying blob sha256:91e24303ace2224cc9aabb3349ff7a08bea09f9bab509b5cc86553dcb11490e9
Nov 14 02:00:04 secondary.cloud.example.de podman[195885]: Copying blob sha256:da9db072f522755cbeb85be2b3f84059b70571b229512f1571d9217b77e1087f
Nov 14 02:00:06 secondary.cloud.example.de podman[195885]: Copying config sha256:faa9a2c5676288c88ffa3ae9812dd7eb5ddeed8c06245b3f8fa181e9dfcf6601
Nov 14 02:00:06 secondary.cloud.example.de podman[195885]: Writing manifest to image destination
Nov 14 02:00:06 secondary.cloud.example.de podman[195885]: Storing signatures
Nov 14 02:00:06 secondary.cloud.example.de systemd[958]: Stopping container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service...
Nov 14 02:00:06 secondary.cloud.example.de 01_reverse-proxy_caddy[1791]: {"level":"info","ts":1731546006.2685885,"msg":"shutting down apps, then terminating","signal":"SIGTERM"}
Nov 14 02:00:06 secondary.cloud.example.de 01_reverse-proxy_caddy[1791]: {"level":"warn","ts":1731546006.2688577,"msg":"exiting; byeee!! π","signal":"SIGTERM"}
Nov 14 02:00:06 secondary.cloud.example.de 01_reverse-proxy_caddy[1791]: {"level":"info","ts":1731546006.2691529,"logger":"http","msg":"servers shutting down with eternal grace period"}
Nov 14 02:00:06 secondary.cloud.example.de 01_reverse-proxy_caddy[1791]: {"level":"info","ts":1731546006.2702558,"logger":"admin","msg":"stopped previous server","address":"localhost:2019"}
Nov 14 02:00:06 secondary.cloud.example.de 01_reverse-proxy_caddy[1791]: {"level":"info","ts":1731546006.2702816,"msg":"shutdown complete","signal":"SIGTERM","exit_code":0}
Nov 14 02:00:06 secondary.cloud.example.de systemd[958]: libpod-04f86c4bf4d9f5157963e1429d85f16918157041dc5b5c838a3a6f57ac1b0973.scope: Consumed 1min 58.476s CPU time.
Nov 14 02:00:06 secondary.cloud.example.de podman[195885]: 2024-11-14 02:00:02.808624034 +0100 CET m=+2.629497768 image pull docker.io/library/caddy:latest
Nov 14 02:00:06 secondary.cloud.example.de podman[195938]: 2024-11-14 02:00:06.317635965 +0100 CET m=+0.037701023 container died 04f86c4bf4d9f5157963e1429d85f16918157041dc5b5c838a3a6f57ac1b0973 (image=docker.io/library/caddy:latest, nam>
Nov 14 02:00:06 secondary.cloud.example.de podman[195938]: 2024-11-14 02:00:06.449903446 +0100 CET m=+0.169968494 container remove 04f86c4bf4d9f5157963e1429d85f16918157041dc5b5c838a3a6f57ac1b0973 (image=docker.io/library/caddy:latest, n>
Nov 14 02:00:06 secondary.cloud.example.de podman[195938]: 2024-11-14 02:00:06.451569954 +0100 CET m=+0.171635039 pod stop a34d2ab76d3cb7d3fa30d8c460e47629b56880013a516fe9086b6992d47279bd (image=, name=01_reverse-proxy)
Nov 14 02:00:06 secondary.cloud.example.de podman[195928]: 04f86c4bf4d9f5157963e1429d85f16918157041dc5b5c838a3a6f57ac1b0973
Nov 14 02:00:06 secondary.cloud.example.de systemd[958]: Stopped container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 02:00:06 secondary.cloud.example.de systemd[958]: Starting container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service...
Nov 14 02:00:06 secondary.cloud.example.de podman[195960]:
Nov 14 02:00:06 secondary.cloud.example.de podman[195960]: 2024-11-14 02:00:06.688147074 +0100 CET m=+0.132039685 container create de849b5a4409d2e599e6446c67f886f6c5943b1cb9a511a478356a338d2d4064 (image=docker.io/library/caddy:latest, n>
Nov 14 02:00:06 secondary.cloud.example.de podman[195960]: time="2024-11-14T02:00:06+01:00" level=error msg="Starting some container dependencies"
Nov 14 02:00:06 secondary.cloud.example.de podman[195960]: time="2024-11-14T02:00:06+01:00" level=error msg="\"unable to restart a container in a paused or unknown state: container state improper\""
Nov 14 02:00:06 secondary.cloud.example.de podman[195960]: 2024-11-14 02:00:06.59113022 +0100 CET m=+0.035022823 image pull docker.io/library/caddy:latest
Nov 14 02:00:06 secondary.cloud.example.de podman[195960]: 2024-11-14 02:00:06.748024507 +0100 CET m=+0.191917093 container remove de849b5a4409d2e599e6446c67f886f6c5943b1cb9a511a478356a338d2d4064 (image=docker.io/library/caddy:latest, n>
Nov 14 02:00:06 secondary.cloud.example.de podman[195960]: Error: starting some containers: internal libpod error
Nov 14 02:00:06 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Main process exited, code=exited, status=126/n/a
Nov 14 02:00:06 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Failed with result 'exit-code'.
Nov 14 02:00:06 secondary.cloud.example.de systemd[958]: Failed to start container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 02:00:06 secondary.cloud.example.de systemd[958]: Stopped container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 02:00:06 secondary.cloud.example.de systemd[958]: Starting container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service...
Nov 14 02:00:06 secondary.cloud.example.de podman[195885]: 2024-11-14 02:00:06.823311402 +0100 CET m=+6.644185139 image tag 11229070f1e2ac463af222c4a912d29a1f1dbed27610c6de2ad5f0a55d43f23e docker.io/library/caddy:latest
Nov 14 02:00:06 secondary.cloud.example.de podman[195982]:
Nov 14 02:00:06 secondary.cloud.example.de podman[195982]: 2024-11-14 02:00:06.891752094 +0100 CET m=+0.035483130 image pull docker.io/library/caddy:latest
Nov 14 02:00:06 secondary.cloud.example.de podman[195982]: 2024-11-14 02:00:06.995718801 +0100 CET m=+0.139449837 container create d02ece867b7ab2d32cf37da2c552f923459c3047b66b36a48b2bc7214d9de997 (image=docker.io/library/caddy:latest, n>
Nov 14 02:00:06 secondary.cloud.example.de podman[195982]: time="2024-11-14T02:00:06+01:00" level=error msg="Starting some container dependencies"
Nov 14 02:00:06 secondary.cloud.example.de podman[195982]: time="2024-11-14T02:00:06+01:00" level=error msg="\"unable to restart a container in a paused or unknown state: container state improper\""
Nov 14 02:00:07 secondary.cloud.example.de podman[195982]: 2024-11-14 02:00:07.07297124 +0100 CET m=+0.216702315 container remove d02ece867b7ab2d32cf37da2c552f923459c3047b66b36a48b2bc7214d9de997 (image=docker.io/library/caddy:latest, na>
Nov 14 02:00:07 secondary.cloud.example.de podman[195982]: Error: starting some containers: internal libpod error
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Main process exited, code=exited, status=126/n/a
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Failed with result 'exit-code'.
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: Failed to start container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 02:00:07 secondary.cloud.example.de podman[195885]: UNIT CONTAINER IMAGE POLICY UPDATED
Nov 14 02:00:07 secondary.cloud.example.de podman[195885]: container-02_monitoring_uptime-kuma.service 044e6dd66aad (02_monitoring_uptime-kuma) docker.io/louislam/uptime-kuma:latest registry false
Nov 14 02:00:07 secondary.cloud.example.de podman[195885]: container-01_reverse-proxy_caddy.service 04f86c4bf4d9 (01_reverse-proxy_caddy) docker.io/library/caddy:latest registry failed
Nov 14 02:00:07 secondary.cloud.example.de podman[195885]: Error: restarting unit container-01_reverse-proxy_caddy.service during rollback: expected "done" but received "failed"
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: podman-auto-update.service: Main process exited, code=exited, status=125/n/a
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: podman-auto-update.service: Failed with result 'exit-code'.
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: Failed to start podman-auto-update.service - Podman auto-update service.
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: podman-auto-update.service: Consumed 2.208s CPU time.
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Scheduled restart job, restart counter is at 1.
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: Stopped container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: Starting container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service...
Nov 14 02:00:07 secondary.cloud.example.de podman[196001]:
Nov 14 02:00:07 secondary.cloud.example.de podman[196001]: 2024-11-14 02:00:07.423887828 +0100 CET m=+0.127235666 container create 6766b76837785a5ad125a475781433db496c2b47d5f5e65feaa44d72b4cc211d (image=docker.io/library/caddy:latest, n>
Nov 14 02:00:07 secondary.cloud.example.de podman[196001]: time="2024-11-14T02:00:07+01:00" level=error msg="Starting some container dependencies"
Nov 14 02:00:07 secondary.cloud.example.de podman[196001]: time="2024-11-14T02:00:07+01:00" level=error msg="\"unable to restart a container in a paused or unknown state: container state improper\""
Nov 14 02:00:07 secondary.cloud.example.de podman[196001]: 2024-11-14 02:00:07.326776453 +0100 CET m=+0.030124278 image pull docker.io/library/caddy:latest
Nov 14 02:00:07 secondary.cloud.example.de podman[196001]: 2024-11-14 02:00:07.484417267 +0100 CET m=+0.187765126 container remove 6766b76837785a5ad125a475781433db496c2b47d5f5e65feaa44d72b4cc211d (image=docker.io/library/caddy:latest, n>
Nov 14 02:00:07 secondary.cloud.example.de podman[196001]: Error: starting some containers: internal libpod error
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Main process exited, code=exited, status=126/n/a
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Failed with result 'exit-code'.
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: Failed to start container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Scheduled restart job, restart counter is at 2.
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: Stopped container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: Starting container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service...
Nov 14 02:00:07 secondary.cloud.example.de podman[196022]:
Nov 14 02:00:07 secondary.cloud.example.de podman[196022]: 2024-11-14 02:00:07.913903258 +0100 CET m=+0.109927045 container create 4ba76c84f1b8bfa7609ee79b1a4755e1f45035aa8169ae84bf3ded7b34cd43d6 (image=docker.io/library/caddy:latest, n>
Nov 14 02:00:07 secondary.cloud.example.de podman[196022]: time="2024-11-14T02:00:07+01:00" level=error msg="Starting some container dependencies"
Nov 14 02:00:07 secondary.cloud.example.de podman[196022]: time="2024-11-14T02:00:07+01:00" level=error msg="\"unable to restart a container in a paused or unknown state: container state improper\""
Nov 14 02:00:07 secondary.cloud.example.de podman[196022]: 2024-11-14 02:00:07.83398009 +0100 CET m=+0.030003864 image pull docker.io/library/caddy:latest
Nov 14 02:00:07 secondary.cloud.example.de podman[196022]: 2024-11-14 02:00:07.996520737 +0100 CET m=+0.192544549 container remove 4ba76c84f1b8bfa7609ee79b1a4755e1f45035aa8169ae84bf3ded7b34cd43d6 (image=docker.io/library/caddy:latest, n>
Nov 14 02:00:07 secondary.cloud.example.de podman[196022]: Error: starting some containers: internal libpod error
Nov 14 02:00:07 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Main process exited, code=exited, status=126/n/a
Nov 14 02:00:08 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Failed with result 'exit-code'.
Nov 14 02:00:08 secondary.cloud.example.de systemd[958]: Failed to start container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 02:00:08 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Scheduled restart job, restart counter is at 3.
Nov 14 02:00:08 secondary.cloud.example.de systemd[958]: Stopped container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 02:00:08 secondary.cloud.example.de systemd[958]: Starting container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service...
Nov 14 02:00:08 secondary.cloud.example.de podman[196042]:
Nov 14 02:00:08 secondary.cloud.example.de podman[196042]: 2024-11-14 02:00:08.337891383 +0100 CET m=+0.039179174 image pull docker.io/library/caddy:latest
Nov 14 02:00:08 secondary.cloud.example.de podman[196042]: 2024-11-14 02:00:08.441266556 +0100 CET m=+0.142554341 container create b8cd827c15f42825a0987399d8098f134a502ccd447c8de42ccfc732117c0a7e (image=docker.io/library/caddy:latest, n>
Nov 14 02:00:08 secondary.cloud.example.de podman[196042]: time="2024-11-14T02:00:08+01:00" level=error msg="Starting some container dependencies"
Nov 14 02:00:08 secondary.cloud.example.de podman[196042]: time="2024-11-14T02:00:08+01:00" level=error msg="\"unable to restart a container in a paused or unknown state: container state improper\""
Nov 14 02:00:08 secondary.cloud.example.de podman[196042]: 2024-11-14 02:00:08.505366237 +0100 CET m=+0.206654044 container remove b8cd827c15f42825a0987399d8098f134a502ccd447c8de42ccfc732117c0a7e (image=docker.io/library/caddy:latest, n>
Nov 14 02:00:08 secondary.cloud.example.de podman[196042]: Error: starting some containers: internal libpod error
Nov 14 02:00:08 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Main process exited, code=exited, status=126/n/a
Nov 14 02:00:08 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Failed with result 'exit-code'.
Nov 14 02:00:08 secondary.cloud.example.de systemd[958]: Failed to start container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 02:00:08 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Scheduled restart job, restart counter is at 4.
Nov 14 02:00:08 secondary.cloud.example.de systemd[958]: Stopped container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 02:00:08 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Start request repeated too quickly.
Nov 14 02:00:08 secondary.cloud.example.de systemd[958]: container-01_reverse-proxy_caddy.service: Failed with result 'exit-code'.
Nov 14 02:00:08 secondary.cloud.example.de systemd[958]: Failed to start container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
The rollback did also not change anything. After a couple tries it stopped trying to restart the service.
This is not what I'm wondering about. Maybe the container did not stopped correctly, that can happen I guess. At 5:22 AM I did a reboot. After that, it started correctly. But it was still running the old version, so I did another podman auto-update manually:
Nov 14 05:50:13 secondary.cloud.example.de systemd[930]: Started podman-4507.scope.
Nov 14 05:50:13 secondary.cloud.example.de podman[4507]: 2024-11-14 05:50:13.471580675 +0100 CET m=+0.075319643 system auto-update
Nov 14 05:50:16 secondary.cloud.example.de systemd[930]: Stopping container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service...
Nov 14 05:50:16 secondary.cloud.example.de podman[4507]: 2024-11-14 05:50:14.703720071 +0100 CET m=+1.307459008 image pull docker.io/library/caddy:latest
Nov 14 05:50:16 secondary.cloud.example.de 01_reverse-proxy_caddy[1826]: {"level":"info","ts":1731559816.4480512,"msg":"shutting down apps, then terminating","signal":"SIGTERM"}
Nov 14 05:50:16 secondary.cloud.example.de 01_reverse-proxy_caddy[1826]: {"level":"warn","ts":1731559816.4482358,"msg":"exiting; byeee!! π","signal":"SIGTERM"}
Nov 14 05:50:16 secondary.cloud.example.de 01_reverse-proxy_caddy[1826]: {"level":"info","ts":1731559816.4483852,"logger":"http","msg":"servers shutting down with eternal grace period"}
Nov 14 05:50:16 secondary.cloud.example.de 01_reverse-proxy_caddy[1826]: {"level":"info","ts":1731559816.4864748,"logger":"admin","msg":"stopped previous server","address":"localhost:2019"}
Nov 14 05:50:16 secondary.cloud.example.de 01_reverse-proxy_caddy[1826]: {"level":"info","ts":1731559816.486534,"msg":"shutdown complete","signal":"SIGTERM","exit_code":0}
Nov 14 05:50:16 secondary.cloud.example.de systemd[930]: libpod-86202b5195da7d8a5f790d667c0007e628ee9d5869f5a64c5f9fee337f1be1a5.scope: Consumed 2.142s CPU time.
Nov 14 05:50:16 secondary.cloud.example.de podman[3684]: @ - - [14/Nov/2024:05:28:39 +0100] "GET /v1.12/libpod/events HTTP/1.0" 200 436 "" ""
Nov 14 05:50:16 secondary.cloud.example.de podman[3684]: @ - - [14/Nov/2024:05:28:39 +0100] "GET /v1.12/libpod/events? HTTP/1.1" 200 436 "" ""
Nov 14 05:50:16 secondary.cloud.example.de podman[3677]: @ - - [14/Nov/2024:05:28:39 +0100] "GET /v1.12/libpod/events HTTP/1.0" 200 436 "" ""
Nov 14 05:50:16 secondary.cloud.example.de podman[3677]: @ - - [14/Nov/2024:05:28:39 +0100] "GET /v1.12/libpod/events? HTTP/1.1" 200 436 "" ""
Nov 14 05:50:16 secondary.cloud.example.de podman[4519]: 2024-11-14 05:50:16.549897032 +0100 CET m=+0.161925950 container died 86202b5195da7d8a5f790d667c0007e628ee9d5869f5a64c5f9fee337f1be1a5 (image=docker.io/library/caddy:latest, name=>
Nov 14 05:50:16 secondary.cloud.example.de podman[3684]: @ - - [14/Nov/2024:05:28:40 +0100] "GET /v1.12/libpod/containers/stats?stream=true HTTP/1.1" 200 453906 "" ""
Nov 14 05:50:16 secondary.cloud.example.de podman[4519]: 2024-11-14 05:50:16.606397482 +0100 CET m=+0.218426413 container cleanup 86202b5195da7d8a5f790d667c0007e628ee9d5869f5a64c5f9fee337f1be1a5 (image=docker.io/library/caddy:latest, na>
Nov 14 05:50:16 secondary.cloud.example.de podman[4519]: 86202b5195da7d8a5f790d667c0007e628ee9d5869f5a64c5f9fee337f1be1a5
Nov 14 05:50:16 secondary.cloud.example.de podman[4519]: 2024-11-14 05:50:16.612795559 +0100 CET m=+0.224824617 pod stop c2e35e4079502b86adcf8cc9ecd24b58d2f3590014158398798170646e5ba41c (image=, name=01_reverse-proxy)
Nov 14 05:50:16 secondary.cloud.example.de podman[4543]: 2024-11-14 05:50:16.700858956 +0100 CET m=+0.038661464 container died fd3a3b3c2ecede9598ee13da081b13c9ccdef968f736970b1ecb3cf4acb4e24b (image=localhost/podman-pause:4.3.1-0, name=>
Nov 14 05:50:16 secondary.cloud.example.de podman[4543]: 2024-11-14 05:50:16.765238001 +0100 CET m=+0.103040532 container cleanup fd3a3b3c2ecede9598ee13da081b13c9ccdef968f736970b1ecb3cf4acb4e24b (image=localhost/podman-pause:4.3.1-0, na>
Nov 14 05:50:16 secondary.cloud.example.de podman[4519]: 2024-11-14 05:50:16.768287214 +0100 CET m=+0.380316132 container cleanup fd3a3b3c2ecede9598ee13da081b13c9ccdef968f736970b1ecb3cf4acb4e24b (image=localhost/podman-pause:4.3.1-0, na>
Nov 14 05:50:16 secondary.cloud.example.de podman[4519]: 2024-11-14 05:50:16.769765035 +0100 CET m=+0.381793952 pod stop c2e35e4079502b86adcf8cc9ecd24b58d2f3590014158398798170646e5ba41c (image=, name=01_reverse-proxy)
Nov 14 05:50:16 secondary.cloud.example.de podman[4543]: 2024-11-14 05:50:16.773334224 +0100 CET m=+0.111136731 pod stop c2e35e4079502b86adcf8cc9ecd24b58d2f3590014158398798170646e5ba41c (image=, name=01_reverse-proxy)
Nov 14 05:50:16 secondary.cloud.example.de podman[4559]: 2024-11-14 05:50:16.849016622 +0100 CET m=+0.050464690 pod stop c2e35e4079502b86adcf8cc9ecd24b58d2f3590014158398798170646e5ba41c (image=, name=01_reverse-proxy)
Nov 14 05:50:16 secondary.cloud.example.de podman[4559]: c2e35e4079502b86adcf8cc9ecd24b58d2f3590014158398798170646e5ba41c
Nov 14 05:50:16 secondary.cloud.example.de podman[4558]: 2024-11-14 05:50:16.973507138 +0100 CET m=+0.171598277 container remove 86202b5195da7d8a5f790d667c0007e628ee9d5869f5a64c5f9fee337f1be1a5 (image=docker.io/library/caddy:latest, nam>
Nov 14 05:50:16 secondary.cloud.example.de podman[4558]: 86202b5195da7d8a5f790d667c0007e628ee9d5869f5a64c5f9fee337f1be1a5
Nov 14 05:50:16 secondary.cloud.example.de podman[4558]: 2024-11-14 05:50:16.974942675 +0100 CET m=+0.173033785 pod stop c2e35e4079502b86adcf8cc9ecd24b58d2f3590014158398798170646e5ba41c (image=, name=01_reverse-proxy)
Nov 14 05:50:16 secondary.cloud.example.de systemd[930]: Stopped container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 05:50:16 secondary.cloud.example.de systemd[930]: container-01_reverse-proxy_caddy.service: Bound to unit pod-01_reverse-proxy.service, but unit isn't active.
Nov 14 05:50:16 secondary.cloud.example.de systemd[930]: Dependency failed for container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 05:50:16 secondary.cloud.example.de systemd[930]: container-01_reverse-proxy_caddy.service: Job container-01_reverse-proxy_caddy.service/start failed with result 'dependency'.
Nov 14 05:50:17 secondary.cloud.example.de podman[4507]: 2024-11-14 05:50:16.980891 +0100 CET m=+3.584629938 image tag 11229070f1e2ac463af222c4a912d29a1f1dbed27610c6de2ad5f0a55d43f23e docker.io/library/caddy:latest
Nov 14 05:50:17 secondary.cloud.example.de podman[4575]: 2024-11-14 05:50:17.086756886 +0100 CET m=+0.209510010 container remove fd3a3b3c2ecede9598ee13da081b13c9ccdef968f736970b1ecb3cf4acb4e24b (image=localhost/podman-pause:4.3.1-0, nam>
Nov 14 05:50:17 secondary.cloud.example.de systemd[930]: Removed slice user-libpod_pod_c2e35e4079502b86adcf8cc9ecd24b58d2f3590014158398798170646e5ba41c.slice - cgroup user-libpod_pod_c2e35e4079502b86adcf8cc9ecd24b58d2f359001415839879817>
Nov 14 05:50:17 secondary.cloud.example.de systemd[930]: user-libpod_pod_c2e35e4079502b86adcf8cc9ecd24b58d2f3590014158398798170646e5ba41c.slice: Consumed 2.149s CPU time.
Nov 14 05:50:17 secondary.cloud.example.de podman[4575]: 2024-11-14 05:50:17.101758226 +0100 CET m=+0.224511321 pod remove c2e35e4079502b86adcf8cc9ecd24b58d2f3590014158398798170646e5ba41c (image=, name=01_reverse-proxy)
Nov 14 05:50:17 secondary.cloud.example.de podman[4575]: c2e35e4079502b86adcf8cc9ecd24b58d2f3590014158398798170646e5ba41c
Nov 14 05:50:17 secondary.cloud.example.de systemd[930]: Starting pod-01_reverse-proxy.service - Podman pod-01_reverse-proxy.service...
Nov 14 05:50:17 secondary.cloud.example.de systemd[930]: Created slice user-libpod_pod_fd4625d5725ebca1f986d7dbe336905096fead74534cfe01b43b9287ba85e546.slice - cgroup user-libpod_pod_fd4625d5725ebca1f986d7dbe336905096fead74534cfe01b43b9>
Nov 14 05:50:17 secondary.cloud.example.de podman[4592]:
Nov 14 05:50:17 secondary.cloud.example.de podman[4592]: 2024-11-14 05:50:17.260211356 +0100 CET m=+0.123284970 container create 42d46f054f5f8527348fddc67eb2d568484f25c40b090d9e0ea599e1d6649b74 (image=localhost/podman-pause:4.3.1-0, nam>
Nov 14 05:50:17 secondary.cloud.example.de podman[4592]: 2024-11-14 05:50:17.265626021 +0100 CET m=+0.128699648 pod create fd4625d5725ebca1f986d7dbe336905096fead74534cfe01b43b9287ba85e546 (image=, name=01_reverse-proxy)
Nov 14 05:50:17 secondary.cloud.example.de podman[4592]: fd4625d5725ebca1f986d7dbe336905096fead74534cfe01b43b9287ba85e546
Nov 14 05:50:17 secondary.cloud.example.de systemd[930]: Started libpod-42d46f054f5f8527348fddc67eb2d568484f25c40b090d9e0ea599e1d6649b74.scope - libcrun container.
Nov 14 05:50:17 secondary.cloud.example.de podman[4601]: 2024-11-14 05:50:17.439950599 +0100 CET m=+0.144347969 container init 42d46f054f5f8527348fddc67eb2d568484f25c40b090d9e0ea599e1d6649b74 (image=localhost/podman-pause:4.3.1-0, name=>
Nov 14 05:50:17 secondary.cloud.example.de podman[4601]: 2024-11-14 05:50:17.455410259 +0100 CET m=+0.159807578 container start 42d46f054f5f8527348fddc67eb2d568484f25c40b090d9e0ea599e1d6649b74 (image=localhost/podman-pause:4.3.1-0, name>
Nov 14 05:50:17 secondary.cloud.example.de podman[4601]: 2024-11-14 05:50:17.455507272 +0100 CET m=+0.159904591 pod start fd4625d5725ebca1f986d7dbe336905096fead74534cfe01b43b9287ba85e546 (image=, name=01_reverse-proxy)
Nov 14 05:50:17 secondary.cloud.example.de podman[4601]: fd4625d5725ebca1f986d7dbe336905096fead74534cfe01b43b9287ba85e546
Nov 14 05:50:17 secondary.cloud.example.de systemd[930]: Started pod-01_reverse-proxy.service - Podman pod-01_reverse-proxy.service.
Nov 14 05:50:17 secondary.cloud.example.de systemd[930]: Starting container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service...
Nov 14 05:50:17 secondary.cloud.example.de podman[4616]:
Nov 14 05:50:17 secondary.cloud.example.de podman[4616]: 2024-11-14 05:50:17.618157098 +0100 CET m=+0.129634840 container create f9e5d42b19971c6d3bbf4d7da4e25bc3f90a19de51cc3e7a00620b359a3338ad (image=docker.io/library/caddy:latest, nam>
Nov 14 05:50:17 secondary.cloud.example.de podman[4616]: 2024-11-14 05:50:17.524488165 +0100 CET m=+0.035965870 image pull docker.io/library/caddy:latest
Nov 14 05:50:17 secondary.cloud.example.de systemd[930]: Started libpod-f9e5d42b19971c6d3bbf4d7da4e25bc3f90a19de51cc3e7a00620b359a3338ad.scope - libcrun container.
Nov 14 05:50:17 secondary.cloud.example.de podman[4616]: 2024-11-14 05:50:17.713014507 +0100 CET m=+0.224492248 container init f9e5d42b19971c6d3bbf4d7da4e25bc3f90a19de51cc3e7a00620b359a3338ad (image=docker.io/library/caddy:latest, name=>
Nov 14 05:50:17 secondary.cloud.example.de systemd[930]: Started container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 05:50:17 secondary.cloud.example.de podman[4616]: 2024-11-14 05:50:17.725896529 +0100 CET m=+0.237374243 container start f9e5d42b19971c6d3bbf4d7da4e25bc3f90a19de51cc3e7a00620b359a3338ad (image=docker.io/library/caddy:latest, name>
Nov 14 05:50:17 secondary.cloud.example.de podman[4616]: f9e5d42b19971c6d3bbf4d7da4e25bc3f90a19de51cc3e7a00620b359a3338ad
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"info","ts":1731559817.7950041,"msg":"using config from file","file":"/etc/caddy/Caddyfile"}
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"info","ts":1731559817.7976627,"msg":"adapted config to JSON","adapter":"caddyfile"}
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"warn","ts":1731559817.7976873,"msg":"Caddyfile input is not formatted; run 'caddy fmt --overwrite' to fix inconsistencies","adapter":"caddyfile","file":">
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"info","ts":1731559817.7994897,"logger":"admin","msg":"admin endpoint started","address":"localhost:2019","enforce_origin":false,"origins":["//localhost:2>
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"info","ts":1731559817.7998223,"logger":"http.auto_https","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one>
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"info","ts":1731559817.8000083,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc000628800"}
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"info","ts":1731559817.8000236,"logger":"http.auto_https","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"info","ts":1731559817.801126,"logger":"http.log","msg":"server running","name":"remaining_auto_https_redirects","protocols":["h1","h2","h3"]}
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"info","ts":1731559817.8013072,"logger":"http","msg":"enabling HTTP/3 listener","addr":":4001"}
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"info","ts":1731559817.8014958,"msg":"failed to sufficiently increase receive buffer size (was: 208 kiB, wanted: 7168 kiB, got: 416 kiB). See https://gith>
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"info","ts":1731559817.801964,"logger":"http.log","msg":"server running","name":"srv0","protocols":["h1","h2","h3"]}
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"info","ts":1731559817.802064,"logger":"http","msg":"enabling automatic TLS certificate management","domains":["monitoring.secondary.cloud.example.de","c>
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"info","ts":1731559817.805358,"msg":"autosaved config (load with --resume flag)","file":"/config/caddy/autosave.json"}
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"info","ts":1731559817.806149,"msg":"serving initial configuration"}
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"info","ts":1731559817.8175337,"logger":"tls","msg":"storage cleaning happened too recently; skipping for now","storage":"FileStorage:/data/caddy","instan>
Nov 14 05:50:17 secondary.cloud.example.de 01_reverse-proxy_caddy[4626]: {"level":"info","ts":1731559817.817674,"logger":"tls","msg":"finished cleaning storage units"}
That failed without any error from podman or the application (caddy). Very weird. I tried a couple times, to understand whats going on.
After a 4 tries that gave the exact ouput as above, It just worked. I changed nothing, I just run podman auto-update and it worked:
Nov 14 06:00:19 secondary.cloud.example.de systemd[930]: Started podman-5977.scope.
Nov 14 06:00:19 secondary.cloud.example.de podman[5977]: 2024-11-14 06:00:19.709847165 +0100 CET m=+0.086425059 system auto-update
Nov 14 06:00:22 secondary.cloud.example.de systemd[930]: Stopping container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service...
Nov 14 06:00:22 secondary.cloud.example.de podman[5977]: 2024-11-14 06:00:20.924095531 +0100 CET m=+1.300673427 image pull docker.io/library/caddy:latest
Nov 14 06:00:22 secondary.cloud.example.de 01_reverse-proxy_caddy[5190]: {"level":"info","ts":1731560422.6299198,"msg":"shutting down apps, then terminating","signal":"SIGTERM"}
Nov 14 06:00:22 secondary.cloud.example.de 01_reverse-proxy_caddy[5190]: {"level":"warn","ts":1731560422.629988,"msg":"exiting; byeee!! π","signal":"SIGTERM"}
Nov 14 06:00:22 secondary.cloud.example.de 01_reverse-proxy_caddy[5190]: {"level":"info","ts":1731560422.6301293,"logger":"http","msg":"servers shutting down with eternal grace period"}
Nov 14 06:00:22 secondary.cloud.example.de 01_reverse-proxy_caddy[5190]: {"level":"info","ts":1731560422.6307187,"logger":"admin","msg":"stopped previous server","address":"localhost:2019"}
Nov 14 06:00:22 secondary.cloud.example.de 01_reverse-proxy_caddy[5190]: {"level":"info","ts":1731560422.6307406,"msg":"shutdown complete","signal":"SIGTERM","exit_code":0}
Nov 14 06:00:22 secondary.cloud.example.de podman[5996]: 2024-11-14 06:00:22.685010457 +0100 CET m=+0.036119347 container died 9bc371c1beff7b54f25c436cd76ed183d12e7653a0cb0f89550e51067aa7c746 (image=docker.io/library/caddy:latest, name=>
Nov 14 06:00:22 secondary.cloud.example.de podman[5996]: 2024-11-14 06:00:22.815472048 +0100 CET m=+0.166580954 container remove 9bc371c1beff7b54f25c436cd76ed183d12e7653a0cb0f89550e51067aa7c746 (image=docker.io/library/caddy:latest, nam>
Nov 14 06:00:22 secondary.cloud.example.de podman[5986]: 9bc371c1beff7b54f25c436cd76ed183d12e7653a0cb0f89550e51067aa7c746
Nov 14 06:00:22 secondary.cloud.example.de systemd[930]: Stopped container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 06:00:22 secondary.cloud.example.de systemd[930]: Starting container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service...
Nov 14 06:00:23 secondary.cloud.example.de podman[6020]: 2024-11-14 06:00:22.955188457 +0100 CET m=+0.037212861 image pull docker.io/library/caddy:latest
Nov 14 06:00:23 secondary.cloud.example.de podman[6020]:
Nov 14 06:00:23 secondary.cloud.example.de podman[6020]: 2024-11-14 06:00:23.093237558 +0100 CET m=+0.175261974 container create ed72df696dc7cdb6cf31c1e6264e4cd5cb685076589a5f767e7304342369f02f (image=docker.io/library/caddy:latest, nam>
Nov 14 06:00:23 secondary.cloud.example.de systemd[930]: Started libpod-ed72df696dc7cdb6cf31c1e6264e4cd5cb685076589a5f767e7304342369f02f.scope - libcrun container.
Nov 14 06:00:23 secondary.cloud.example.de podman[6020]: 2024-11-14 06:00:23.201436902 +0100 CET m=+0.283461319 container init ed72df696dc7cdb6cf31c1e6264e4cd5cb685076589a5f767e7304342369f02f (image=docker.io/library/caddy:latest, name=>
Nov 14 06:00:23 secondary.cloud.example.de systemd[930]: Started container-01_reverse-proxy_caddy.service - Podman container-01_reverse-proxy_caddy.service.
Nov 14 06:00:23 secondary.cloud.example.de podman[6020]: 2024-11-14 06:00:23.218848186 +0100 CET m=+0.300872617 container start ed72df696dc7cdb6cf31c1e6264e4cd5cb685076589a5f767e7304342369f02f (image=docker.io/library/caddy:latest, name>
Nov 14 06:00:23 secondary.cloud.example.de podman[6020]: ed72df696dc7cdb6cf31c1e6264e4cd5cb685076589a5f767e7304342369f02f
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"info","ts":1731560424.1585462,"msg":"using config from file","file":"/etc/caddy/Caddyfile"}
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"info","ts":1731560424.175008,"msg":"adapted config to JSON","adapter":"caddyfile"}
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"warn","ts":1731560424.1750412,"msg":"Caddyfile input is not formatted; run 'caddy fmt --overwrite' to fix inconsistencies","adapter":"caddyfile","file":">
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"info","ts":1731560424.1778564,"logger":"admin","msg":"admin endpoint started","address":"localhost:2019","enforce_origin":false,"origins":["//localhost:2>
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"info","ts":1731560424.178122,"logger":"http.auto_https","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one >
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"info","ts":1731560424.178141,"logger":"http.auto_https","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"info","ts":1731560424.1787431,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc000453880"}
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"info","ts":1731560424.2028756,"logger":"http","msg":"enabling HTTP/3 listener","addr":":4001"}
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"info","ts":1731560424.2374506,"msg":"failed to sufficiently increase receive buffer size (was: 208 kiB, wanted: 7168 kiB, got: 416 kiB). See https://gith>
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"info","ts":1731560424.2393188,"logger":"http.log","msg":"server running","name":"srv0","protocols":["h1","h2","h3"]}
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"info","ts":1731560424.2394407,"logger":"http.log","msg":"server running","name":"remaining_auto_https_redirects","protocols":["h1","h2","h3"]}
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"info","ts":1731560424.2397304,"logger":"http","msg":"enabling automatic TLS certificate management","domains":["monitoring.secondary.cloud.example.de",">
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"info","ts":1731560424.2511995,"msg":"autosaved config (load with --resume flag)","file":"/config/caddy/autosave.json"}
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"info","ts":1731560424.251232,"msg":"serving initial configuration"}
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"info","ts":1731560424.2619343,"logger":"tls","msg":"storage cleaning happened too recently; skipping for now","storage":"FileStorage:/data/caddy","instan>
Nov 14 06:00:24 secondary.cloud.example.de 01_reverse-proxy_caddy[6031]: {"level":"info","ts":1731560424.2620654,"logger":"tls","msg":"finished cleaning storage units"}
Unfortunately I have no clue how to prevent this behavior in future.
Hi guys,
I'm not sure if this is a bug, but I have completely no clue, what happened here, so I would really appreciate I someone could take a look at it.
I'm running latest
Debian 12
andpodman 4.3.1
. I usedpodman generate systemd --new --files --name
to generate systemd services, because quadlet is not yet available in Debian.Here are the systemd units where the issue appeared:
Here is what happend. On 2 AM
podman auto-update
automatically runs (systemd timer). Restarting the container after updating did not work because of a podman error I don't know where it came from:The rollback did also not change anything. After a couple tries it stopped trying to restart the service.
This is not what I'm wondering about. Maybe the container did not stopped correctly, that can happen I guess. At 5:22 AM I did a reboot. After that, it started correctly. But it was still running the old version, so I did another
podman auto-update
manually:That failed without any error from podman or the application (caddy). Very weird. I tried a couple times, to understand whats going on.
After a 4 tries that gave the exact ouput as above, It just worked. I changed nothing, I just run
podman auto-update
and it worked:Unfortunately I have no clue how to prevent this behavior in future.
Does anyone of you know, what happened here?