unattended-upgrades does not block shutdown of system, as it is designed to

Bug #1690980 reported by ethan.hsieh on 2017-05-16
22
This bug affects 2 people
Affects Status Importance Assigned to Milestone
OEM Priority Project
Critical
ethan.hsieh
Xenial
Critical
Unassigned
apt (Ubuntu)
Critical
Unassigned
Xenial
Critical
Unassigned
Zesty
Critical
Unassigned
unattended-upgrades (Ubuntu)
Undecided
Balint Reczey
Xenial
Undecided
Unassigned
Zesty
Undecided
Unassigned

Bug Description

Title: No pop-up window to warn users that system should not reboot or shutdown while installing security updates

Summary:
No pop-up window to warn users that system should not reboot or shutdown while installing security updates

Steps:
1. trigger unattended-upgrades
2. reboot or shutdown system while installing packages

Expected results: There is a pop-up window to warn users that system should not reboot or shutdown

Actual results: There is no pop-up window to warn users

Additional information:
$ apt-cache policy unattended-upgrades
unattended-upgrades:
  Installed: 0.90
  Candidate: 0.90ubuntu0.5
$ lsb_release -rd
Description: Ubuntu 16.04 LTS

* APT SRU *
[Impact]
Stopping apt-daily-upgrade.service terminates dpkg and friends by sending the signals to all processes in the cgroup, and will send KILL quickly after.

[Test case]
Start apt-daily-upgrade.service and stop it while unattended-upgrades is running.

The upgrade should run to completion or a safe exit point as long as it takes less than about 900s (which is the timeout for sending kill).

[Regression potential]
Leftover processes might remain in the apt-daily-upgrade cgroup if the postinst scripts or some apt hooks do something funny.

Shutdown might take longer due to the 900 second timeout.

no longer affects: bluez (Ubuntu)
ethan.hsieh (ethan.hsieh) wrote :

According to 1), system rebooted at 08:22:27, May 12.
According to 2)3)4), system was updating packages at 08:22:XX.
System rebooted while installing security updates. It resulted in the incomplete package installation.
X crash (compiz[1824]: segfault) is caused by an incomplete package installation.

1) Kern.log
kern.log
May 12 08:22:27 NetworkManager[965]: <info> [1494591747.8211] ModemManager disappeared from bus
// System reboots
May 12 08:23:37 kernel: [ 0.000000] Initializing cgroup subsys cpuset
// It's the first time we see segfault of compiz.
May 12 08:24:14 kernel: [ 59.139613] compiz[1824]: segfault at e0 ip 00007f0b62318263 sp 00007ffdfbff4c20 error 4

2) history.log
apt/history.log
Start-Date: 2017-05-12 07:43:26
Commandline: /usr/bin/unattended-upgrade
Install: linux-image-4.4.0-75-generic:amd64 (4.4.0-75.96, automatic), ... etc

3) dpkg.log
dpkg.log
2017-05-12 07:43:26 startup archives unpack
2017-05-12 07:43:27 upgrade login:amd64 1:4.2-3.1ubuntu5 1:4.2-3.1ubuntu5.2
...
2017-05-12 08:22:24 status unpacked linux-headers-4.4.0-75:all 4.4.0-75.96
2017-05-12 08:22:24 install linux-headers-4.4.0-75-generic:amd64 <none> 4.4.0-75.96
2017-05-12 08:22:24 status half-installed linux-headers-4.4.0-75-generic:amd64 4.4.0-75.96

4) unattended-upgrades/unattended-upgrades.log
2017-05-12 07:06:36,093 INFO Initial whitelisted packages:
2017-05-12 07:06:36,094 INFO Starting unattended upgrades script
2017-05-12 07:06:36,094 INFO Allowed origins are: ['o=Ubuntu,a=xenial-security']
2017-05-12 07:43:24,300 INFO Packages that will be upgraded: apparmor apport apport-gtk ... etc

affects: unattended-upgrades → unattended-upgrades (Ubuntu)
Changed in oem-priority:
importance: Undecided → High
assignee: nobody → ethan.hsieh (ethan.hsieh)
Brian Murray (brian-murray) wrote :

Could you provide some more information about how you started unattended-upgrades? Additionally, could you explain the use case for running unattended-upgrades manually?

Changed in unattended-upgrades (Ubuntu):
status: New → Incomplete
ethan.hsieh (ethan.hsieh) wrote :

@Brian Murray

When I saw this issue first time, unattended-upgrades was triggered automatically.
I tried to reproduce this issue, so I executed the python script manually.

I filed the bug because users don't know security updates is ongoing when unattended-upgrades is triggered automatically. If users reboot or shutdown system at that moment, system may fail to boot at next time.

Brian Murray (brian-murray) wrote :

I tested this on Yakkety and confirm the behavior - it is possible to reboot while unattended-upgrades is running and reading the code there is nothing to prevent it.

Changed in oem-priority:
status: New → Confirmed
importance: High → Critical
Brian Murray (brian-murray) wrote :

After a discussion with Michael Vogt I tested this with unattended-upgrades version 0.92ubuntu1.4 from yakkety-updates and observed the shutdown blocked temporarily (message in plymouth about updates being installed) when I shutdown the system with unattended-upgrades running.

I was connected via ssh when running the unattended-upgrades and saw the following:

Preparing to unpack .../18-libreoffice-style-galaxy_1%3a5.2.2-0ubuntu2.1_all.deb ...
Unpacking libreoffice-style-galaxy (1:5.2.2-0ubuntu2.1) over (1:5.2.2-0ubuntu2) ...
Connection to clean-yakkety-amd64 closed by remote host.
Connection to clean-yakkety-amd64 closed.

In plymouth I also saw the message about "libreoffice-style-galaxy". Could you please retest and ensure you shutdown the system when packages are being unpacked / installed?

Brian Murray (brian-murray) wrote :

Additionally, after reboot and running unattended-upgrades I saw the following:

2017-05-18 13:01:59,777 INFO Allowed origins are: ['o=Ubuntu,a=yakkety', 'o=Ubuntu,a=yakkety-security']
2017-05-18 13:01:59,777 WARNING Unclean dpkg state detected, trying to correct
2017-05-18 13:02:20,263 WARNING dpkg --configure -a output:
Setting up libdns162:amd64 (1:9.10.3.dfsg.P4-10.1ubuntu1.6) ...
...

So while there isn't a "pop-up window" that unattended-upgrades are running a reboot while they are running is something which can be recovered from.

ethan.hsieh (ethan.hsieh) wrote :

@Brian Murray

Here is the log which I uploaded in #1
//dpkg.log
2017-05-12 08:22:24 status unpacked linux-headers-4.4.0-75:all 4.4.0-75.96
2017-05-12 08:22:24 install linux-headers-4.4.0-75-generic:amd64 <none> 4.4.0-75.96
2017-05-12 08:22:24 status half-installed linux-headers-4.4.0-75-generic:amd64 4.4.0-75.96
//term.log
Selecting previously unselected package linux-headers-4.4.0-75.
Preparing to unpack .../linux-headers-4.4.0-75_4.4.0-75.96_all.deb ...
Unpacking linux-headers-4.4.0-75 (4.4.0-75.96) ...
Selecting previously unselected package linux-headers-4.4.0-75-generic.
Preparing to unpack .../linux-headers-4.4.0-75-generic_4.4.0-75.96_amd64.deb ...
Unpacking linux-headers-4.4.0-75-generic (4.4.0-75.96) ...

In my case, the installation of linux-header/linux-image was interrupted, and then system failed to boot to Ubuntu desktop. unattended-upgrades had no chance to finish the installation. It looks like not all packages can be recovered after reboot.
It seems to me that the ideal way is that reboot/shutdown is blocked until unattended-upgrades finishes secure update.

Changed in oem-priority:
status: Confirmed → Triaged
Brian Murray (brian-murray) wrote :

The description of the bug contains the following:

