systemd does not gracefully shutdown rootless containers on system shutdown/reboot #18699

hadrabap · 2023-05-26T14:20:30Z

hadrabap
May 26, 2023

Hello friends,

After update from Oracle Linux 8.7 to 8.8 all my containers are not shutting down gracefully.

What I have discovered are these strange messages in /var/log/messages:

May 26 15:50:59 sws podman[120601]: time="2023-05-26T15:50:59+02:00" level=warning msg="Failed to add pause process to systemd sandbox cgroup: write unix @: sendmsg: broken pipe"

The number of these messages correlates with the number of my containers.

The behavior happens only when shutdown or reboot is invoked. Regular management like systemctl --user start|stop works as expected.

Is anybody aware of this issue?

I have tried changing the podman's --cgroups option to no-connom—which didn't change anything—and to split as well, which failed completely.
It looks like podman is trying to talk to systemd over D-Bus asynchronously, but the bus is already closed.

Background:

Oracle Linux 8.8 with UEK
Switched to CGroupsv2
regular user with lingering and CGroups delegation enabled
All systemd .service files are generated using a sequence: podman create… and podman generate systemd…
I've also tried to re-generate the .service files.

Version information:

[root@sws opc]# systemctl --version
systemd 239 (239-74.0.1.el8_8)
+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy

[root@sws opc]# podman info
host:
  arch: amd64
  buildahVersion: 1.29.0
  cgroupControllers:
  - cpuset
  - cpu
  - io
  - memory
  - hugetlb
  - pids
  - rdma
  - misc
  cgroupManager: systemd
  cgroupVersion: v2
  conmon:
    package: conmon-2.1.6-1.module+el8.8.0+21045+adcb6a64.x86_64
    path: /usr/bin/conmon
    version: 'conmon version 2.1.6, commit: 31a72124adb6095b6be85b27e3e481313a1cea96'
  cpuUtilization:
    idlePercent: 99.57
    systemPercent: 0.1
    userPercent: 0.32
  cpus: 128
  distribution:
    distribution: '"ol"'
    variant: server
    version: "8.8"
  eventLogger: file
  hostname: sws.swsnet.private-sandbox.net
  idMappings:
    gidmap: null
    uidmap: null
  kernel: 5.15.0-101.103.2.1.el8uek.x86_64
  linkmode: dynamic
  logDriver: k8s-file
  memFree: 511015206912
  memTotal: 539922161664
  networkBackend: cni
  ociRuntime:
    name: runc
    package: runc-1.1.4-1.module+el8.8.0+21045+adcb6a64.x86_64
    path: /usr/bin/runc
    version: |-
      runc version 1.1.4
      spec: 1.0.2-dev
      go: go1.19.4
      libseccomp: 2.5.2
  os: linux
  remoteSocket:
    exists: true
    path: /run/podman/podman.sock
  security:
    apparmorEnabled: false
    capabilities: CAP_SYS_CHROOT,CAP_NET_RAW,CAP_CHOWN,CAP_DAC_OVERRIDE,CAP_FOWNER,CAP_FSETID,CAP_KILL,CAP_NET_BIND_SERVICE,CAP_SETFCAP,CAP_SETGID,CAP_SETPCAP,CAP_SETUID
    rootless: false
    seccompEnabled: true
    seccompProfilePath: /usr/share/containers/seccomp.json
    selinuxEnabled: true
  serviceIsRemote: false
  slirp4netns:
    executable: /bin/slirp4netns
    package: slirp4netns-1.2.0-2.module+el8.8.0+21045+adcb6a64.x86_64
    version: |-
      slirp4netns version 1.2.0
      commit: 656041d45cfca7a4176f6b7eed9e4fe6c11e8383
      libslirp: 4.4.0
      SLIRP_CONFIG_VERSION_MAX: 3
      libseccomp: 2.5.2
  swapFree: 4294963200
  swapTotal: 4294963200
  uptime: 3h 40m 41.00s (Approximately 0.12 days)
plugins:
  authorization: null
  log:
  - k8s-file
  - none
  - passthrough
  - journald
  network:
  - bridge
  - macvlan
  - ipvlan
  volume:
  - local
