Bug #1739107 fix causes linux-cloud-tools-common not to be upgradable with unattended-upgrades on shutdown mode

[Guillaume Penin]

Since the following linux-cloud-tools-common package versions :

Xenial : 4.4.0-135.161
Bionic : 4.15.0-34.37

the Systemd service unit file for hv-kvp-daemon has been modified with new dependencies that make the package unable to be upgraded with unattended-upgrades on shutdown mode.
Unattended-upgrades hangs with the linux-cloud-tools-common package during "Preparing to unpack". The server restarts after the unattended-upgrades service timeout expires.

- Package state after reboot :

iFR linux-cloud-tools-common 4.15.0-34.37 all Linux kernel version specific cloud tools for version 4.15.0

- Unattended-upgrades dpkg logs :

Log started: 2018-10-05 17:59:04
(Reading database ... 52043 files and directories currently installed.)
Preparing to unpack .../linux-cloud-tools-common_4.15.0-36.39_all.deb ...
Log ended: 2018-10-05 18:00:54

- Impact :

The current impact is very important as all security updates are blocked until you manually fix each server with :

dpkg --configure -a
apt install --only-upgrade linux-cloud-tools-common

- Workaround/Fix :

As a simple straightforward fix, replacing :

Before=shutdown.target cloud-init-local.service walinuxagent.service

with :

Before=shutdown.target walinuxagent.service

makes the package upgradable during shutdown.

[Ubuntu Kernel Bot (ubuntu-kernel-bot)]

This bug is missing log files that will aid in diagnosing the problem. While running an Ubuntu kernel (not a mainline or third-party kernel) please enter the following command in a terminal window:

apport-collect 1796376

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

[Guillaume Penin (guillaume-penin)]

Sorry, i'm not able to run apport through our enterprise Network.

[David Coronel (davecore)]

Hi Guillaume, would it be possible to provide step-by-step instructions to reproduce this issue?

[Eric Desrochers (slashd)]

Do you have the full logs of "/var/log/unattended-upgrades" and "/var/log/apt" handy ?

- Eric

[Guillaume Penin (guillaume-penin)]

@David, of course :

- Start from an up-to-date Ubuntu Bionic :

[root@uzimysut01 ~]# lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 18.04.1 LTS
Release: 18.04
Codename: bionic

- Downgrade linux-cloud-tools-common to version 4.15.0-34.37 :

[root@uzimysut01 ~]# apt install linux-cloud-tools-common=4.15.0-34.37
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following packages will be DOWNGRADED:
  linux-cloud-tools-common
0 upgraded, 0 newly installed, 1 downgraded, 0 to remove and 0 not upgraded.
Need to get 58.3 kB of archives.
After this operation, 7,168 B disk space will be freed.
Do you want to continue? [Y/n]
Get:1 https://repos.it.sncf.fr/ubuntu-security bionic-security/main amd64 linux-cloud-tools-common all 4.15.0-34.37 [58.3 kB]
Fetched 58.3 kB in 0s (268 kB/s)
dpkg: warning: downgrading linux-cloud-tools-common from 4.15.0-36.39 to 4.15.0-34.37
(Reading database ... 37537 files and directories currently installed.)
Preparing to unpack .../linux-cloud-tools-common_4.15.0-34.37_all.deb ...
Unpacking linux-cloud-tools-common (4.15.0-34.37) over (4.15.0-36.39) ...
Setting up linux-cloud-tools-common (4.15.0-34.37) ...
Processing triggers for ureadahead (0.100.0-20) ...
Processing triggers for man-db (2.8.3-2) ...

- Install unattended-upgrades :

[root@uzimysut01 ~]# apt install unattended-upgrades

- Ensure unattended-upgrades is active, and that it works in "shutdown mode" :

[root@uzimysut01 ~]# grep Unattended-Upgrade /etc/apt/apt.conf.d/20auto-upgrades
APT::Periodic::Unattended-Upgrade "1";

[root@uzimysut01 ~]# grep InstallOnShutdown /etc/apt/apt.conf.d/50unattended-upgrades
Unattended-Upgrade::InstallOnShutdown "true";

- [optional] If you do not want to wait 30 minutes, modify the TimeoutStopSec :

[root@uzimysut01 ~]# systemctl edit unattended-upgrades

[Service]
TimeoutStopSec=300

- Reboot :

[root@uzimysut01 ~]# systemctl reboot

- After reboot, dpkg is in a broken state :