$ apt-cache policy unattended-upgrades
unattended-upgrades:
  Installed: 0.90
  Candidate: 0.90ubuntu0.5

Additionally, we can see in the unattended-upgrades.log file that unattended-upgrades will be upgraded. Please run the test again with unattended-upgrades version 0.90ubuntu0.5 on a xenial system. My testing has indicated that there may have been an issue with installing updates and shutting down but this should be resolved with the version of the package in -updates.

Changed in oem-priority:
status: Triaged → In Progress
ethan.hsieh (ethan.hsieh) wrote :

@Brian Murray

I still can reproduce this issue with 0.90ubuntu0.6
$ apt-cache policy unattended-upgrades
unattended-upgrades:
  Installed: 0.90ubuntu0.6
  Candidate: 0.90ubuntu0.6

Please check full log as attached.

Here are reproduction steps:
1. sudo /usr/bin/unattended-upgrade
2. Run the following script.
#!/bin/sh
loop=1
count=0
while [ $loop -gt 0 ]
do
    count=`expr $count + 1`
    echo "loop...$count"
    if [ `grep -r -e "status half-installed linux-headers-4.4.0-78" /var/log/dpkg.log | wc -l` -ge 1 ]; then
        aplay /usr/share/sounds/alsa/Front_Right.wav
        sudo reboot
    fi
    sleep 1
done

ethan.hsieh (ethan.hsieh) wrote :

@Brian Murray
Still can reproduce this issue if I reboot system by GUI.

Brian Murray (brian-murray) wrote :

What in the log files indicates that the unattended-upgrades process did not finish? As far as I can tell everything was installed successfully even though the unattended-upgrades log file did not receive all the log messages.

Brian Murray (brian-murray) wrote :

Using your test script on Xenial I discovered that after the reboot I needed to run 'sudo dpkg --configure -a' to finish the operations that unattended-upgrades was doing.

Further testing has revealed that there seems to be something wrong with Xenial while I'd been testing Yakkety.

When running your script on Yakkety I saw that unattended-upgrades-shutdown.log was created and contained the following:

bdmurray@clean-yakkety-amd64:~$ cat /var/log/unattended-upgrades/unattended-upgrades-shutdown.log
2017-05-24 14:56:03,095 WARNING - Unattended-upgrade in progress during shutdown, sleeping for 5s
Progress: 50.1385 % (linux-headers-4.8.0-52)
2017-05-24 14:56:08,110 INFO - All upgrades installed

While on Xenial unattended-upgrades-shutdown.log was an empty file and I did not see anything on the shutdown screen about the shutdown being paused.

Could you confirm that Yakkety deals better with a reboot while unattended-upgrades is running? Thanks!

Brian Murray (brian-murray) wrote :

I ran the same test in Zesty and observed the same behavior as in Yakkety.

 $ cat /var/log/unattended-upgrades/unattended-upgrades-shutdown.log
2017-05-24 15:21:05,408 WARNING - Unattended-upgrade in progress during shutdown, sleeping for 5s
Progress: 56.7568 % (libvirt-bin)
2017-05-24 15:21:10,425 INFO - All upgrades installed
[ 3:30PM 9033 ] [ bdmurray@speedy:~ ]
 $ apt-cache policy unattended-upgrades
unattended-upgrades:
  Installed: 0.93.1ubuntu2.2
  Candidate: 0.93.1ubuntu2.2
  Version table:
 *** 0.93.1ubuntu2.2 500
        500 http://192.168.10.7/ubuntu zesty-updates/main amd64 Packages
        500 http://192.168.10.7/ubuntu zesty-updates/main i386 Packages
        100 /var/lib/dpkg/status

tags: added: xenial
ethan.hsieh (ethan.hsieh) wrote :

@Brian Murray
It seems to me that Yakkety (16.10) deals better with a reboot while unattended-upgrades is running.

After I shutdowned system by GUI, I saw the following message.
"Unattended-upgrade in progress during shutdown, sleeping for 5s
Progress: 67.5656 % ......"
(Please check logs as attached)

And, I still can login to Ubuntu desktop after shutdown.

Brian Murray (brian-murray) wrote :

I tested this again today with Ubuntu 16.04, Xenial, but I installed the 16.10 version of unattended-upgrades and installed the version of systemd from xenial-updates before running the test. The results were the same and /var/log/unattended-upgrades/unattended-upgrades-shutdown.log is still empty.

Changed in oem-priority:
status: In Progress → Triaged
Changed in oem-priority:
importance: Critical → High
ethan.hsieh (ethan.hsieh) wrote :

New test result:
1. unattended-upgrades is triggered by apt-daily.timer.
yakkety (triggered by apt-daily.timer): Failed
xenial (triggered by apt-daily.timer): Failed
2. unattended-upgrades is triggered by cmdline (sudo unattended-upgrade)
yakkety (triggered by cmdline): Pass
xenial (triggered by cmdline): Failed

This issue can be reproduced on yakkety.

unattended-upgrades received signal, and then it was stopped.
Here is the log:

1. unattended-upgrades.log
2017-06-26 17:30:59,944 INFO Initial blacklisted packages:
2017-06-26 17:30:59,948 INFO Initial whitelisted packages:
2017-06-26 17:30:59,948 INFO Starting unattended upgrades script
2017-06-26 17:30:59,948 INFO Allowed origins are: ['o=Ubuntu,a=yakkety-security']
2017-06-26 17:33:21,236 INFO Packages that will be upgraded: apparmor apparmor-easyprof ...
2017-06-26 17:33:21,236 INFO get_lock returned 174
2017-06-26 17:33:41,569 INFO signal received, will stop
2017-06-26 17:33:41,610 INFO signal received, will stop

2. syslog:
Jun 26 17:33:41 u-Inspiron-5379 systemd[1]: Starting Unattended Upgrades Shutdown...

3. unattended-upgrades-shutdown.log
2017-06-26 17:33:41,871 WARNING - Running unattended-upgrades in shutdown mode
2017-06-26 17:33:42,079 WARNING - ps -aef | grep unatteded-upgrade
2017-06-26 17:33:42,316 WARNING - root 2551 1 4 17:33 ? 00:00:00 /usr/bin/python3 /usr/share/unattended-upgrades/unattended-upgrade-shutdown
2017-06-26 17:33:42,329 WARNING - root 2670 2551 0 17:33 ? 00:00:00 grep unattended-upgrade
2017-06-26 17:33:42,345 WARNING - get_lock returned 4
2017-06-26 17:33:42,362 WARNING - lock not taken

Kent Lin (kent-jclin) on 2017-06-27
Changed in oem-priority:
importance: High → Critical
ethan.hsieh (ethan.hsieh) wrote :

In xenial and yakkety, unattended-upgrade can finish security updates after applying workaround 1&2.

workaround 3: If users reboot/shutdown by UI, there will be a pop-up window which asks users for root password.
If users reboot/shutdown by command (sudo reboot), unattended-upgrade will be killed and cannot finish security updates.

Workaround 1:
/lib/systemd/system/apt-daily.service
[Service]
Type=oneshot
ExecStart=/usr/lib/apt/apt.systemd.daily
+KillMode=none
+TimeoutStopSec=0

Wordaround 2:
/lib/systemd/system/apt-daily.service
[Unit]
Description=Daily apt activities
Documentation=man:apt(8)
+DefaultDependencies=no
+Before=shutdown.target

Workaround 3:
/lib/systemd/system/apt-daily.service
[Service]
Type=oneshot
-ExecStart=/usr/lib/apt/apt.systemd.daily
+ExecStart=/bin/systemd-inhibit --what=shutdown --mode=block /usr/lib/apt/apt.systemd.daily

---
the code flow of unattended-upgrades:
(1) -> apt_pkg.get_lock() -> do_install() -> (2)

If users reboot/shutdown system in (1), unattended-upgrades-shutdown will break from monitoring loop and then there will no message to tell user that security update is ongoing.

