<div dir="ltr">Is this with cgroups v1 or v2? If cgroups v1 is involved (thanks Docker), I recall it was a bit complex for systemd to get notified when the cgroup actually empties – via /sys/fs/cgroup/systemd/release_agent that specifies a helper executable that the kernel runs... I wonder if that mechanism is broken on your system. </div> <div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Wed, Oct 11, 2023 at 7:38 AM Martin Schwenke <<a href="mailto:martin@meltin.net">martin@meltin.net</a>> wrote: </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">I'm seeing "systemctl stop <service>" for several services taking a long time because it goes through the timeout process, even though all relevant processes have exited. I'll give 2 examples. Both examples are running inside a privileged Rocky Linux 8.8 Docker container on a Rocky Linux 8.8 host. The systemd version, reported by "systemctl --version" in the container is: systemd 239 (239-74.el8_8.5) Here is ctdb.system: [Unit] Description=CTDB Documentation=man:ctdbd(1) man:ctdb(7) After=network-online.target time-sync.target ConditionFileNotEmpty=/etc/ctdb/nodes [Service] Type=forking LimitCORE=infinity LimitNOFILE=1048576 TasksMax=4096 PIDFile=/var/run/ctdb/ctdbd.pid ExecStart=/usr/sbin/ctdbd ExecStop=/usr/bin/ctdb shutdown KillMode=control-group Restart=no [Install] WantedBy=multi-user.target "/usr/bin/ctdb shutdown" causes a controlled shutdown. In many cases, starting and then stopping using systemctl works fine. However, many times it takes >90s to stop, as per TimeoutStopSec. If I reduce that value then the duration reduces accordingly. I can confirm using both "ps auxfww" and "systemd-cgls" that within the container there are no relevant processes a moment after "systemctl stop ctdb" is run. In particular, in systemd-cgls ctdb.service is gone but "systemctl stop ctdb" is still waiting. Before attempting to stop, the service is successfully started: Oct 11 00:56:44 rocky1 systemd[710741]: ctdb.service: Executing: /usr/sbin/ctdbd Oct 11 00:56:44 rocky1 ctdbd[710741]: CTDB logging to location file:/var/log/log.ctdb Oct 11 00:56:44 rocky1 systemd[1]: Received SIGCHLD from PID 710741 (ctdbd). Oct 11 00:56:44 rocky1 systemd[1]: Child 710741 (ctdbd) died (code=exited, status=0/SUCCESS) Oct 11 00:56:44 rocky1 systemd[1]: ctdb.service: Child 710741 belongs to ctdb.service. Oct 11 00:56:44 rocky1 systemd[1]: ctdb.service: Control process exited, code=exited status=0 Oct 11 00:56:44 rocky1 systemd[1]: ctdb.service: Got final SIGCHLD for state start. Oct 11 00:56:44 rocky1 systemd[1]: ctdb.service: New main PID 710742 belongs to service, we are happy. Oct 11 00:56:44 rocky1 systemd[1]: ctdb.service: Main PID loaded: 710742 Oct 11 00:56:44 rocky1 systemd[1]: ctdb.service: Changed start -> running Oct 11 00:56:44 rocky1 systemd[1]: ctdb.service: Job ctdb.service/start finished, result=done Oct 11 00:56:44 rocky1 systemd[1]: Started CTDB. -- Subject: Unit ctdb.service has finished start-up -- Defined-By: systemd -- Support: <a href="https://lists.freedesktop.org/mailman/listinfo/systemd-devel" rel="noreferrer" target="_blank">https://lists.freedesktop.org/mailman/listinfo/systemd-devel</a> -- -- Unit ctdb.service has finished starting up. -- -- The start-up result is done. The relevant part of the log while stopping seems to be: Oct 11 00:56:47 rocky1 systemd[1]: Received SIGCHLD from PID 710743 (ctdb-eventd). Oct 11 00:56:47 rocky1 systemd[1]: Child 710742 (ctdbd) died (code=exited, status=0/SUCCESS) Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Child 710742 belongs to ctdb.service. Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Can't open PID file /var/run/ctdb/ctdbd.pid (yet?) after stop: No such file or directory Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Main process exited, code=exited, status=0/SUCCESS Oct 11 00:56:47 rocky1 systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/ctdb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=54 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a Oct 11 00:56:47 rocky1 systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/ctdb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=55 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a Oct 11 00:56:47 rocky1 systemd[1]: Child 710743 (ctdb-eventd) died (code=exited, status=0/SUCCESS) Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Child 710743 belongs to ctdb.service. Oct 11 00:56:47 rocky1 systemd[1]: systemd-journald.service: Received EPOLLHUP on stored fd 18 (stored), closing. Oct 11 00:56:47 rocky1 systemd[1]: Received SIGCHLD from PID 710860 (ctdb). Oct 11 00:56:47 rocky1 systemd[1]: Child 710860 (ctdb) died (code=exited, status=0/SUCCESS) Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Child 710860 belongs to ctdb.service. Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Control process exited, code=exited status=0 Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Got final SIGCHLD for state stop. Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Changed stop -> stop-sigterm Oct 11 00:56:47 rocky1 systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/ctdb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=56 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a Oct 11 00:56:47 rocky1 systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1/unit/ctdb_2eservice interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=57 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a Oct 11 00:56:47 rocky1 systemd[1]: Received SIGCHLD from PID 710834 (ctdb_lock_helpe). Oct 11 00:56:47 rocky1 systemd[1]: Child 710834 (ctdb_lock_helpe) died (code=exited, status=0/SUCCESS) Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Child 710834 belongs to ctdb.service. Oct 11 00:56:47 rocky1 systemd[1]: Received SIGCHLD from PID 710835 (ctdb_lock_helpe). Oct 11 00:56:47 rocky1 systemd[1]: Child 710832 (ctdb_lock_helpe) died (code=exited, status=0/SUCCESS) Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Child 710832 belongs to ctdb.service. Oct 11 00:56:47 rocky1 systemd[1]: Child 710835 (ctdb_lock_helpe) died (code=exited, status=0/SUCCESS) Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Child 710835 belongs to ctdb.service. Oct 11 00:56:47 rocky1 systemd[1]: Child 710833 (ctdb_lock_helpe) died (code=exited, status=0/SUCCESS) Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Child 710833 belongs to ctdb.service. Oct 11 00:56:47 rocky1 systemd[1]: Child 710836 (ctdb_lock_helpe) died (code=exited, status=0/SUCCESS) Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Child 710836 belongs to ctdb.service. Oct 11 00:56:47 rocky1 systemd[1]: Child 710837 (ctdb_lock_helpe) died (code=exited, status=0/SUCCESS) Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Child 710837 belongs to ctdb.service. Oct 11 00:56:47 rocky1 systemd[1]: Child 710838 (ctdb_lock_helpe) died (code=exited, status=0/SUCCESS) Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Child 710838 belongs to ctdb.service. Oct 11 00:56:47 rocky1 systemd[1]: Child 710839 (ctdb_lock_helpe) died (code=exited, status=0/SUCCESS) Oct 11 00:56:47 rocky1 systemd[1]: ctdb.service: Child 710839 belongs to ctdb.service. Oct 11 00:56:47 rocky1 systemd[1]: Received SIGCHLD from PID 710832 (n/a). Oct 11 00:57:44 rocky1 systemd[1]: systemd-journald.service: Got notification message from PID 840 (WATCHDOG=1) Oct 11 00:58:17 rocky1 systemd[1]: ctdb.service: State 'stop-sigterm' timed out. Killing. Oct 11 00:58:17 rocky1 systemd[1]: ctdb.service: Failed with result 'timeout'. -- Subject: Unit failed -- Defined-By: systemd -- Support: <a href="https://lists.freedesktop.org/mailman/listinfo/systemd-devel" rel="noreferrer" target="_blank">https://lists.freedesktop.org/mailman/listinfo/systemd-devel</a> -- -- The unit ctdb.service has entered the 'failed' state with result 'timeout'. Oct 11 00:58:17 rocky1 systemd[1]: ctdb.service: Changed stop-sigterm -> failed Oct 11 00:58:17 rocky1 systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=58 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a Oct 11 00:58:17 rocky1 systemd[1]: ctdb.service: Job ctdb.service/stop finished, result=done Oct 11 00:58:17 rocky1 systemd[1]: Stopped CTDB. -- Subject: Unit ctdb.service has finished shutting down -- Defined-By: systemd -- Support: <a href="https://lists.freedesktop.org/mailman/listinfo/systemd-devel" rel="noreferrer" target="_blank">https://lists.freedesktop.org/mailman/listinfo/systemd-devel</a> -- -- Unit ctdb.service has finished shutting down. Oct 11 00:58:17 rocky1 systemd[1]: Sent message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=JobRemoved cookie=59 reply_cookie=0 signature=uoss error-name=n/a error-message=n/a Oct 11 00:58:17 rocky1 systemd[1]: ctdb.service: Unit entered failed state. It would be very useful if systemd could log what it is still waiting for when it times out. Note that during start and stop, CTDB runs a lot of subprocesses, including some that use systemctl to start and stop various services that it, in turn, manages. The full debug level log, after running: systemd-analyze log-level debug is uploaded it to: <a href="https://meltin.net/uploads/systemd/ctdb-stop.log" rel="noreferrer" target="_blank">https://meltin.net/uploads/systemd/ctdb-stop.log</a> I'm happy to reply and attach it, but it is 48KB. The only theory I can come up with is some sort of race where processes are created during shutdown and systemd gets confused. I see a similar thing for a much simpler service, winbind: Here is winbind.service: [Unit] Description=Samba Winbind Daemon Documentation=man:winbindd(8) man:samba(7) man:smb.conf(5) After=network.target nmb.service [Service] Type=notify PIDFile=/var/run/winbindd.pid EnvironmentFile=-/etc/sysconfig/samba ExecStart=/usr/sbin/winbindd --foreground --no-process-group $WINBINDOPTIONS ExecReload=/bin/kill -HUP $MAINPID LimitCORE=infinity [Install] WantedBy=multi-user.target Yesterday I watched it do the same thing as CTDB. I could start the service by hand but it would time out during stop, nearly every time, even though there were no relevant processes running anymore. winbindd sends a READY=1 notification after successfully starting. It does not send STOPPING=1. winbindd is much simpler during shutdown. I can get logs for this one too if necessary. Thanks for any help. peace & happiness, martin </blockquote></div> -- <div dir="ltr" class="gmail_signature"><div dir="ltr">Mantas Mikulėnas</div></div>