[root@uzimysut01 ~]# apt dist-upgrade
E: dpkg was interrupted, you must manually run 'dpkg --configure -a' to correct the problem.

- State of the linux-cloud-tools-common package :

iFR linux-cloud-tools-common 4.15.0-34.37 all Linux kernel version specific cloud tools for version 4.15.0

Thanks a lot for your help.

[Guillaume Penin (guillaume-penin)]

@Eric : Logs in attachment.

Thanks a lot for your help.

[Eric Desrochers (slashd)]

# We see that "4.15.0-34.37" has been installed, and then 2-3 minutes later 'uu' failed to upgrade to "4.15.0-36.39" :

Start-Date: 2018-10-10 10:45:05
Commandline: apt install linux-cloud-tools-common=4.15.0-34.37
Downgrade: linux-cloud-tools-common:amd64 (4.15.0-36.39, 4.15.0-34.37)
End-Date: 2018-10-10 10:45:10

Start-Date: 2018-10-10 10:47:54
Commandline: /usr/bin/unattended-upgrade
Upgrade: linux-cloud-tools-common:amd64 (4.15.0-34.37, 4.15.0-36.39)
Error: Sub-process /usr/bin/dpkg exited unexpectedly
End-Date: 2018-10-10 10:52:41

I also found curious the attempt to Downgrade from "4.15.0-36.39" to "4.15.0-34.37".

apt/history.log:Commandline: apt install linux-cloud-tools-common=4.15.0-34.37
apt/history.log:Downgrade: linux-cloud-tools-common:amd64 (4.15.0-36.39, 4.15.0-34.37)
apt/history.log:Upgrade: linux-cloud-tools-common:amd64 (4.15.0-34.37, 4.15.0-36.39)

I don't have enough data to conclude things, but clearly something went wrong.
Can you reproduce the issue every time ?

[Guillaume Penin (guillaume-penin)]

Hi Eric,

The downgrade operation you saw is just because I've used the same server to give you the logs and to test the step-by-step instructions before writing them on this bug report.

I can confirm that the issue can be reproduced any time starting from the 2 versions (Xenial : 4.4.0-135.161, Bionic : 4.15.0-34.37), hundreds of our servers were impacted (and therefore we have stopped automatic upgrades on our Production servers).

I can also confirm that if i test an unattended-upgrade during shutdown on Bionic from 4.15.0-33.36, the package will be upgraded to version 4.15.0-36.39 without any problem.

[Eric Desrochers (slashd)]

Ok I'll give it a try today and test.

Does the impacted systems necessary need to be part of a Microsoft's virtualization platform ecosystem ? (Azure, Hyper-V, ...) to reproduce the problem ?

[Guillaume Penin (guillaume-penin)]

@Eric, no, it is not necessary. We encountered the same problem on AWS EC2 instances that share the same OS image and also have the linux-cloud-tools-common package installed.

[Eric Desrochers (slashd)]

I have tested w/ Bionic inside a KVM guest, and the upgrade went fine.

# unattended-upgrades/unattended-upgrades-dpkg.log