registries:
  search:
  - container-registry.oracle.com
  - docker.io
store:
  configFile: /etc/containers/storage.conf
  containerStore:
    number: 0
    paused: 0
    running: 0
    stopped: 0
  graphDriverName: overlay
  graphOptions:
    overlay.mountopt: nodev,metacopy=on
  graphRoot: /var/lib/containers/storage
  graphRootAllocated: 75112652800
  graphRootUsed: 40093450240
  graphStatus:
    Backing Filesystem: xfs
    Native Overlay Diff: "false"
    Supports d_type: "true"
    Using metacopy: "true"
  imageCopyTmpDir: /var/tmp
  imageStore:
    number: 0
  runRoot: /run/containers/storage
  transientStore: false
  volumePath: /var/lib/containers/storage/volumes
version:
  APIVersion: 4.4.1
  Built: 1684543580
  BuiltTime: Sat May 20 02:46:20 2023
  GitCommit: ""
  GoVersion: go1.19.6
  Os: linux
  OsArch: linux/amd64
  Version: 4.4.1

Answered by hadrabap

Aug 22, 2023

Soooo, long story short…

Did a lot of digging around and inside and 've found the culprit: podman generated libpod scopes.

When the machine is going down, libpod scopes (there is one for each running container) are triggered for stop. That works fine. The libpod scope invokes podman stop which sends an appropriate signal to the first process of the container, thus triggering the shutdown sequence. However, the libpod scope does not respect any timeouts (the podman generate systemd service – this is expected – nor podman --stop-timeout neither TimeoutStopSec on the libpod scope). Instead it immediately starts firing KILL signals all around effectively breaking graceful shutdown.

To get rid…

View full answer

hadrabap · 2023-05-27T07:47:18Z

hadrabap
May 27, 2023
Author

OK, found this: #17096

It seems the D-Bus User Management Bus is required for podman stop to work. The issue seems to be:

systemd stops container service, which
launches podman stop, which
sends some signal to something else (conmon? runc?)
systemd stops D-Bus User Message Bus
the process notified by step 3 tries to send D-Bus message, which fails as D-Bus User Message Bus is already shutting down (rejecting requests) or shut down already (broken pipe)
as the process in step 5 fails, the container is SIGKILled.

To test the behavior one does not need to reboot the whole machine dealing with persistent journal etc… Stopping and re-starting rootless user is sufficient:

[root@sws opc]# systemctl stop [email protected]

and the logs:

