Hi!

There are several systems where I get

    Date: Tue, 15 Jun 2021 06:00:17 +0200
    From: Cron Daemon
    Subject: Cron <root@dom> test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily )

    /etc/cron.daily/logrotate:
    invoke-rc.d: -----------------------------------------------------
    invoke-rc.d: WARNING: 'invoke-rc.d rsyslog rotate' called
    invoke-rc.d: during shutdown sequence.
    invoke-rc.d: enabling safe mode: initscript policy layer disabled
    invoke-rc.d: -----------------------------------------------------

whenever unattended-upgrades needs to reboot. *Before* the
reboot the system looks like this:

    root       835  0.0  0.0   8504  2336 ?        Ss   Jun15   0:00 /usr/sbin/cron
    root     12595  0.0  0.0   9120  2316 ?        S    06:25   0:00  \_ /usr/sbin/CRON
    root     12596  0.0  0.0   2388   700 ?        Ss   06:25   0:00      \_ /bin/sh -c test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily )
    root     12597  0.0  0.0   2284   688 ?        S    06:25   0:00          \_ run-parts --report /etc/cron.daily
    root     12598  0.0  0.0   2388   764 ?        S    06:25   0:00              \_ /bin/sh /usr/lib/apt/apt.systemd.daily
    root     12733  0.0  0.0   2388  1488 ?        S    06:41   0:00                  \_ /bin/sh /usr/lib/apt/apt.systemd.daily lock_is_held
    root     13047  0.0  0.2 123308 34548 ?        Sl   06:41   0:00                      \_ /usr/bin/python3 /usr/bin/unattended-upgrade
    root     13057  0.0  0.0   2372  1752 ?        S    06:41   0:00                          \_ /sbin/shutdown -r 06:00

In human language: this morning at 06:25 cron.daily ran,
which triggered unattended-upgrades, which triggered
`/sbin/shutdown -r 06:00`.

Now one problem here is that `/sbin/shutdown -r 06:00` is
actually blocking. It will *not* exit, but instead will
count waiting time to zero and reboot after.

We are on a system with `sysv-rc` and not `systemd`. I have
*not* verified whether `shutdown -r $TIME` behavior is
identical on a `systemd` system.

The system apparently shut down at:

    # cat /var/log/messages
    Jun 15 06:00:14 dom shutdown[13634]: shutting down for system reboot

also

    # cat /var/log/daemon.log
    Jun 15 06:00:15 dom init: Switching to runlevel: 6

also

    # last -F
    reboot   system boot  4.19.0-16-amd64  Tue Jun 15 06:00:28 2021 - Wed Jun 16 10:34:57 2021 (1+04:34)

So my interpretation is this:

1. cron.daily runs
2. it executes unattended-upgrade
3. unattended-upgrade blocks when it calls shutdown -r 06:00
4. in our case that stops the other cron.daily tasks that are
   sorted after /etc/cron.daily/apt-compat (that is pretty
   much all others since apt-compat is first in the alphabet)
   from running
5. the clock hits 06:00:00 and shutdown exits (this is my
   guess - I think it's the same behavior as with
   `shutdown -r now` which also exits and so you sometimes
   see/get back to the prompt before the sytstem *actually*
   warm reboots)
6. after `shutdown -r 06:00` exits unattended-upgrade
   finishes whatever it was doing, exits and cron.daily continues
   with the execution with the other scripts in /etc/cron.daily/
   that alphabetically follow apt-compat, which makes a
   mess, because we're actually in runlevel 6/shutdown
   now. which triggers the warning we saw above from
   logrotate/cron.

Now what would a "correct" or "better" behavior be?

I suggest to trigger an asynchronous shutdown, that is *not*
to wait for `shutdown -r $TIME` to come back so that whatever
daily menial taks are scheduled via /etc/cron.daily are able
to be executed.

In other words: fork & exec shutdown...

?

Thanks a lot for maintaining unattended-upgrades!!!! Greetings,
*t

With respect to "unattended-upgrades blocking other cron.daily scripts via
shutdown -r" I reflected:

What about the idea of using

     echo "shutdown -r now" | at $TIME

instead of directly calling

     shutdown -r now

Pro:

* async execution. unattended-update can finish it's stuff and
   the rest of cron.daily finishes correctly
* consoles won't be flooded with repeat "Systeme will be going
   doing in XX hours"

Con:

* does care have to be taken that unattended-upgrade won't re-run
   while it wants the system to reboot?
* behavior change (this should be triggering a major semver change...)
   * this could be worked around with yet another config option
     (UseAtInstead=True)
* users on the system won't be warned of the system going down in
   XX hours

What do you think?
*t

The idea in code:

--- /usr/bin/unattended-upgrade.orig    2021-06-18 09:46:37.434386824 
+0200
+++ /usr/bin/unattended-upgrade 2021-06-18 09:47:03.958639111 +0200
@@ -1353,11 +1353,12 @@
      when = apt_pkg.config.find(
          "Unattended-Upgrade::Automatic-Reboot-Time", "now")
      logging.warning("Found %s, rebooting" % REBOOT_REQUIRED_FILE)
-    cmd = ["/sbin/shutdown", "-r", when]
+    cmd = ["/usr/bin/at", when]
      try:
-        shutdown_msg = subprocess.check_output(cmd, stderr=subprocess.STDOUT)
-        if shutdown_msg.strip():
-            logging.warning("Shutdown msg: %s", shutdown_msg.strip())
+        p = subprocess.Popen(cmd, stdin=subprocess.PIPE, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
+        p_out = p.communicate(input=b'shutdown -h now\n')[0].decode('utf-8').strip()
+        if p_out:
+            logging.warning("Shutdown msg: %s", p_out)
      except Exception as e:
          logging.error("Failed to issue shutdown: %s", e)

Feedback about whether this is a good idea is appreciated.

Thanks & greetings,
*t

Argh, that should of course be:

--- /usr/bin/unattended-upgrade.orig    2021-06-18 09:46:37.434386824 +0200
+++ /usr/bin/unattended-upgrade 2021-06-18 09:47:03.958639111 +0200
@@ -1353,11 +1353,12 @@
     when = apt_pkg.config.find(
         "Unattended-Upgrade::Automatic-Reboot-Time", "now")
     logging.warning("Found %s, rebooting" % REBOOT_REQUIRED_FILE)
-    cmd = ["/sbin/shutdown", "-r", when]
+    cmd = ["/usr/bin/at", when]
     try:
-        shutdown_msg = subprocess.check_output(cmd, stderr=subprocess.STDOUT)
-        if shutdown_msg.strip():
-            logging.warning("Shutdown msg: %s", shutdown_msg.strip())
+        p = subprocess.Popen(cmd, stdin=subprocess.PIPE, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
+        p_out = p.communicate(input=b'shutdown -r now\n')[0].decode('utf-8').strip()
+        if p_out:
+            logging.warning("Shutdown msg: %s", p_out)
     except Exception as e:
         logging.error("Failed to issue shutdown: %s", e)

(s/shutdown -h/shutdown -r/)

As always: feedback appreciated

Thanks & greetings,
*t