Unattended upgrades maybe very slow and time out on shutdown

Bug #1843099 reported by Zahid Bukhari
14
This bug affects 2 people
Affects Status Importance Assigned to Milestone
unattended-upgrades (Ubuntu)
Invalid
Undecided
Unassigned

Bug Description

1) The release of Ubuntu you are using, via 'lsb_release -rd' or System -> About Ubuntu
 * Ubuntu Xenial 16.04.6 LTS
2) The version of the package you are using, via 'apt-cache policy pkgname' or by checking in Software Center
 * 1.1ubuntu1.18.04.7~16.04.3
3) What you expected to happen
 * Packages to be upgraded on reboot / shutdown.
4) What happened instead
 * The host just rebooted. Didn't perform upgrades. No useful output either until I enabled debug logging in the systemd unit file.

I'm reporting a new bug but this is very similar to #1806487 and I'm actually wondering if it resurfaced somehow.

We're running Ubuntu Xenial 16.04.6 which has 1.1ubuntu1.18.04.7~16.04.3 installed.

I see that #1806487 was resolved with 1.1ubuntu1.18.04.7~16.04.2. However I'm seeing similar behavior.

So far I've modified systemd to see if anything stands out. I do have an strace and then just debug mode.

Unless needed, simply put, this is what a reboot with debug logging looks like (i.e. unattended-upgrades-shutdown.log):

2019-09-06 09:20:04,871 DEBUG - Waiting for signal to start operation
2019-09-06 09:20:43,996 WARNING - SIGTERM or SIGHUP received, stopping unattended-upgradesonly if it is running
2019-09-06 09:20:43,996 DEBUG - Starting countdown of 25.0 minutes
2019-09-06 09:20:43,997 DEBUG - get_lock returned 7
2019-09-06 09:20:43,997 DEBUG - lock not taken

I hope that helps, please let me know if you need anything else from me or if I can provide any more information.

I've done this many times before, this is the first time it hasn't worked. When I patched around the end of May, all went well. My other variants worked, well mainly Trusty but that's EOL for public access. Bionic doesn't seem to have anything it needs to update.

Revision history for this message
Zahid Bukhari (cimmerian) wrote :