Log started: 2018-10-12 09:10:05
(Reading database ... ^M(Reading database ... 5%^M(Reading database ... 10%^M(Reading database ... 15%^M(Reading database ... 20%^M(Reading database ... 25%^M(Reading database ... 30%^M(Reading database ... 35%^M(Reading database ... 40%^M(Reading database ... 45%^M(Reading database ... 50%^M(Reading database ... 55%^M(Reading database ... 60%^M(Reading database ... 65%^M(Reading database ... 70%^M(Reading database ... 75%^M(Reading database ... 80%^M(Reading database ... 85%^M(Reading database ... 90%^M(Reading database ... 95%^M(Reading database ... 100%^M(Reading database ... 66657 files and directories currently installed.)^M
Preparing to unpack .../linux-cloud-tools-common_4.15.0-36.39_all.deb ...^M
Unpacking linux-cloud-tools-common (4.15.0-36.39) over (4.15.0-34.37) ...^M
Setting up linux-cloud-tools-common (4.15.0-36.39) ...^M
Processing triggers for ureadahead (0.100.0-20) ...^M
Processing triggers for man-db (2.8.3-2) ...^M
Log ended: 2018-10-12 09:10:09

# dpkg
ii linux-cloud-tools-common 4.15.0-36.39 all Linux kernel version specific cloud tools for version 4.15.0

[Guillaume Penin (guillaume-penin)]

@Eric : Is cloud-init installed on your system. If not, can you install it and try again please ? Indeed, as you can see in my first comment, removing the cloud-init dependency on the linux-cloud-tools-common makes the update process work well. So it seems to be related with cloud-init.

[Eric Desrochers (slashd)]

Still no apparent issue on my side.

# dpkg
ii cloud-init 18.3-9-g2e62cb8a-0ubuntu1~18.04.2 all Init scripts for cloud instances
ii linux-cloud-tools-common 4.15.0-36.39 all Linux kernel version specific cloud tools for version 4.15.0

Upgrade:
# apt-get install linux-cloud-tools-common -y
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following packages will be upgraded:
  linux-cloud-tools-common
1 upgraded, 0 newly installed, 0 to remove and 72 not upgraded.
Need to get 47.0 kB of archives.
After this operation, 7,168 B of additional disk space will be used.
Get:1 http://us.archive.ubuntu.com/ubuntu bionic-updates/main amd64 linux-cloud-tools-common all 4.15.0-36.39 [47.0 kB]
Fetched 47.0 kB in 0s (299 kB/s)
(Reading database ... 67213 files and directories currently installed.)
Preparing to unpack .../linux-cloud-tools-common_4.15.0-36.39_all.deb ...
Unpacking linux-cloud-tools-common (4.15.0-36.39) over (4.15.0-34.37) ...
Setting up linux-cloud-tools-common (4.15.0-36.39) ...
Processing triggers for ureadahead (0.100.0-20) ...
Processing triggers for man-db (2.8.3-2) ...

# term.log
Log started: 2018-10-12 09:56:38
(Reading database ... ^M(Reading database ... 5%^M(Reading database ... 10%^M(Reading database ... 15%^M(Reading database ... 20%^M(Reading database ... 25%^M(Reading database ... 30%^M(Reading database ... 35%^M(Reading database ... 40%^M(Reading database ... 45%^M(Reading database ... 50%^M(Reading database ... 55%^M(Reading database ... 60%^M(Reading database ... 65%^M(Reading database ... 70%^M(Reading database ... 75%^M(Reading database ... 80%^M(Reading database ... 85%^M(Reading database ... 90%^M(Reading database ... 95%^M(Reading database ... 100%^M(Reading database ... 67213 files and directories currently installed.)^M
Preparing to unpack .../linux-cloud-tools-common_4.15.0-36.39_all.deb ...^M
Unpacking linux-cloud-tools-common (4.15.0-36.39) over (4.15.0-34.37) ...^M
Setting up linux-cloud-tools-common (4.15.0-36.39) ...^M
Processing triggers for ureadahead (0.100.0-20) ...^M
Processing triggers for man-db (2.8.3-2) ...^M
Log ended: 2018-10-12 09:56:41

[Eric Desrochers (slashd)]

Can you run sosreport from an impacted system ? It may provide more context.

[Eric Desrochers (slashd)]

and send me the generated sosreport file : <email address hidden> (if sensible data) otherwise attach to the lp bug.

[Guillaume Penin (guillaume-penin)]

@Eric : Sosreport sent by email. Did you try the second time (with cloud-init installed) to reproduce with unattended upgrades on shutdown mode ? I did not mention it but upgrading the package outside of unattended upgrades on shutdown mode works.

[Eric Desrochers (slashd)]

Seems to me like the package "4.15.0-34.37" was already not in "ii" state :

2018-10-10 10:16:57 status half-configured linux-cloud-tools-4.15.0-34-generic:amd64 4.15.0-34.37
2018-10-10 10:16:57 status half-installed linux-cloud-tools-4.15.0-34-generic:amd64 4.15.0-34.37
2018-10-10 10:16:57 status half-configured linux-cloud-tools-4.15.0-34:amd64 4.15.0-34.37
2018-10-10 10:16:57 status half-installed linux-cloud-tools-4.15.0-34:amd64 4.15.0-34.37

2018-10-10 10:45:05 status half-configured linux-cloud-tools-common:all 4.15.0-36.39
2018-10-10 10:45:05 status half-installed linux-cloud-tools-common:all 4.15.0-36.39
2018-10-10 10:45:05 status half-installed linux-cloud-tools-common:all 4.15.0-36.39

[Eric Desrochers (slashd)]

Can you confirm the state of the package pre-upgrade ?

[Guillaume Penin (guillaume-penin)]

@Eric : The server was installed with a 4.15.0-34.37 kernel from a corporate OS image, and linux-cloud-tools-common package was also in version 4.15.0-34.37. All packages where in state "ii".

I dist-upgrade the server with APT (to version 4.15.0-36.39) and only downgrade the linux-cloud-tools-common package in order to only let unattended-upgrades try to upgrade the linux-cloud-tools-common package and have simpler unattended-upgrades logs to analyze. Upgrading the linux-cloud-tools-common simultaneously with the other kernel packages leeds to the same result.

Also, all packages where in state "ii" before running unattended-upgrades.

Let me know if you want me to delete the server and deploy it once more with another "fresh" test case.

[Eric Desrochers (slashd)]

Do you have an non-upgraded machine where you can run the sosreport prior the upgrade ? then run the upgrade (and if the problem occurs) run a second sosreport post upgrade ?

- Eric

[Eric Desrochers (slashd)]

I can't see anything obvious in the sosreport, minus the fact I clearly see the package in "iFR" state.

I asked a colleague of mine to test in Azure to double-check but my KVM guest tests look good so far :

# apt-get install linux-cloud-tools-common -y
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following packages will be upgraded:
  linux-cloud-tools-common
1 upgraded, 0 newly installed, 0 to remove and 72 not upgraded.
Need to get 47.0 kB of archives.
After this operation, 7,168 B of additional disk space will be used.
Get:1 http://us.archive.ubuntu.com/ubuntu bionic-updates/main amd64 linux-cloud-tools-common all 4.15.0-36.39 [47.0 kB]
Fetched 47.0 kB in 0s (227 kB/s)
(Reading database ... 67213 files and directories currently installed.)
Preparing to unpack .../linux-cloud-tools-common_4.15.0-36.39_all.deb ...
Unpacking linux-cloud-tools-common (4.15.0-36.39) over (4.15.0-34.37) ...
Setting up linux-cloud-tools-common (4.15.0-36.39) ...
Processing triggers for ureadahead (0.100.0-20) ...
Processing triggers for man-db (2.8.3-2) ...

[David Coronel (davecore)]

@Guillaume: I am Eric's colleague from comment #21. I was able to reproduce the issue in Azure with your reproducer in comment #5. I'll show Eric how I reproduced the issue and he'll be able to follow up with you. Thanks!

[Eric Desrochers (slashd)]

Might be a good idea to enable some systemd parameter for debugging purposes : https://freedesktop.org/wiki/Software/systemd/Debugging/

Enabling tty9 w/ systemd.debug-shell=1

and possibly the following :

Diagnosing Shutdown Problems
Just like with boot problems, when you encounter a hang during shutting down, make sure you wait at least 5 minutes to distinguish a permanent hang from a broken service that's just timing out. Then it's worth testing whether the system reacts to CTRL+ALT+DEL in any way.

If shutdown (whether it be to reboot or power-off) of your system gets stuck, first test if the kernel itself is able to reboot or power-off the machine forcedly using one of these commands:

reboot -f
poweroff -f
If either one of the commands does not work, it's more likely to be a kernel, not systemd bug.

Shutdown Completes Eventually
If normal reboot or poweroff work, but take a suspiciously long time, then

boot with the debug options:

systemd.log_level=debug systemd.log_target=kmsg log_buf_len=1M printk.devkmsg=on enforcing=0
save the following script as /usr/lib/systemd/system-shutdown/debug.sh and make it executable:

#!/bin/sh
mount -o remount,rw /
dmesg > /shutdown-log.txt
mount -o remount,ro /
reboot

Look for timeouts logged in the resulting file shutdown-log.txt and/or attach it to a bugreport.

Shutdown Never Finishes
If normal reboot or poweroff never finish even after waiting a few minutes, the above method to create the shutdown log will not help and the log must be obtained using other methods. Two options that are useful for debugging boot problems can be used also for shutdown problems:

use a serial console
use a debug shell - not only is it available from early boot, it also stays active until late shutdown.

[Eric Desrochers (slashd)]

It may help to better understand what's going on.

[Guillaume Penin (guillaume-penin)]

Hi Eric,

Please find attached the resulting file "shutdown-log.txt".

[Eric Desrochers (slashd)]

Hi Guillaume,

I seemed to only be able to reproduce the behaviour in the 'uu' context, if for instance I upgrade the pkg using apt, it goes well for me so far.

Can you conclude you are experiencing the same outcome as me and you are only able to fully reproduce when 'uu' is involved ?

[Eric Desrochers (slashd)]

in 'uu' context and only during the shutdown operation seems like.

I just ran 'uu' from the CLI and it went well :

$ sudo unattended-upgrade --debug
...
Log started: 2018-11-01 19:10:16
(Reading database ... 56537 files and directories currently installed.)
Preparing to unpack .../linux-cloud-tools-common_4.15.0-36.39_all.deb ...
Unpacking linux-cloud-tools-common (4.15.0-36.39) over (4.15.0-34.37) ...
Setting up linux-cloud-tools-common (4.15.0-36.39) ...
Processing triggers for ureadahead (0.100.0-20) ...
Processing triggers for man-db (2.8.3-2ubuntu0.1) ...
left to upgrade {'libcurl4', 'curl'}
adjusting candidate version: linux-cloud-tools-common=4.15.0-36.39
applying set ['libcurl4', 'curl']
Log ended: 2018-11-01 19:10:20
...

ii linux-cloud-tools-common 4.15.0-36.39 all Linux kernel version specific cloud tools for version 4.15.0

During the shutdown procedure, it seems like something send a SIGTERM to 'uu' which cause the installation to not complete :

2018-11-01 14:20:26,426 INFO Writing dpkg log to /var/log/unattended-upgrades/unattended-upgrades-dpkg.log
2018-11-01 14:25:23,996 WARNING SIGTERM received, will stop
2018-11-01 14:25:24,027 WARNING SIGTERM received, will stop
2018-11-01 14:25:24,578 ERROR Installing the upgrades failed!
2018-11-01 14:25:24,579 ERROR error message: installArchives() failed
2018-11-01 14:25:24,579 ERROR dpkg returned a error! See /var/log/unattended-upgrades/unattended-upgrades-dpkg.log for details

[Eric Desrochers (slashd)]

Next step, I'll compile 'uu' upstream 1.6 and test against it and the cosmic version which has more fixes.

If the result is different, I'll then start a bisection.

Let's see.

[Eric Desrochers (slashd)]

Guillaume can you use your protocol but this time using this test package[1]

I wasn't able to reproduce with the change I made based on a bug fixed in Cosmic:
https://bugs.launchpad.net/bugs/1778219

--
sudo add-apt-repository ppa:slashd/uu2
sudo apt-get update
sudo apt-get install unattended-upgrades
--

Let me know the outcome.

Regards,
Eric

[Eric Desrochers (slashd)]

The package include the following upstream fix :
https://github.com/mvo5/unattended-upgrades/commit/cda637b0d89973fd46382418893a23bef4195a2f

[Guillaume Penin (guillaume-penin)]

Hi Eric,

I confirm that this behaviour can only be reproduced in 'uu' context and only in 'shutdown mode'.

I can also confirm that the upgrade process is now OK in Bionic with your test package :

- unattended-upgrades version after the test package installation :

ii unattended-upgrades 1.1ubuntu1.18.04.6+testpkgb1 all automatic installation of security upgrades

- dpkg status for linux-cloud-tools-common after reboot + 'uu' in 'shutdown mode' :

ii linux-cloud-tools-common 4.15.0-36.39 all Linux kernel version specific cloud tools for version 4.15.0

- APT logs for linux-cloud-tools-common :

Start-Date: 2018-11-02 16:28:56
Commandline: /usr/bin/unattended-upgrade
Upgrade: linux-cloud-tools-common:amd64 (4.15.0-34.37, 4.15.0-36.39)
End-Date: 2018-11-02 16:29:01

Would it also be possible to backport the fix in Xenial, as this version is also impacted ?

Thanks a lot for your help.

[Eric Desrochers (slashd)]

Yes, I'll be SRU'ing Bionic and Xenial as well.

[Eric Desrochers (slashd)]

Well in fact for Xenial there is an email thread already to do a full backport :
https://lists.canonical.com/mailman/listinfo/openstack-devops
https://bugs.launchpad.net/ubuntu/+source/unattended-upgrades/+bug/1702793

So I'll SRU Bionic and let the full backport discussion to finish for Xenial, as I don't want to interfere.

[Eric Desrochers (slashd)]

In fact more fixes are needed due to regression in the fix above the fixes are found here :
https://github.com/mvo5/unattended-upgrades/pull/148

[Balint Reczey (rbalint)]

Since this issue is marked as invalid for linux i'm setting it as a duplicate of the u-u bug where SRU-ing the fix is tracked.