Steve Langasek (vorlon) on 2017-06-29
summary: - No pop-up window to warn users that system should not reboot or shutdown
- while installing security updates
+ unattended-upgrades does not block shutdown of system, as it is designed
+ to
Changed in unattended-upgrades (Ubuntu):
assignee: nobody → Balint Reczey (rbalint)
Balint Reczey (rbalint) on 2017-06-30
Changed in unattended-upgrades (Ubuntu):
status: Incomplete → In Progress
Balint Reczey (rbalint) wrote :

Could you please test the attached patch on Xenial either by rebuilding the package or by grabbing it from https://launchpad.net/~rbalint/+archive/ubuntu/scratch ?
It is expected to fix the communication between u-u and u-u-shutdown and make u-u-shutdown wait properly for u-u to finish.

Changed in unattended-upgrades (Ubuntu):
status: In Progress → Incomplete

The attachment "unattended-upgrades_0.90ubuntu0.7.patch" seems to be a debdiff. The ubuntu-sponsors team has been subscribed to the bug report so that they can review and hopefully sponsor the debdiff. If the attachment isn't a patch, please remove the "patch" flag from the attachment, remove the "patch" tag, and if you are member of the ~ubuntu-sponsors, unsubscribe the team.

[This is an automated message performed by a Launchpad user owned by ~brian-murray, for any issue please contact him.]

tags: added: patch
ethan.hsieh (ethan.hsieh) wrote :

@Balint
The attached patch can fix the communication between u-u and u-u-shutdown.
However, without workaround 1 or 2 in #19, u-u will be killed when users reboot/shutdown the device.

Brian Murray (brian-murray) wrote :

Ethan - Have you tested the patch that Balint provided or are you guessing about how it will behave? If the communication is improved u-u-shutdown will delay the shutdown process while updates are being installed.

Brian Murray (brian-murray) wrote :

I built a new version of unattended-upgrades with Balint's patch and tested it on an Ubuntu 16.04 system. I used the attached modified version of the reboot script provided by Ethan and saw the following in the terminal which I had run "sudo unattended-upgrade --debug --verbose":

Preparing to unpack .../libc6-dev_2.23-0ubuntu9_amd64.deb ...
Unpacking libc6-dev:amd64 (2.23-0ubuntu9) over (2.23-0ubuntu3) ...
Connection to clean-xenial-amd64.local closed by remote host.
Connection to clean-xenial-amd64.local closed.

The system ended up in a state where I had to run 'sudo dpkg --configure -a' and then 'sudo apt-get -f install'.

ethan.hsieh (ethan.hsieh) wrote :

@Brian
My test result with Balint's patch is in #22.

According to the previous test in #18, the behavior of my test script is different from apt-daily timer. If you want to reproduce this issue, creating override.conf would be a better way.
---
sudo cat << EOF > /etc/systemd/system/apt-daily.timer.d/override.conf
[Timer]
OnCalendar=
OnCalendar= *-*-* XX:YY
RandomizedDelaySec=1m
AccuracySec=1m
EOF
fi
PS: Please remember to modify XX:YY to the time you want.

Balint Reczey (rbalint) wrote :

IMO the proper fix involves several changes which I collected in this GitHub branch to be merged
to upstream:
https://github.com/rbalint/unattended-upgrades/commits/lock-handling

Since the changes are extensive I would prefer merging them upstream, releasing them to sid, then Artful, and then they can be backported to Xenial and other releases. It looks like to me that more code needs to be backported than half of the delta between releases thus I propose SRU-s practically syncing latest unattended-updates to supported releases.

Testing of the new code is appreciated, but please let u-u be triggered by the apt-daily* timers because sudo does not protect u-u from being killed as Ethan pointed out in #25.

Balint Reczey (rbalint) wrote :

I opened a PR upstream with the proposed fix and also prepared a backport for Xenial in this PPA:
https://launchpad.net/~rbalint/+archive/ubuntu/scratch

The PPA has a build for Artful, too.

PR: https://github.com/mvo5/unattended-upgrades/pull/64

Balint Reczey (rbalint) on 2017-07-22
Changed in unattended-upgrades (Ubuntu):
status: Incomplete → Confirmed
ethan.hsieh (ethan.hsieh) wrote :

@Balint
Something wrong happens when installing deb package apport.
(Please check full log as attached)

unattended-upgrades-dpkg.log
Unpacking python3-apport (2.20.1-0ubuntu2.10) over (2.20.1-0ubuntu2) ...
Preparing to unpack .../apport_2.20.1-0ubuntu2.10_all.deb ...

unattended-upgrades-shutdown.log
2017-07-25 11:27:46,257 WARNING - Unattended-upgrade in progress during shutdown, sleeping for 5s
Progress: 38.7177 % (apport)
...
2017-07-25 11:33:12,886 WARNING - Unattended-upgrade in progress during shutdown, sleeping for 5s
Progress: 38.7177 % (apport)
2017-07-25 11:33:17,906 WARNING - Unattended-upgrade in progress during shutdown, sleeping for 5s
Progress: 38.7177 % (apport)
2017-07-25 11:33:22,925 WARNING - Giving up on lockfile after 10 delay

//No progress when installing apport. It's always 38.7177 %

Balint Reczey (rbalint) wrote :

Instead of providing the drop-in and placing it in u-u's preinst I think it would be better to fix apt instead.

Apt already exits on SIGUSR1 thus even when u-u is not installed this seems to work correctly.

I've uploaded apt and u-u for testing to ppa:rbalint/scratch, please give them a try.

Please upgrade apport in advance because the failure seems to be unrelated, but I'm going to check it again.

Balint Reczey (rbalint) wrote :
Julian Andres Klode (juliank) wrote :

I disagree with the apt patch, well the kill changes. I'm not sure what you're trying to achieve with that, but I definitely don't want to terminate stuff using USR1 and I don't want to only kill the main process (the shell script).

Balint Reczey (rbalint) wrote :

@Julian: Unattended-upgrades exits gracefully on USR1 and apt exits properly, too.
Otherwise apt just gets killed on shutdown and without the kill changes u-u gets killed too which is the issue here.

If the default KillMode=control-group is kept dpkg gets the signal, too, and u-u can't protect the installation steps.

Julian Andres Klode (juliank) wrote :

apt does not have special handling for USR1, it's the default action, which is TERM.

Balint Reczey (rbalint) wrote :

@Julian: OK, I'm changing u-u to handle TERM instead which seems reasonable.
Looking at the history it used to use INT, but TERM would be the best choice.
The KillMode still needs to be changed. Are you OK with that part?

Balint Reczey (rbalint) wrote :

I moved to handling TERM in u-u:
https://github.com/rbalint/unattended-upgrades/commits/master

I also attached the patch for APT which changes the KillMode and timeout. Since this affects only apt-daily-upgrade.service and it runs "apt.systemd.daily install" which perform minimal tasks when u-u is not installed this should be safe change.

I've uploaded apt and u-u for testing to ppa:rbalint/scratch, please give them a try.

Balint Reczey (rbalint) wrote :

The apport issue seems to be due to a bug in xenial's shared-mime-info:

root@xenial-test:/home/rbalint# time apt-get install -y --allow-downgrades --reinstall apport=2.20.1-0ubuntu2
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following packages were automatically installed and are no longer required:
  libllvm3.8 libmircommon5 linux-image-4.4.0-78-generic
  linux-image-4.4.0-83-generic
Use 'sudo apt autoremove' to remove them.
0 upgraded, 0 newly installed, 1 reinstalled, 0 to remove and 20 not upgraded.
Need to get 0 B/119 kB of archives.
After this operation, 0 B of additional disk space will be used.
(Reading database ... 271938 files and directories currently installed.)
Preparing to unpack .../apport_2.20.1-0ubuntu2_all.deb ...
Unpacking apport (2.20.1-0ubuntu2) over (2.20.1-0ubuntu2) ...
Processing triggers for ureadahead (0.100.0-19) ...
Processing triggers for systemd (229-4ubuntu18) ...
Processing triggers for shared-mime-info (1.5-2ubuntu0.1) ...
Processing triggers for hicolor-icon-theme (0.15-0ubuntu1) ...
Processing triggers for man-db (2.7.5-1) ...
Setting up apport (2.20.1-0ubuntu2) ...