I did want to suggest, before (i.e. Bug #1806487) it seemed to be a race / ordering issue, could a possible fix just be adjusting the systemd unit files after or before bits?

Although even after restarting while the system was up, a reboot didn't work so not sure it's that simple.

Revision history for this message
Zahid Bukhari (cimmerian) wrote :

Hello,

I looked deeper into this, I feel the issue may be with apt_pkg.get_lock's return value now. It seems the code considers 0 success whereas now an FD is returned which seems to mean it's fine.

# Example logging output
2019-09-06 10:54:31,249 WARNING - SIGTERM or SIGHUP received, stopping unattended-upgradesonly if it is running
2019-09-06 10:54:31,250 DEBUG - Starting countdown of 25.0 minutes
2019-09-06 10:54:31,250 DEBUG - get_lock returned 7
2019-09-06 10:54:31,250 DEBUG - lock not taken

# Tracing manually
/usr/share/unattended-upgrades/unattended-upgrade-shutdown:
L230> 2019-09-06 10:54:31,249 WARNING - SIGTERM or SIGHUP received, stopping unattended-upgradesonly if it is running
  * Bug - add space to end (i.e. "SIGTERM or SIGHUP received, stopping unattended-upgrades ")
L318> 2019-09-06 10:54:31,250 DEBUG - Starting countdown of 25.0 minutes
L333> 2019-09-06 10:54:31,250 DEBUG - get_lock returned 7
  * Bug - The lock should be acquired so it should be 0 ... according to code but docs say it's fine
  L332> res = apt_pkg.get_lock(self.options.lock_file)
  L333> logging.debug("get_lock returned %i" % res) # <-- This is where I believe there's the bug
  L334> # exit here if there is no lock
  L335> if res > 0:
  L336> logging.debug("lock not taken")
  L337> if self.lock_was_taken:
  L338> exit_log_result(self.signal_sent)
  L339> else:
  L340> sys.exit(0)
  L341> self.lock_was_taken = True
  L342> signal_stop_unattended_upgrade()
  L343> self.signal_sent = True
  L344> # show log
  L345> log_progress()
  L346> return True

  * Looking deeper into get_lock it shows that a file descriptor is returned
    vs -1 or an error raised. I believe the code may need to be updated as
    running python3 interactively, importing apt_pkg and printing its
    __doc__ shows the following. This is Sparta err python 3... so perhaps
    that's the reason.

>>> print(apt_pkg.get_lock.__doc__)
get_lock(file: str, errors: bool) -> int

Create an empty file of the given name and lock it. If the locking
succeeds, return the file descriptor of the lock file. Afterwards,
locking the file from another process will fail and thus cause
get_lock() to return -1 or raise an Error (if 'errors' is True).

From Python 2.6 on, it is recommended to use the context manager
provided by apt_pkg.FileLock instead using the with-statement.

Revision history for this message
Zahid Bukhari (cimmerian) wrote :

I'd submit a patch but I don't know which way we want to go with this and ya'll are official devs. Update code to handle returned FD or just check to see if it's not -1 or update to use apt_pkg.FileLock? Not Sure, either way - enjoy!

Revision history for this message
Balint Reczey (rbalint) wrote :

How do you shutdown the systemd?

Do you start it from the desktop or via CLI?
If via CLI do you use this command?:
dbus-send --system --print-reply --dest=org.freedesktop.login1 /org/freedesktop/login1 org.freedesktop.login1.Manager.PowerOff boolean:false

Changed in unattended-upgrades (Ubuntu):
status: New → Incomplete
Revision history for this message
Balint Reczey (rbalint) wrote :

... or this one for reboot?:
sudo dbus-send --system --print-reply --dest=org.freedesktop.login1 /org/freedesktop/login1 org.freedesktop.login1.Manager.Reboot boolean:false

Revision history for this message
Zahid Bukhari (cimmerian) wrote :

These are all VMWare VM servers but the few physicals we have ran into the same issue.

We just use /sbin/shutdown or /sbin/reboot.

Revision history for this message
Zahid Bukhari (cimmerian) wrote :

Err, basically I meant to say we do it from the command line but we just use shutdown or reboot.

Revision history for this message
Balint Reczey (rbalint) wrote :

@cimmerian Could you please try using the commands I listed instead?
You probably hit https://github.com/systemd/systemd/issues/949

Revision history for this message
Zahid Bukhari (cimmerian) wrote :

I'll give it a shot and report back. However the code in u-s-s is checking against a FD as if it's an errval or retval and so if it's >0, it bails when it's a legit FD.

Either way - I'll try to do this tomorrow and report back.

Revision history for this message
Zahid Bukhari (cimmerian) wrote :
Download full text (7.3 KiB)

It went further but still failed to update - here it is via the dbus shutdown command you supplied:

### unattended-upgrades.log:
2019-09-13 14:09:43,981 INFO Initial blacklisted packages:
2019-09-13 14:09:43,982 INFO Initial whitelisted packages:
2019-09-13 14:09:43,982 INFO Starting unattended upgrades script
2019-09-13 14:09:43,983 INFO Allowed origins are: o=Ubuntu-aptly,a=xenial
2019-09-13 14:10:01,496 INFO Packages that will be upgraded: apport apt-transport-https base-files bash bind9-host bsdutils btrfs-tools busybox-initramfs busybox-static bzip2 ca-certificates cloud-guest-utils cloud-initramfs-copymods cloud-initramfs-dyn-netconf console-setup console-setup-linux curl dbus dh-python distro-info-data dns-root-data dnsmasq-base dnsutils dpkg file friendly-recovery gettext-base git git-man gnupg gpgv grub-common grub-legacy-ec2 grub-pc grub-pc-bin grub2-common hdparm ifupdown initramfs-tools initramfs-tools-bin initramfs-tools-core iproute2 isc-dhcp-client isc-dhcp-common keyboard-configuration kmod krb5-locales libapparmor-perl libapparmor1 libasprintf0v5 libbind9-140 libblkid1 libbz2-1.0 libc-bin libcurl3-gnutls libdb5.3 libdbus-1-3 libdns-export162 libdns162 libelf1 libexpat1 libfdisk1 libgcrypt20 libglib2.0-0 libglib2.0-data libgnutls-openssl27 libgnutls30 libicu55 libisc-export160 libisc160 libisccc140 libisccfg140 libk5crypto3 libkmod2 libldap-2.4-2 liblwres141 libmagic1 libmount1 libmspack0 libpam-modules libpam-modules-bin libpam-runtime libpam-systemd libpam0g libpci3 libperl5.22 libplymouth4 libpng12-0 libpolkit-agent-1-0 libpolkit-backend-1-0 libpolkit-gobject-1-0 libprocps4 libpython3.5 libpython3.5-minimal libpython3.5-stdlib libsasl2-2 libsasl2-modules libsasl2-modules-db libseccomp2 libslang2 libsmartcols1 libsqlite3-0 libssl1.0.0 libsystemd0 libudev1 libuuid1 libx11-6 libx11-data libxml2 libxslt1.1 linux-firmware linux-headers-generic locales login lshw mount multiarch-support ntfs-3g open-iscsi open-vm-tools openssh-client openssh-server openssh-sftp-server openssl overlayroot passwd patch pciutils perl perl-base perl-modules-5.22 plymouth plymouth-theme-ubuntu-text policykit-1 procps python-apt-common python-lxml python3-apport python3-apt python3-distupgrade python3-problem-report python3-requests python3-software-properties python3-update-manager python3-urllib3 python3.5 python3.5-minimal resolvconf rsyslog shared-mime-info software-properties-common sosreport squashfs-tools sudo systemd systemd-sysv tzdata ubuntu-minimal ubuntu-release-upgrader-core ubuntu-server ubuntu-standard udev uidmap update-manager-core update-notifier-common ureadahead util-linux uuid-runtime vim vim-common vim-runtime vim-tiny vlan wget wireless-regdb xdg-user-dirs
2019-09-13 14:10:01,497 INFO Writing dpkg log to /var/log/unattended-upgrades/unattended-upgrades-dpkg.log
2019-09-13 14:10:13,935 WARNING SIGTERM received, will stop
2019-09-13 14:10:16,810 WARNING SIGTERM received, will stop
2019-09-13 14:10:19,803 WARNING SIGTERM received, will stop
2019-09-13 14:10:22,772 WARNING SIGTERM received, will stop
2019-09-13 14:10:22,779 WARNING SIGTERM received, will stop
2019-09-13 14:10:25,764 WARNING SIGTERM received, will stop
2019-09-13 14:...

Read more...

Revision history for this message
Zahid Bukhari (cimmerian) wrote :

Using reboot did more of the same. At this point the Xenial version is 16.04.4 - we have a snapshot from 2019-05-28. unattended-upgrades was at 0.90ubuntu0.9 but salt config management upgrades to 1.1ubuntu1.18.04.7~16.04.3 once the machine has salt installed. We pretty much update a symlink which has two publish dates, 2019-05-28 (old) to 2019-09-04 (new). I'm not sure if that's playing a role but I do know 0.90ubuntu0.9 worked for me last time.

# As root
dbus-send --system --print-reply \
  --dest=org.freedesktop.login1 /org/freedesktop/login1 \
  org.freedesktop.login1.Manager.PowerOff boolean:false

dbus-send --system --print-reply \
  --dest=org.freedesktop.login1 /org/freedesktop/login1 \
  org.freedesktop.login1.Manager.Reboot boolean:false

Balint Reczey (rbalint)
Changed in unattended-upgrades (Ubuntu):
status: Incomplete → Confirmed
Revision history for this message
Balint Reczey (rbalint) wrote :

In #10 the log shows that unattended-upgrades is asked to stop after 30 seconds and this is expected with the default configuration, when the configuration is changed only to enable InstallOnShutdown.

Please note that the behaviour of unattended-upgrades changed as described in the NEWS file.

$ zless /usr/share/doc/unattended-upgrades/NEWS.Debian.gz

unattended-upgrades (1.1ubuntu1.18.04.7~16.04.0) xenial; urgency=medium

  When InstallOnShutdown was configured unattended-upgrades in
  versions before 1.1ubuntu1.18.04.7~16.04.0 installed updates _after_ the
  shutdown transaction is started by systemd making maintainer scripts
  restarting services fail or wait in a deadlock until being killed by
  shutdown's timeout leaving a broken installation behind.

  Starting with version 1.1ubuntu1.18.04.7~16.04.0 configuring
  InstallOnShutdown makes unattended-upgrades start package installations
  _before_ the shutdown transaction is started, when PrepareForShutdown()
  signal is received via DBus.

  Unattended-upgrades 1.1ubuntu1.18.04.7~16.04.0 also increases logind's
  InhibitDelayMaxSec to 30 seconds. This allows more time for
  unattended-upgrades to shut down gracefully or even install a few
  packages in InstallOnShutdown mode, but is still a big step back from
  the 30 minutes allowed for InstallOnShutdown previously.

  Users enabling InstallOnShutdown mode are advised to increase
  InhibitDelayMaxSec even further, possibly to 30 minutes.

In newer versions the configuration file also points this out, but the configuration file comment change was not SRU-d to avoid conflicts with locally changed configuration files:
...
// Install all updates when the machine is shutting down
// instead of doing it in the background while the machine is running.
// This will (obviously) make shutdown slower.
// Unattended-upgrades increases logind's InhibitDelayMaxSec to 30s.
// This allows more time for unattended-upgrades to shut down gracefully
// or even install a few packages in InstallOnShutdown mode, but is still a
// big step back from the 30 minutes allowed for InstallOnShutdown previously.
// Users enabling InstallOnShutdown mode are advised to increase
// InhibitDelayMaxSec even further,q possibly to 30 minutes.
//Unattended-Upgrade::InstallOnShutdown "false
...

The problem on the system is that even preprocessing the available updates takes longer than 30 seconds, thus none of the updates can be applied. Speeding up the preprocessing part is ongoing, but it will still be recommended to bump logind's timeout.

Changed in unattended-upgrades (Ubuntu):
status: Confirmed → Invalid
Balint Reczey (rbalint)
Changed in unattended-upgrades (Ubuntu):
status: Invalid → In Progress
Revision history for this message
Balint Reczey (rbalint) wrote :

The following fix should speed up u-u where originally it tried to adjust a lot of packages:
https://github.com/mvo5/unattended-upgrades/pull/231

Revision history for this message
Zahid Bukhari (cimmerian) wrote :

Thank you! I should've responded but your earlier explanation did make sense so I was thinking of just adjusting the value you mentioned and didn't respond.

Still I believe the fix will be useful to many. Essentially we do quarterly patching, unless there's an urgent security need, so there often are a lot of packages to update.

This is in a corporate environment.

Balint Reczey (rbalint)
summary: - Unattended upgrades does not work on shutdown
+ Unattended upgrades maybe very slow and time out on shutdown
Revision history for this message
Balint Reczey (rbalint) wrote :

I created a separate bug (LP: #1848357) for the specific fix landing in the PR in #13, because the majority of this problem reported here will still be present.

The full fix is being prepared here:
https://github.com/rbalint/unattended-upgrades/tree/apply-pinning

Balint Reczey (rbalint)
Changed in unattended-upgrades (Ubuntu):
status: In Progress → Invalid
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.