Wait for service to gracefully exit before machine shutdown/reboot

How do you write a systemd service that gracefully shuts down upon machine shutdown or reboot? In particular, it should delay machine shutdown until it exits gracefully.

I have a service that takes 10 seconds to shut down: /usr/local/bin/shutdowntest.sh:

#!/bin/bash

SHUTDOWN=0
SHUTDOWN_TIME=10
TRAPPED_SIGNAL=

function onexit() {
  TRAPPED_SIGNAL=$1
  SHUTDOWN=1
}

for SIGNAL in SIGINT SIGTERM SIGHUP SIGPIPE SIGALRM SIGUSR1 SIGUSR2; do
  trap "onexit $SIGNAL" $SIGNAL
done

echo >&2 "shutdowntest running"
while ((!SHUTDOWN || SHUTDOWN_TIME>0)); do
  if [[ -n "$TRAPPED_SIGNAL" ]]; then
    echo >&2 "shutdowntest received signal $TRAPPED_SIGNAL"
    TRAPPED_SIGNAL=
  elif ((SHUTDOWN)); then
    echo >&2 "shutdowntest Shutting down: $SHUTDOWN_TIME more sleeps"
    SHUTDOWN_TIME=$((SHUTDOWN_TIME-1))
    sleep 1
  else
    sleep 10
  fi
done
echo >&2 "shutdowntest Finished shutting down; quitting"

I set TimeoutStopSec to 15s in /etc/systemd/system/shutdowntest.service:

[Service]
ExecStart=/usr/local/bin/shutdowntest.sh
TimeoutStopSec=15

[Install]
WantedBy=multi-user.target

When I run sudo systemctl stop shutdowntest.service, the service shuts down gracefully according to /var/log/syslog:

00:57:11 shutdowntest.sh[1980]: shutdowntest received signal SIGTERM
00:57:11 shutdowntest.sh[1980]: shutdowntest Shutting down: 10 more sleeps
00:57:11 systemd[1]: Stopping shutdowntest.service...
00:57:11 shutdowntest.sh[1980]: Terminated
00:57:11 shutdowntest.sh[1980]: shutdowntest Shutting down: 9 more sleeps
00:57:12 shutdowntest.sh[1980]: shutdowntest Shutting down: 8 more sleeps
00:57:13 shutdowntest.sh[1980]: shutdowntest Shutting down: 7 more sleeps
00:57:14 shutdowntest.sh[1980]: shutdowntest Shutting down: 6 more sleeps
00:57:15 shutdowntest.sh[1980]: shutdowntest Shutting down: 5 more sleeps
00:57:16 shutdowntest.sh[1980]: shutdowntest Shutting down: 4 more sleeps
00:57:17 shutdowntest.sh[1980]: shutdowntest Shutting down: 3 more sleeps
00:57:18 shutdowntest.sh[1980]: shutdowntest Shutting down: 2 more sleeps
00:57:19 shutdowntest.sh[1980]: shutdowntest Shutting down: 1 more sleeps
00:57:20 shutdowntest.sh[1980]: shutdowntest Finished shutting down; quitting
00:57:20 systemd[1]: Stopped shutdowntest.service.

But when I sudo reboot or sudo shutdown now the machine, the service is killed without enough time to exit gracefully, and the /var/log/syslog ends only 1s later.

00:59:30 shutdowntest.sh[2014]: Terminated
00:59:30 shutdowntest.sh[2014]: shutdowntest received signal SIGTERM
00:59:30 shutdowntest.sh[2014]: shutdowntest Shutting down: 10 more sleeps
00:59:30 systemd[1]: Stopping shutdowntest.service...

How to ensure that the service is given the time (TimeoutSec or TimeoutStopSec) to exit when the machine is shutdown or rebooted?

Solution 1:

The comment from Bigon is correct. I was looking in /var/log/syslog, but this is written by rsyslog.service, which systemd stops pretty early in the shutdown process (as indicated by “Stopped System Logging Service” below).

After I enabled persistent journald logging instead (Storage=persistent in /etc/systemd/journald.conf and systemctl restart systemd-journald), journalctl -b-1 -u shutdowntest.service shows that my service is indeed given enough time to shut down after the system is rebooted, shutdown, or after the Power key is pressed (ACPI G2 Soft Off).

journalctl -b-1 -u shutdowntest.service -u rsyslog.service -u systemd-logind
-- Logs begin at Mon 2018-03-26 18:39:12 UTC, end at Mon 2018-03-26 20:22:34 UTC. --
…
Mar 26 18:46:46 myhost systemd-logind[1202]: Power key pressed.
Mar 26 18:46:46 myhost systemd-logind[1202]: Powering Off...
Mar 26 18:46:46 myhost systemd-logind[1202]: System is powering down.
Mar 26 18:46:46 myhost shutdowntest.sh[1237]: Terminated
Mar 26 18:46:46 myhost shutdowntest.sh[1237]: shutdowntest received signal SIGTERM
Mar 26 18:46:46 myhost shutdowntest.sh[1237]: shutdowntest Shutting down: 10 more sleeps
Mar 26 18:46:46 myhost systemd[1]: Stopping shutdowntest.service...
Mar 26 18:46:46 myhost systemd[1]: Stopping Login Service...
Mar 26 18:46:46 myhost systemd[1]: Stopped Login Service.
Mar 26 18:46:46 myhost systemd[1]: Stopping System Logging Service...
Mar 26 18:46:47 myhost systemd[1]: Stopped System Logging Service.
Mar 26 18:46:47 myhost shutdowntest.sh[1237]: shutdowntest Shutting down: 9 more sleeps
Mar 26 18:46:48 myhost shutdowntest.sh[1237]: shutdowntest Shutting down: 8 more sleeps
Mar 26 18:46:49 myhost shutdowntest.sh[1237]: shutdowntest Shutting down: 7 more sleeps
Mar 26 18:46:50 myhost shutdowntest.sh[1237]: shutdowntest Shutting down: 6 more sleeps
Mar 26 18:46:51 myhost shutdowntest.sh[1237]: shutdowntest Shutting down: 5 more sleeps
Mar 26 18:46:52 myhost shutdowntest.sh[1237]: shutdowntest Shutting down: 4 more sleeps
Mar 26 18:46:53 myhost shutdowntest.sh[1237]: shutdowntest Shutting down: 3 more sleeps
Mar 26 18:46:54 myhost shutdowntest.sh[1237]: shutdowntest Shutting down: 2 more sleeps
Mar 26 18:46:55 myhost shutdowntest.sh[1237]: shutdowntest Shutting down: 1 more sleeps
Mar 26 18:46:56 myhost shutdowntest.sh[1237]: shutdowntest Finished shutting down; quitting
Mar 26 18:46:56 myhost systemd[1]: Stopped shutdowntest.service.