May 27 09:30:20 sws systemd[1]: Stopping User Manager for UID 953...
May 27 09:30:20 sws systemd[78427]: Stopping libcontainer container fc6c01ed2be347f12035da464ab78e91aabf0b0a2691f7b6679b4b9a694ecc88.
May 27 09:30:20 sws systemd[78427]: Stopping D-Bus User Message Bus...
May 27 09:30:20 sws systemd[78427]: Stopping libcontainer container 9b866dce6f498ce356ddf9e1e50671cf8b835468d06cf70b7c5f504171547270.
May 27 09:30:20 sws systemd[78427]: Stopping podman-pause-fa60fa6f.scope.
May 27 09:30:20 sws systemd[78427]: Stopping libcontainer container d4ede8a175e63ed1b25deb38c960397dafc5ba107f4584fc175ef8b8b1413797.
May 27 09:30:20 sws systemd[78427]: Stopping libcontainer container c9bebffc9f67780f5ad2739fc22dc2ee80d721832d41b4fc9441f5588fbe7f26.
May 27 09:30:20 sws systemd[78427]: Stopping libcontainer container 082f8d2b0cc8e2d4017df2d7e3920e2f911a7e009a0e2cfea7b321fed90b20e6.
May 27 09:30:20 sws systemd[78427]: Stopped target Default.
May 27 09:30:20 sws systemd[78427]: Stopping Podman container-gitlab.service...
May 27 09:30:21 sws systemd[78427]: Stopping Podman container-nexus.service...
May 27 09:30:21 sws systemd[78427]: Stopping Podman container-chartmuseum.service...
May 27 09:30:21 sws systemd[78427]: Stopping Podman container-registry.service...
May 27 09:30:21 sws systemd[78427]: Stopping Podman container-davical.service...
May 27 09:30:21 sws systemd[78427]: Stopping Podman container-oradb-21c3.service...
May 27 09:30:21 sws systemd[78427]: Stopping Podman container-step-ca.service...
May 27 09:30:21 sws systemd[78427]: Stopping Podman Start All Containers With Restart Policy Set To Always...
May 27 09:30:21 sws systemd[78427]: Stopping Podman container-synchro.service...
May 27 09:30:21 sws systemd[78427]: Stopped D-Bus User Message Bus.
May 27 09:30:21 sws systemd[78427]: Stopped libcontainer container fc6c01ed2be347f12035da464ab78e91aabf0b0a2691f7b6679b4b9a694ecc88.
May 27 09:30:21 sws systemd[78427]: libpod-fc6c01ed2be347f12035da464ab78e91aabf0b0a2691f7b6679b4b9a694ecc88.scope: Consumed 269ms CPU time
May 27 09:30:21 sws systemd[78427]: Stopped libcontainer container c9bebffc9f67780f5ad2739fc22dc2ee80d721832d41b4fc9441f5588fbe7f26.
May 27 09:30:21 sws systemd[78427]: libpod-c9bebffc9f67780f5ad2739fc22dc2ee80d721832d41b4fc9441f5588fbe7f26.scope: Consumed 111ms CPU time
May 27 09:30:21 sws systemd[78427]: Stopped podman-pause-fa60fa6f.scope.
May 27 09:30:21 sws systemd[78427]: Stopped libcontainer container d4ede8a175e63ed1b25deb38c960397dafc5ba107f4584fc175ef8b8b1413797.
May 27 09:30:21 sws systemd[78427]: libpod-d4ede8a175e63ed1b25deb38c960397dafc5ba107f4584fc175ef8b8b1413797.scope: Consumed 5.279s CPU time
May 27 09:30:21 sws podman[86941]: step-ca
May 27 09:30:21 sws sh[86636]: time="2023-05-27T09:30:21+02:00" level=info msg="/usr/bin/podman filtering at log level info"
May 27 09:30:21 sws sh[86636]: Error: you must provide at least one name or id
May 27 09:30:21 sws systemd[78427]: podman-restart.service: Control process exited, code=exited status=125
May 27 09:30:21 sws systemd[78427]: podman-restart.service: Failed with result 'exit-code'.
May 27 09:30:21 sws systemd[78427]: Stopped Podman Start All Containers With Restart Policy Set To Always.
May 27 09:30:21 sws podman[87113]: step-ca
May 27 09:30:21 sws systemd[78427]: Stopped Podman container-step-ca.service.
May 27 09:30:21 sws podman[86940]: synchro
May 27 09:30:21 sws podman[86939]: chartmuseum
May 27 09:30:21 sws systemd[78427]: container-chartmuseum.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
May 27 09:30:21 sws podman[87182]: synchro
May 27 09:30:21 sws podman[86938]: registry
May 27 09:30:21 sws systemd[78427]: Stopped Podman container-synchro.service.
May 27 09:30:21 sws systemd[78427]: container-registry.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
May 27 09:30:21 sws podman[87203]: chartmuseum
May 27 09:30:21 sws systemd[78427]: container-chartmuseum.service: Failed with result 'exit-code'.
May 27 09:30:21 sws systemd[78427]: Stopped Podman container-chartmuseum.service.
May 27 09:30:21 sws podman[87209]: registry
May 27 09:30:21 sws systemd[78427]: container-registry.service: Failed with result 'exit-code'.
May 27 09:30:21 sws systemd[78427]: Stopped Podman container-registry.service.
May 27 09:30:22 sws podman[86881]: davical
May 27 09:30:22 sws podman[87280]: davical
May 27 09:30:22 sws systemd[78427]: Stopped Podman container-davical.service.
May 27 09:30:25 sws systemd[78427]: Stopped libcontainer container 082f8d2b0cc8e2d4017df2d7e3920e2f911a7e009a0e2cfea7b321fed90b20e6.
May 27 09:30:25 sws systemd[78427]: libpod-082f8d2b0cc8e2d4017df2d7e3920e2f911a7e009a0e2cfea7b321fed90b20e6.scope: Consumed 41.067s CPU time
May 27 09:30:25 sws systemd[78427]: Stopped /usr/bin/podman healthcheck run 082f8d2b0cc8e2d4017df2d7e3920e2f911a7e009a0e2cfea7b321fed90b20e6.
May 27 09:30:25 sws podman[87090]: oradb-21c3
May 27 09:30:25 sws systemd[78427]: container-oradb-21c3.service: Main process exited, code=exited, status=143/n/a
May 27 09:30:25 sws podman[87352]: oradb-21c3
May 27 09:30:25 sws systemd[78427]: container-oradb-21c3.service: Failed with result 'exit-code'.
May 27 09:30:25 sws systemd[78427]: Stopped Podman container-oradb-21c3.service.
May 27 09:30:27 sws podman[86937]: nexus
May 27 09:30:27 sws podman[87406]: nexus
May 27 09:30:27 sws systemd[78427]: Stopped Podman container-nexus.service.
May 27 09:30:31 sws systemd[78427]: Stopped libcontainer container 9b866dce6f498ce356ddf9e1e50671cf8b835468d06cf70b7c5f504171547270.
May 27 09:30:31 sws systemd[78427]: libpod-9b866dce6f498ce356ddf9e1e50671cf8b835468d06cf70b7c5f504171547270.scope: Consumed 2min 4.206s CPU time
May 27 09:30:31 sws systemd[78427]: Removed slice user.slice.
May 27 09:30:31 sws systemd[78427]: Stopped /usr/bin/podman healthcheck run 9b866dce6f498ce356ddf9e1e50671cf8b835468d06cf70b7c5f504171547270.
May 27 09:30:32 sws podman[86849]: gitlab
May 27 09:30:32 sws systemd[78427]: container-gitlab.service: Main process exited, code=exited, status=9/n/a
May 27 09:30:32 sws podman[87507]: gitlab
May 27 09:30:32 sws podman[87484]: time="2023-05-27T09:30:32+02:00" level=warning msg="Failed to add pause process to systemd sandbox cgroup: write unix @: sendmsg: broken pipe"
May 27 09:30:32 sws systemd[78427]: container-gitlab.service: Failed with result 'exit-code'.
May 27 09:30:32 sws systemd[78427]: Stopped Podman container-gitlab.service.
May 27 09:30:32 sws systemd[78427]: Stopped target Basic System.
May 27 09:30:32 sws systemd[78427]: Stopped target Sockets.
May 27 09:30:32 sws systemd[78427]: Closed REST API socket for snapd user session agent.
May 27 09:30:32 sws systemd[78427]: Closed Sound System.
May 27 09:30:32 sws systemd[78427]: Closed D-Bus User Message Bus Socket.
May 27 09:30:32 sws systemd[78427]: Closed Multimedia System.
May 27 09:30:32 sws systemd[78427]: Closed Podman API Socket.
May 27 09:30:32 sws systemd[78427]: Stopped target Paths.
May 27 09:30:32 sws systemd[78427]: Stopped target Timers.
May 27 09:30:32 sws systemd[78427]: Stopped Timer for Services renewal service..
May 27 09:30:32 sws systemd[78427]: Reached target Shutdown.
May 27 09:30:32 sws systemd[78427]: Started Exit the Session.
May 27 09:30:32 sws systemd[78427]: Reached target Exit the Session.
May 27 09:30:32 sws systemd[1]: [email protected]: Succeeded.
May 27 09:30:32 sws systemd[1]: Stopped User Manager for UID 953.
May 27 09:30:32 sws systemd[1]: Stopping User runtime directory /run/user/953...
May 27 09:30:32 sws systemd[1]: run-user-953.mount: Succeeded.
May 27 09:30:32 sws systemd[1]: [email protected]: Succeeded.
May 27 09:30:32 sws systemd[1]: Stopped User runtime directory /run/user/953.
May 27 09:30:32 sws systemd[1]: Removed slice User Slice of UID 953.
May 27 09:30:32 sws systemd[1]: user-953.slice: Consumed 6min 57.296s CPU time, received 557.2K IP traffic, sent 544.9K IP traffic