real 1m36.802s
user 0m1.812s
sys 0m0.796s

root@xenial-test:/home/rbalint# time update-mime-database.real /usr/share/mime

real 1m53.622s
user 0m0.264s
sys 0m0.096s

This takes ~2s on zesty:
root@zesty-test:/home/rbalint# time update-mime-database.real /usr/share/mime
Unknown media type in type 'all/all'
Unknown media type in type 'all/allfiles'

real 0m2.146s
user 0m0.272s
sys 0m0.104s

This may worth further investigation and possibly an SRU.

ethan.hsieh (ethan.hsieh) wrote :

@Balint

unattended-upgrades didn't finish online-update.
https://launchpad.net/~rbalint/+archive/ubuntu/scratch/+packages
unattended-upgrades: (0.93.2~16.04.0+rbalint2)
apt:(1.2.25~rbalint2)

Here are logs:

/var/log/unattended-upgrades/unattended-upgrades.log
2017-07-26 15:58:59,769 INFO Initial blacklisted packages:
2017-07-26 15:58:59,770 INFO Initial whitelisted packages:
2017-07-26 15:58:59,770 INFO Starting unattended upgrades script
2017-07-26 15:58:59,770 INFO Allowed origins are: ['o=Ubuntu,a=xenial', 'o=Ubuntu,a=xenial-security', 'o=UbuntuESM,a=xenial']
2017-07-26 16:03:53,918 WARNING SIGTERM received, will stop
2017-07-26 16:03:54,073 WARNING SIGTERM received, will stop
2017-07-26 16:03:55,082 WARNING SIGTERM received, will stop

/var/log/unattended-upgrades/unattended-upgrades-shutdown.log
2017-07-26 16:03:54,924 WARNING - Unattended-upgrade in progress during shutdown, sleeping for 5s
2017-07-26 16:04:00,607 INFO - All upgrades installed

Installed packages:
apt_1.2.25-rbalint2_amd64.deb
apt-doc_1.2.25-rbalint2_all.deb
apt-transport-https_1.2.25-rbalint2_amd64.deb
apt-utils_1.2.25-rbalint2_amd64.deb
libapt-inst2.0_1.2.25-rbalint2_amd64.deb
libapt-pkg5.0_1.2.25-rbalint2_amd64.deb
libapt-pkg-doc_1.2.25-rbalint2_all.deb
unattended-upgrades_0.93.2-16.04.0+rbalint2_all.deb

Balint Reczey (rbalint) wrote :

Thanks, this happened when Unattended-Upgrade::InstallOnShutdown was set.

I have uploaded a new u-u package to the ppa and updated the GitHub PR with the fix. Please give the package a try, it now works fine on my system.
I did not notice the issue because the download step was quick in my VM.

Balint Reczey (rbalint) wrote :

When InstallOnShutdown is not set u-u is still asked to stop gracefully during download/installation thus all updates may not get installed but the consistency of the system is kept.

Balint Reczey (rbalint) on 2017-07-26
Changed in unattended-upgrades (Ubuntu):
status: Confirmed → Fix Committed
Balint Reczey (rbalint) on 2017-07-26
Changed in apt (Ubuntu):
status: New → Fix Committed
Brian Murray (brian-murray) wrote :

So far this seems to work, I don't get an inconsistent system while testing on Ubuntu 16.04, I did notice a crash report in /var/crash from unattended-upgrades. Here's the Traceback:

 Traceback (most recent call last):
   File "/usr/bin/unattended-upgrade", line 918, in do_install
     cache, logfile_dpkg, options.verbose or options.debug)
   File "/usr/bin/unattended-upgrade", line 433, in upgrade_normal
     res, error = cache_commit(cache, logfile_dpkg, verbose)
   File "/usr/bin/unattended-upgrade", line 424, in cache_commit
     res = cache.commit(install_progress=iprogress)
   File "/usr/lib/python3/dist-packages/apt/cache.py", line 515, in commit
     res = self.install_archives(pm, install_progress)
   File "/usr/lib/python3/dist-packages/apt/cache.py", line 479, in install_archives
     res = install_progress.run(pm)
   File "/usr/lib/python3/dist-packages/apt/progress/base.py", line 208, in run
     res = self.wait_child()
   File "/usr/lib/python3/dist-packages/apt/progress/base.py", line 279, in wait_child
     self.update_interface()
   File "/usr/bin/unattended-upgrade", line 227, in update_interface
     self._do_verbose_output_if_needed()
   File "/usr/bin/unattended-upgrade", line 244, in _do_verbose_output_if_needed
     os.write(1, os.read(self.output_logfd, 1024))
 OSError: [Errno 5] Input/output error

 During handling of the above exception, another exception occurred:

 Traceback (most recent call last):
   File "/usr/bin/unattended-upgrade", line 1581, in <module>
     main(options)
   File "/usr/bin/unattended-upgrade", line 1468, in main
     logfile_dpkg)
   File "/usr/bin/unattended-upgrade", line 921, in do_install
     os.write(2, ("Exception: %s\n" % e).encode('utf-8'))
 OSError: [Errno 5] Input/output error

Brian Murray (brian-murray) wrote :

Additionally, when I modified my reboot script to reboot when linux-headers were half-installed I ran into the following:

bdmurray@clean-xenial-amd64:~$ sudo apt-get dist-upgrade
E: dpkg was interrupted, you must manually run 'sudo dpkg --configure -a' to correct the problem.

I thought that is what we are trying to avoid. Here's the script:

bdmurray@clean-xenial-amd64:~$ cat u-u-reboot.sh
#!/bin/sh
loop=1
count=0
today=$(date +%Y-%m-%d)
while [ $loop -gt 0 ]
do
    count=$(expr $count + 1)
    echo "loop...$count"
    time=$(date +%H:%M)
    if [ $(grep -r -e "$today $time.*status half-installed linux-headers.*" /var/log/dpkg.log | wc -l) -ge 1 ]; then
        aplay /usr/share/sounds/alsa/Front_Right.wav
        sudo reboot
    fi
    sleep 1
done

Balint Reczey (rbalint) wrote :

@Brian: did you have the updated apt 1.2.25~rbalint2 package installed, too?

Brian Murray (brian-murray) wrote :

bdmurray@clean-xenial-amd64:~$ apt-cache policy unattended-upgrades
unattended-upgrades:
  Installed: 0.93.2~16.04.0+rbalint3
  Candidate: 0.93.2~16.04.0+rbalint3
  Version table:
 *** 0.93.2~16.04.0+rbalint3 500
        500 http://ppa.launchpad.net/rbalint/scratch/ubuntu xenial/main amd64 Packages
        500 http://ppa.launchpad.net/rbalint/scratch/ubuntu xenial/main i386 Packages
        100 /var/lib/dpkg/status
     0.90ubuntu0.6 500
        500 http://192.168.10.7/ubuntu xenial-updates/main amd64 Packages
        500 http://192.168.10.7/ubuntu xenial-updates/main i386 Packages
     0.90ubuntu0.1 500
        500 http://192.168.10.7/ubuntu xenial-security/main amd64 Packages
        500 http://192.168.10.7/ubuntu xenial-security/main i386 Packages
     0.90 500
        500 http://192.168.10.7/ubuntu xenial/main amd64 Packages
        500 http://192.168.10.7/ubuntu xenial/main i386 Packages
bdmurray@clean-xenial-amd64:~$ apt-cache policy apt
apt:
  Installed: 1.2.25~rbalint2
  Candidate: 1.2.25~rbalint2
  Version table:
 *** 1.2.25~rbalint2 500
        500 http://ppa.launchpad.net/rbalint/scratch/ubuntu xenial/main amd64 Packages
        100 /var/lib/dpkg/status
     1.2.20 500
        500 http://192.168.10.7/ubuntu xenial-updates/main amd64 Packages
     1.2.15ubuntu0.2 500
        500 http://192.168.10.7/ubuntu xenial-security/main amd64 Packages
     1.2.10ubuntu1 500
        500 http://192.168.10.7/ubuntu xenial/main amd64 Packages