As shown, the shutdown process takes less than a second. The proper shutdown of all the containers takes at least 3 minutes!

I really don't know what's going on. Everything has been working until RHEL 8.8 (Oracle Linux 8.8 in my case) arrived. That release upgraded podman as well as systemd.

But anyway, I need to find out a solution as this can easily lead to data loss.

Is there any way to tell podman to NOT use D-Bus?

0 replies

hadrabap · 2023-05-29T08:21:30Z

hadrabap
May 29, 2023
Author

OKi, next iteration.

As the log tells, systemd initiates the D-Bus User Message Bus shutdown procedure which effectively disables acceptance of new requests. When I put override.conf into ~/.config/systemd/user/dbus.service.d/

[Service]
ExecStop=/usr/bin/true

all the Failed to add pause process to systemd sandbox cgroup: write unix @: sendmsg: broken pipe go away.

0 replies

hadrabap · 2023-08-22T12:33:29Z

hadrabap
Aug 22, 2023
Author

Soooo, long story short…

Did a lot of digging around and inside and 've found the culprit: podman generated libpod scopes.

When the machine is going down, libpod scopes (there is one for each running container) are triggered for stop. That works fine. The libpod scope invokes podman stop which sends an appropriate signal to the first process of the container, thus triggering the shutdown sequence. However, the libpod scope does not respect any timeouts (the podman generate systemd service – this is expected – nor podman --stop-timeout neither TimeoutStopSec on the libpod scope). Instead it immediately starts firing KILL signals all around effectively breaking graceful shutdown.