Balint Reczey (rbalint) wrote :

@Brian: Thanks! Verbose/debug mode seems to cause the errors and possibly the inconsistent state, too, due to u-u crashing early.

The other case where you can still get an inconsistent state is when u-u takes more than 15 minutes to install all the packages in a way that it can't be interrupted in the last 5 minutes.

Do you have something in the logs to verify one of the theories?

Brian Murray (brian-murray) wrote :
Download full text (7.7 KiB)

Here's unattended-upgrades.log when the reboot did not cause an inconsistent state:

2017-07-26 08:33:37,462 INFO Initial blacklisted packages:
2017-07-26 08:33:37,463 INFO Initial whitelisted packages:
2017-07-26 08:33:37,463 INFO Starting unattended upgrades script
2017-07-26 08:33:37,463 INFO Allowed origins are: ['o=Ubuntu,a=xenial', 'o=Ubuntu,a=xenial-security', 'o=UbuntuESM,a=xenial']
2017-07-26 08:38:14,276 INFO Packages that will be upgraded: apparmor apport apport-gtk apt-transport-https bash bind9-host cpp-5 curl dbus dbus-x11 distro-info-data dnsutils eject evince evince-common firefox firefox-locale-en fonts-opensymbol g++-5 gcc-5 gcc-5-base ghostscript ghostscript-x gir1.2-gst-plugins-base-1.0 gir1.2-javascriptcoregtk-4.0 gir1.2-webkit2-4.0 gstreamer1.0-alsa gstreamer1.0-plugins-base gstreamer1.0-plugins-base-apps gstreamer1.0-plugins-good gstreamer1.0-pulseaudio gstreamer1.0-x imagemagick imagemagick-6.q16 imagemagick-common libapparmor-perl libapparmor1 libapt-inst2.0 libarchive13 libasan2 libasn1-8-heimdal libatomic1 libbind9-140 libc-bin libc-dev-bin libc6 libc6-dbg libc6-dev libcc1-0 libcilkrts5 libcurl3 libcurl3-gnutls libdbus-1-3 libdns-export162 libdns162 libevdocument3-4 libevent-2.0-5 libevview3-3 libexpat1 libfreetype6 libgc1c2 libgcc-5-dev libgcrypt20 libgd3 libgnutls-openssl27 libgnutls30 libgomp1 libgs9 libgs9-common libgssapi3-heimdal libgstreamer-plugins-base1.0-0 libgstreamer-plugins-good1.0-0 libhcrypto4-heimdal libheimbase1-heimdal libheimntlm0-heimdal libhogweed4 libhx509-5-heimdal libicu55 libisc-export160 libisc160 libisccc140 libisccfg140 libitm1 libjasper1 libjavascriptcoregtk-4.0-18 libjbig2dec0 libkrb5-26-heimdal libldap-2.4-2 liblightdm-gobject-1-0 liblsan0 liblwres141 libmagickcore-6.q16-2 libmagickcore-6.q16-2-extra libmagickwand-6.q16-2 libminiupnpc10 libmpx0 libmwaw-0.3-3 libnettle6 libnl-3-200 libnl-genl-3-200 libnm-glib-vpn1 libnm-glib4 libnm-gtk-common libnm-gtk0 libnm-util2 libnm0 libnma-common libnma0 libnspr4 libnss3 libnss3-nssdb liboxideqt-qmlplugin liboxideqtcore0 liboxideqtquick0 libpcsclite1 libpoppler-glib8 libpoppler58 libpython2.7 libpython2.7-minimal libpython2.7-stdlib libpython3.5 libpython3.5-minimal libpython3.5-stdlib libquadmath0 libreoffice-avmedia-backend-gstreamer libreoffice-base-core libreoffice-calc libreoffice-common libreoffice-core libreoffice-draw libreoffice-gnome libreoffice-gtk libreoffice-impress libreoffice-math libreoffice-ogltrans libreoffice-pdfimport libreoffice-style-breeze libreoffice-style-galaxy libreoffice-writer libroken18-heimdal librtmp1 libsmbclient libsndfile1 libssl1.0.0 libstdc++-5-dev libstdc++6 libtasn1-6 libtiff5 libtracker-sparql-1.0-0 libtsan0 libubsan0 libvncclient1 libwbclient0 libwebkit2gtk-4.0-37 libwebkit2gtk-4.0-37-gtk2 libwind0-heimdal libxml2 libxpm4 libxslt1.1 lightdm lintian linux-firmware linux-generic linux-headers-generic linux-image-generic linux-libc-dev locales login multiarch-support network-manager network-manager-gnome ntfs-3g openssl oxideqt-codecs passwd poppler-utils python2.7 python2.7-minimal python3-apport python3-cryptography python3-pil python3-problem-report python3-uno python3.5 python3.5-minimal samba-libs sudo ta...

Read more...

Balint Reczey (rbalint) wrote :

We discussed the test with Brian, and ending in inconsistent states can still occur when running u-u manually/via cron.

In those cases the apt fix does not protect dpkg from being terminated early.
When running u-u manually or via cron it is recommended to use workaround 3. from #19, i.e. running u-u like that:
 systemd-inhibit --what=shutdown,handle-hibernate-key --mode=block /usr/lib/

Balint Reczey (rbalint) wrote :

@Julian, @Michael: I think the timeout of 900 seconds should be increased to 1800 seconds and the 10 min delay in u-u-s should also be bumped to 25min.
Ethan experienced updates taking ~10 minutes over wifi. I believe updates will keep accumulating and are getting bigger, thus letting u-u run for 30 minutes before killing it seems to be a reasonable change to make u-u more future-proof.

Julian Andres Klode (juliank) wrote :

Downloads happen in a different service, so WiFi or not should not matter. The TERM signal is sent immediately anyway; after that, unattended-upgrades stops the upgrade. unattended-upgrade splits updates into small dpkg runs and that is what we are worrying about - not the time for a complete upgrade.

Julian Andres Klode (juliank) wrote :

Re inhibitor: unattended-upgrades should not inhibit shutdown generally. It should however do the inhibit thing per "transaction", if you know what I mean. This requires communicating with systemd via dbus I suppose.

Balint Reczey (rbalint) wrote :

@Julian: When running u-u at shutdown the expectation is that it runs to completion including the downloads (started by u-u-s).

When running in periodic mode triggered by apt's timer it finishes the transaction on TERM signal then it exits to let the shutdown continue. In this case you are right it does not perform the download and installation steps in the same service. In apt-daily-upgrade's case the 900 second is probably future-proof unless the machine/disk is very slow.

There are still installer packages which need downloads even during installation, but they are not updated very often.

Balint Reczey (rbalint) wrote :

Re inhibitor: One can run u-u --download-only from cron first without the inhibitor then the full u-u with the inhibitor. While this method does not allow per-transaction granularity, it is a fairly good solution without added complexity.
I someone comes up with a proper patch it may be integrated but I think this is out of the scope of this bug. The committed solution already provides the per-transaction stopping granularity when u-u is started by apt's service.

Balint Reczey (rbalint) wrote :

The problem causing apport's slow installation mentioned in https://bugs.launchpad.net/ubuntu/+source/unattended-upgrades/+bug/1690980/comments/37 seems to be LP: #1320403.

Brian Murray (brian-murray) wrote :

I test this again in the following manner, installed apt and unattended-upgrades from Balint's PPA, then modified /etc/apt/apt.conf.d/20auto-upgrades so that APT:Periodic::Unattended-Upgrade was "1". I then ran "sudo service apt-daily-upgrade start" and ran the u-u-reboot.sh script I've mentioned before.