To get rid of this, the KillMode=none property in the libpod scope must be introduced. When that's done, the generated scope invokes podman stop and that's all. Podman does the rest (including sending KILLs to container's processes when stop timeout is reached).

Luckily enough podman has the --annotation option. To propagate the KillMode to libpod scope one needs to include the "--annotation=org.systemd.property.KillMode='none'" parameter.

Full example:

podman create --name xxx                                            \
	--memory-swap 0b                                            \
	--memory 2g                                                 \
	--pids-limit 4000                                           \
	--cpus 2                                                    \
	--stop-timeout=420                                          \
	--cgroup-parent=podman-containers.slice                     \
	--annotation=org.systemd.property.TimeoutStopSec=420        \
	"--annotation=org.systemd.property.KillMode='none'"         \
	-p 127.0.0.1:9999:80                                        \
	-p 10.228.200.1:9999:80                                     \
	-p 10.228.201.1:9999:80                                     \
	-v /xxx/home:/home:z                                        \
	registry:5000/xxx:xxx

pushd ~/.config/systemd/user
podman generate systemd --files         \
	--after=podman-containers.slice \
	--wants=podman-containers.slice \
	--name xxx
popd

systemctl --user daemon-reload
systemctl --user enable container-xxx
systemctl --user start container-xxx

Please note the --annotation=org.systemd.property.TimeoutStopSec=420 can be omitted; it seems it is unfortunately ignored by systemd.

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

systemd does not gracefully shutdown rootless containers on system shutdown/reboot #18699

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Replies: 3 comments

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{editor}}'s edit

{{editor}}'s edit

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

systemd does not gracefully shutdown rootless containers on system shutdown/reboot #18699

Uh oh!

Uh oh!

hadrabap May 26, 2023

Replies: 3 comments

Uh oh!

Uh oh!

hadrabap May 27, 2023 Author

Uh oh!

hadrabap May 29, 2023 Author

Uh oh!

hadrabap Aug 22, 2023 Author

hadrabap
May 26, 2023

hadrabap
May 27, 2023
Author

hadrabap
May 29, 2023
Author

hadrabap
Aug 22, 2023
Author