After the reboot I ran 'sudo apt-get update' and 'sudo apt-get upgrade' which returned:

E: dpkg was interrupted, you must manually run 'sudo dpkg --configure -a' to correct the problem.

This is the problem we are trying to avoid. I'll attach /var/log/unattended-upgrades/unattended-upgrades.log and u-u-dpkg.log.

Brian Murray (brian-murray) wrote :

The dpkg log file too.

Balint Reczey (rbalint) wrote :

@Brian: It looks like blocking shutdown did work properly but the upgrade itself took longer than 15 minutes which is the current timeout. (see u-u.log)

I already filed a PR against u-u to bump the timeout to 30 mins: https://github.com/mvo5/unattended-upgrades/pull/69 , but in this case apt's timer kicks in (@Julian).

Balint Reczey (rbalint) wrote :

For being on the safe side on slow machines I would bump the timeout even higher.
I'll also file a PR setting --minimal-upgrade-steps the default which will allow upgrading in transactions by default.

Balint Reczey (rbalint) wrote :

I've filed the PR to default to minimal steps fixing a few related issues:
https://github.com/mvo5/unattended-upgrades/pull/70

@Brian: This should really work in your tests leaving a consistent system behind on shutdown.

ethan.hsieh (ethan.hsieh) wrote :

@Balint

I tried three times, and 0.95-16.04.0rbalint1 didn't work well.

Please refer to attached file for detailed log.

1) Reboot system when unattended upgrades starts to download packages.
//unattended-upgrades.log
2017-08-08 15:34:07,782 INFO Starting unattended upgrades script
2017-08-08 15:34:07,782 INFO Allowed origins are: ['o=Ubuntu,a=xenial', 'o=Ubuntu,a=xenial-security', 'o=UbuntuESM,a=xenial']
//unattended-upgrades-shutdown.log
2017-08-08 15:36:06,358 INFO - All upgrades installed

The log shows "All upgrades installed", but there is no package installed.

2) Reboot system after unattended upgrades downloads packages for 5mins
//unattended-upgrades.log
2017-08-08 15:55:27,907 INFO Starting unattended upgrades script
2017-08-08 15:55:27,907 INFO Allowed origins are: ['o=Ubuntu,a=xenial', 'o=Ubuntu,a=xenial-security', 'o=UbuntuESM,a=xenial']

System reboots immediately. There is no unattended-upgrades-shutdown log.

3) Reboot system when unattended upgrades starts to download packages.
//unattended-upgrades.log
2017-08-08 16:09:03,548 INFO Starting unattended upgrades script
2017-08-08 16:09:03,549 INFO Allowed origins are: ['o=Ubuntu,a=xenial', 'o=Ubuntu,a=xenial-security', 'o=UbuntuESM,a=xenial']
//unattended-upgrades-shutdown.log
2017-08-08 16:10:50,573 INFO - All upgrades installed

The log shows "All upgrades installed", but there is no package installed.

---
The installed packages:
apt_1.2.25-rbalint2_amd64.deb
apt-doc_1.2.25-rbalint2_all.deb
apt-transport-https_1.2.25-rbalint2_amd64.deb
apt-utils_1.2.25-rbalint2_amd64.deb
libapt-inst2.0_1.2.25-rbalint2_amd64.deb
libapt-pkg5.0_1.2.25-rbalint2_amd64.deb
libapt-pkg-doc_1.2.25-rbalint2_all.deb
unattended-upgrades_0.95-16.04.0rbalint1_all.deb

Balint Reczey (rbalint) wrote :

@Ethan Yes, the "All upgrades installed" message is still misleading.

Note however that there are two modes of u-u you can operate in on shutdown and they are picked by setting Unattended-Upgrade::InstallOnShutdown.

When it is set to True u-u runs to completion (unless it times out after 15 minutes).

In the other case (set to false) shutdown gracefully terminates u-u with the current fixes possibly (and probably) not installing every update. In that case the message is clearly misleading.

I'm updating the message, but I believe that this is how u-u is expected to operate.

On Tue, Aug 08, 2017 at 08:53:48AM -0000, ethan.hsieh wrote:
> @Balint
>
> I tried three times, and 0.95-16.04.0rbalint1 didn't work well.
>
> Please refer to attached file for detailed log.
>
> 1) Reboot system when unattended upgrades starts to download packages.
> //unattended-upgrades.log
> 2017-08-08 15:34:07,782 INFO Starting unattended upgrades script
> 2017-08-08 15:34:07,782 INFO Allowed origins are: ['o=Ubuntu,a=xenial', 'o=Ubuntu,a=xenial-security', 'o=UbuntuESM,a=xenial']
> //unattended-upgrades-shutdown.log
> 2017-08-08 15:36:06,358 INFO - All upgrades installed
>
> The log shows "All upgrades installed", but there is no package
> installed.
>
> 2) Reboot system after unattended upgrades downloads packages for 5mins
> //unattended-upgrades.log
> 2017-08-08 15:55:27,907 INFO Starting unattended upgrades script
> 2017-08-08 15:55:27,907 INFO Allowed origins are: ['o=Ubuntu,a=xenial', 'o=Ubuntu,a=xenial-security', 'o=UbuntuESM,a=xenial']
>
> System reboots immediately. There is no unattended-upgrades-shutdown
> log.
>
> 3) Reboot system when unattended upgrades starts to download packages.
> //unattended-upgrades.log
> 2017-08-08 16:09:03,548 INFO Starting unattended upgrades script
> 2017-08-08 16:09:03,549 INFO Allowed origins are: ['o=Ubuntu,a=xenial', 'o=Ubuntu,a=xenial-security', 'o=UbuntuESM,a=xenial']
> //unattended-upgrades-shutdown.log
> 2017-08-08 16:10:50,573 INFO - All upgrades installed
>
> The log shows "All upgrades installed", but there is no package
> installed.

Keep in mind there is also the log file
/var/log/unattended-upgrades/unattended-upgrades-dpkg.log which contains
detailed information about the packages being installed.

--
Brian Murray

Launchpad Janitor (janitor) wrote :

This bug was fixed in the package apt - 1.5~rc1~ubuntu1

---------------
apt (1.5~rc1~ubuntu1) artful; urgency=medium

  * Redefine APT_CONST to mean APT_PURE
  * Replace APT_CONST with APT_PURE everywhere
  * Make test-bug-818628-unreadable-source work on !amd64

 -- Julian Andres Klode <email address hidden> Thu, 24 Aug 2017 17:56:28 +0200

Changed in apt (Ubuntu):
status: Fix Committed → Fix Released
Julian Andres Klode (juliank) wrote :

Correct changelog:

apt (1.5~beta2) unstable; urgency=medium

  [ M. Willis Monroe ]
  * Minor grammar fix

  [ Zhou Mo ]
  * zh_CN.po: update Simplified Chinese programs translation

  [ David Kalnischkies ]
  * don't expect more downloads from failed transactions
  * remove reference to a-t-debtorrent in description
  * ignore SIGPIPE in dump solver if forwarding
  * support compressed extended_states file for bug triage
  * don't move failed pdiff indexes out of partial (Closes: 869425)
  * don't try to parse all fields starting with HTTP as status-line
  * send weak-only hashes to methods
  * fail earlier if server answers with too much data
  * fail early in http if server answer is too small as well
  * use FileFd to parse all apt configuration files
  * show warnings instead of errors if files are unreadable (LP: #1701852)
  * reimplement and document auth.conf (Closes: #811181)
  * lookup login info for proxies in auth.conf
  * allow the auth.conf to be root:root owned
  * update URI scheme descriptions in sources.list(5)
  * show a warning for Debian shutting down FTP services
  * suggest using auth.conf for sources with passwords
  * ftparchive: sort discovered filenames before writing indexes.
    Thanks to Chris Lamb for initial patch & Stefan Lippers-Hollmann for testing
    (Closes: 869557)
  * don't keep configuration files open needlessly
  * don't hang if multiple sources use unavailable method (Closes: 870675)

  [ Beatrice Torracca ]
  * Italian manpage translation update (Closes: 858877)

  [ Apollon Oikonomopoulos ]
  * Handle supported components with slashes in sources.list (Closes: #868127)

  [ Julian Andres Klode ]
  * Drop cacheiterators.h include
  * methods/aptmethod.h: Add missing fileutl.h include
  * Reformat and sort all includes with clang-format
  * cacheiterators: Warn about direct include and don't include pkgcache.h
  * Update gitignore with new files
  * Use C++11 threading support instead of pthread
  * Always warn if --force-yes is validly specified, not just if used
  * Work around float rounding change in gcc 7 on i386
  * Handle GCC 7 std::string operator ABI break (Closes: #871275)
  * debian: Update symbols for libapt-pkg5.0

  [ Paul Wise ]
  * Support zero delay for the various APT::Periodic activities
  * Support seconds, minutes, hours and days for APT::Periodic intervals
  * Switch from /org to /srv in example apt-ftparchive configuration

  [ Balint Reczey ]
  * Gracefully terminate process when stopping apt-daily-upgrade (LP: #1690980)

  [ Dominik ]
  * doc: Add '--allow-unauthenticated' to '--force-yes'

 -- Julian Andres Klode <email address hidden> Thu, 17 Aug 2017 19:28:00 +0200

(sorry, I did not generate the .changes file against 1.5~beta1...).

Launchpad Janitor (janitor) wrote :
Download full text (3.5 KiB)

This bug was fixed in the package unattended-upgrades - 0.96ubuntu1

---------------
unattended-upgrades (0.96ubuntu1) artful; urgency=low

  * Merge from Debian unstable (LP: #1714019)
    - Remaining changes:
      - Recover from broken dh_installinit override in versions < 0.93.1ubuntu3
      - unattended-upgrades: Do not automatically upgrade the development
        release of Ubuntu unless Unattended-Upgrade::DevRelease is true.
    - Dropped changes, included in Debian:
      - Cherry-pick 2e5deed, f26edb4 from upstream to add support for a
        --download-only option, enabling us to download updates at a random
        time of day by default but apply them predictably in the 6am-7am
        window.
      - Fix PEP8 failures (replace except: with except Exception:)
      - unattended-upgrades: Provide some information and create a log entry
        when there is a failure to parse the allowed origins.
      - Add UbuntuESM to the list of sources automatically upgraded from by
        default.
      - Complete the solution for the unattended-upgrades.service unit not
        correctly working
      - d/rules : Remove the override_dh_installinit. The stop option is no
        longer available so the command falls back to default. This is the
        normal behavior so the override is not required
      - d/unattended-upgrades.init : Add Default-Start runlevels, otherwise
        the unattended-upgrades.service unit cannot be enabled on boot
      - d/postinst : Cleanup the stop symlinks created by the wrong
        override_dh_installinit. Without that, the systemd unit cannot be
        enabled correctly.
        Force disable the service before deb-systemd-helper runs so the old
        symlink is not left dangling (workaround for Debian Bug #797108).
        Force enable and start of the systemd unit to work around Debian Bug
        #797108 which fails to enable systemd units correctly when
        WantedBy= statement is changed which is the case here.
      - d/unattended-upgrades.service : Fix the service so it runs correctly on
        shutdown :
        - Remove DefaultDependencies=no : Breaks normal shutdown dependencies
        - Set After= to network.target and local-fs.target. Since our service
          is now ExecStop, it will run before network and local-fs become
          unavailable.
        - Add RequiresMountsFor=/var/log /var/run /var/lib /boot : Necessary if
          /var is a separate file system. Set WantedBy= to multi-user.target
      - Add DEP8 tests to verify the following :
        - Verify that the unattended-upgrades.service unit is enabled and
          started.
        - Verify that InstallOnShutdown works when configured.
      - The systemd unit needs to be an ExecStop since it is is activated on
        shutdown. Otherwise, it will get scheduled after completion of
        the local-fs.target. In the case where /var is a separate
        filesystem, unattended-upgrade-shutdown will hang until timeout
        since /var/run is expected but no longer there
      - When performing a sanity check for packages to install or upgrade
        return false when either there are no packages in the cache or th...

Read more...

Changed in unattended-upgrades (Ubuntu):
status: Fix Committed → Fix Released
Balint Reczey (rbalint) wrote :

@Ethan: I have uploaded unattended-upgrades_0.96ubuntu1~16.04.1 for testing to https://launchpad.net/~rbalint/+archive/ubuntu/scratch , too.

Balint Reczey (rbalint) wrote :

@Ethan: Re: ping over IRC, yes, please apt_1.2.25-rbalint2 for testing u-u.

When Unattended-Upgrade::InstallOnShutdown is set u-u should also work properly with apt 1.2.24 from -updates.

Changed in apt (Ubuntu Xenial):
status: New → Incomplete
status: Incomplete → Triaged
Changed in apt (Ubuntu Zesty):
status: New → Triaged
Changed in apt (Ubuntu):
importance: Undecided → Critical
Changed in apt (Ubuntu Zesty):
importance: Undecided → Critical
Changed in apt (Ubuntu Xenial):
importance: Undecided → Critical
ethan.hsieh (ethan.hsieh) wrote :

@Balint

Here is my test result: (InstallOnShutdown:true)

Packages will be installed when rebooting system.
I rebooted system five times, but system still didn't finish the update.
It took too long to finish online update.

Timestamp: (reboot system)
1. 2017-09-14 13:57:00,998
2. 2017-09-14 14:32:26,172
3. 2017-09-14 15:20:41,267
4. 2017-09-14 16:00:18,694
5. 2017-09-14 16:36:47,174
(Please check full log as attached)

$ apt-config dump
Unattended-Upgrade::InstallOnShutdown "true";

Installed packages:
apt_1.2.25-rbalint2_amd64.deb
apt-doc_1.2.25-rbalint2_all.deb
apt-transport-https_1.2.25-rbalint2_amd64.deb
apt-utils_1.2.25-rbalint2_amd64.deb
libapt-inst2.0_1.2.25-rbalint2_amd64.deb
libapt-pkg5.0_1.2.25-rbalint2_amd64.deb
libapt-pkg-doc_1.2.25-rbalint2_all.deb
unattended-upgrades_0.96ubuntu1-16.04.1_all.deb

Balint Reczey (rbalint) wrote :

@Ethan,

On Thu, Sep 14, 2017 at 12:04 PM, ethan.hsieh <email address hidden> wrote:
> @Balint
>
> Here is my test result: (InstallOnShutdown:true)
>
> Packages will be installed when rebooting system.
> I rebooted system five times, but system still didn't finish the update.
> It took too long to finish online update.
>
> Timestamp: (reboot system)
> 1. 2017-09-14 13:57:00,998
> 2. 2017-09-14 14:32:26,172
> 3. 2017-09-14 15:20:41,267
> 4. 2017-09-14 16:00:18,694
> 5. 2017-09-14 16:36:47,174
> (Please check full log as attached)

Thanks for the tests, there are several interesting things in it.

The first one is that upgrades took very long time and I opened an
upstream issue for that:
https://github.com/mvo5/unattended-upgrades/issues/76

The second is that u-u properly blocks shutdown so this bug seems to
be fixed for the tested case.

The third is the presence of the crash file in 3/ which is a result of
killing u-u --download and it is normal, thus u-u should not generate
it.
I'll fix that separately.

ethan.hsieh (ethan.hsieh) wrote :

@Balint

Here is another test result for InstallOnShutdown:false

Log: 2017-09-14 17:20:14 ~ 2017-09-15 00:00:03
It took 6~7 hours to finish online update. (Packages: around 700mb)

unattended-upgrades.log
// Online update was triggered.
2017-09-14 17:15:03,561 INFO Allowed origins are: ['o=Ubuntu,a=xenial', 'o=Ubuntu,a=xenial-security', 'o=UbuntuESM,a=xenial']
// Reboot system manually
2017-09-14 18:07:49,988 WARNING SIGTERM received, will stop
// Online udpate didn't be finished. apt-daily-upgrade triggerred it again.
2017-09-14 18:16:29,208 INFO Allowed origins are: ['o=Ubuntu,a=xenial', 'o=Ubuntu,a=xenial-security', 'o=UbuntuESM,a=xenial']
(Please check full log as attached)

$ grep -r -e "Install" 50unattended-upgrades
// Install all unattended-upgrades when the machine is shutting down
//Unattended-Upgrade::InstallOnShutdown "true";

Installed packages:
apt_1.2.25-rbalint2_amd64.deb
apt-doc_1.2.25-rbalint2_all.deb
apt-transport-https_1.2.25-rbalint2_amd64.deb
apt-utils_1.2.25-rbalint2_amd64.deb
libapt-inst2.0_1.2.25-rbalint2_amd64.deb
libapt-pkg5.0_1.2.25-rbalint2_amd64.deb
libapt-pkg-doc_1.2.25-rbalint2_all.deb
unattended-upgrades_0.96ubuntu1-16.04.1_all.deb

Balint Reczey (rbalint) wrote :

@Ethan: Thanks for the test and the logs.

Those show that the fix works but the move to minimal steps slowed down u-u a lot. I tried fixing the slowdown by finishing the concept of pre-calculating the steps then performing them but IMO this direction is not safe and can potentially leave packages not-upgraded due to inter-dependencies between pre-calculated upgrade steps:
https://github.com/mvo5/unattended-upgrades/tree/feature/minimal-upgrades-speedup2

I'm now profiling u-u instead to find where the slowdown is coming from and try fixing that instead of pre-calculating the steps.

Balint Reczey (rbalint) wrote :

It is also worth noting that users should rarely meet such slow upgrade as the number of packages to upgrade with each run is usually much lower.

Balint Reczey (rbalint) wrote :

@Ethan Based on profiling real-life scenario (updating unstable with 100+ packages) I believe I was able to make u-u ~10 > times faster that should bring down the time of your test of upgrading xenial with all security updates to below one hour.
Since running only dpkg's part took more than 30 minutes I think this state is good for Artful and for backporting the fixes to older releases.
I've set up a separate PPA for u-u testing if you would like to verify the speedup & other fixes:
https://launchpad.net/~rbalint/+archive/ubuntu/unattended-upgrades

ethan.hsieh (ethan.hsieh) wrote :

@Balint

Here is test result for InstallOnShutdown:true

"Errors were encountered while processing: apport"
u-u still has packages to upgrade after this issue happens.
So, when I reboot system every time, u-u still tries to upgrade package.
We expect that there are 30 mins to do the update.
But, dependency problem will prevent u-u from upgrading packages.

1. unattended-upgrades-shutdown.log: (Please check full log as attached)
----------------
2017-09-22 14:54:25,865 WARNING - Running unattended-upgrades in shutdown mode
14:54:25~14:55:54 => 1:29, u-u only takes 1:29 to upgrade packges.
2017-09-22 14:57:02,183 WARNING - Running unattended-upgrades in shutdown mode
14:57:02~14:58:30 => 1:28
2017-09-22 15:00:00,233 WARNING - Running unattended-upgrades in shutdown mode
15:00:00~15:01:28 => 1:28
----------------

2. unattended-upgrades-dpkg.log:
----------------
Log started: 2017-09-22 14:34:24
...
Preparing to unpack .../apport_2.20.1-0ubuntu2.10_all.deb ...
Failed to get load state of apport-forward.socket: Connection reset by peer
2017-09-22 14:37:26,769 WARNING SIGTERM received, will stop
Log ended: 2017-09-22 14:37:26
----------------

Installed packages:
apt (1.2.25-rbalint2)
unattended-upgrades_0.96ubuntu1-16.04.1_all.deb

ethan.hsieh (ethan.hsieh) wrote :

typo... u-u in #73 should be 0.97ubuntu1~16.04.1

ethan.hsieh (ethan.hsieh) wrote :

@Balint

Here is test result for InstallOnShutdown:false

Timestamp:
1. 13:25:10~13:40:32: 15mins
2. reboot system
3. 14:59:17~16:44:18: 1hr45mins
Total: 2hr

Comparing to the test result in #69, 0.97ubuntu1~16.04.1 saves 4~5 hours.

Log: Please check full log as attached.

Installed packages:
apt (1.2.25-rbalint2)
unattended-upgrades_0.97ubuntu1~16.04.1_all.deb

Balint Reczey (rbalint) wrote :

@Ethan

On Fri, Sep 22, 2017 at 9:29 AM, ethan.hsieh <email address hidden> wrote:
> @Balint
>
> Here is test result for InstallOnShutdown:true
>
> "Errors were encountered while processing: apport"
> u-u still has packages to upgrade after this issue happens.
> So, when I reboot system every time, u-u still tries to upgrade package.
> We expect that there are 30 mins to do the update.
> But, dependency problem will prevent u-u from upgrading packages.
>
> 1. unattended-upgrades-shutdown.log: (Please check full log as attached)
> ----------------
> 2017-09-22 14:54:25,865 WARNING - Running unattended-upgrades in shutdown mode
> 14:54:25~14:55:54 => 1:29, u-u only takes 1:29 to upgrade packges.
> 2017-09-22 14:57:02,183 WARNING - Running unattended-upgrades in shutdown mode
> 14:57:02~14:58:30 => 1:28
> 2017-09-22 15:00:00,233 WARNING - Running unattended-upgrades in shutdown mode
> 15:00:00~15:01:28 => 1:28
> ----------------
>
> 2. unattended-upgrades-dpkg.log:
> ----------------
> Log started: 2017-09-22 14:34:24
> ...
> Preparing to unpack .../apport_2.20.1-0ubuntu2.10_all.deb ...
> Failed to get load state of apport-forward.socket: Connection reset by peer
> 2017-09-22 14:37:26,769 WARNING SIGTERM received, will stop
> Log ended: 2017-09-22 14:37:26
> ----------------

Thanks for the tests and the logs!
It looks like this is an apport issue and u-u can't do much about it.
I think upgrading services _during shutdown_ is something they are
generally not prepared for and to support InstallOnShutdown:true
system-wide packages need to be tested and be prepared with that
scenario in mind.

Balint Reczey (rbalint) wrote :

@Ethan

On Fri, Sep 22, 2017 at 12:21 PM, ethan.hsieh <email address hidden> wrote:
> @Balint
>
> Here is test result for InstallOnShutdown:false
>
> Timestamp:
> 1. 13:25:10~13:40:32: 15mins
> 2. reboot system
> 3. 14:59:17~16:44:18: 1hr45mins
> Total: 2hr
>
> Comparing to the test result in #69, 0.97ubuntu1~16.04.1 saves 4~5
> hours.
>
> Log: Please check full log as attached.

Thanks! looking at the logs there is still some room for improvements
and I have some in my mind but they are more risky and should be
applied after Artful's release.

Changed in apt (Ubuntu Zesty):
status: Triaged → In Progress

Hello ethan.hsieh, or anyone else affected,

Accepted apt into zesty-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/apt/1.4.8 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed.Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested and change the tag from verification-needed-zesty to verification-done-zesty. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-zesty. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

Changed in apt (Ubuntu Zesty):
status: In Progress → Fix Committed
tags: added: verification-needed verification-needed-zesty
description: updated
Changed in apt (Ubuntu Xenial):
status: Triaged → In Progress
Timo Aaltonen (tjaalton) wrote :

Hello ethan.hsieh, or anyone else affected,

Accepted apt into xenial-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/apt/1.2.25 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed.Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested and change the tag from verification-needed-xenial to verification-done-xenial. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-xenial. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

Changed in apt (Ubuntu Xenial):
status: In Progress → Fix Committed
tags: added: verification-needed-xenial
tags: added: id-596781a4fd7307546010c061
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

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