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

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

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

@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.

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.

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?

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.

@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.

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.

@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

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

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.

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!

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

@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.

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.

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

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.

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.

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.]

@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.

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.

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'.

@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.

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.

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
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 %

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.

The new set of commits for u-u are in https://github.com/rbalint/unattended-upgrades/commits/master

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).

@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.

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

@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?

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.

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.

@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

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.

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.

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

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

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

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

@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?

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...

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/

@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.

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.

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.

@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.

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.

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.

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.

The dpkg log file too.

@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).

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.

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.

@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

@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

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

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...).

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...

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

@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.

@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

@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.

@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

@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.

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.

@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

@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

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

@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

@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.

@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.

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!

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!

It would be great if someone else could verify the SRUs for xenial and zesty? I don't have full VMs lying around to start / stop the service. (I have a dual boot (x)ubuntu on my HDD, but that's slow, and only one) We really should get these updates out of the door soon, /me thinks.

I booted my xenial system in a VM, and tried to verify it; but:

The hierarchy of apt-daily-upgrade.service is:

apt.system.daily install
 - apt.systemd.daily lock_is_held install
   - unattended-upgrades

only the top-level process is terminated. Manually sending SIGTERM to unattended-upgrades makes it exit; but it seems the SIGTERM is not forwarded through the shells.

The result is simple: The big lock protecting against update and co is released (not that problematic), but upgrades are never stopped. I'm not sure if systemd still waits for the runaway processes on shutdown; if that's the case, then it sort of works. We'd have to verify that somehow.

So, if we want to have a time out working, we have to get rid of the shell script it seems. Which sucks a lot.

A work around would be to invoke subprocesses using:

_term() {
  kill -TERM "$child" 2>/dev/null
}

trap _term SIGTERM

run() {
    "$@" &
    child="$!"
    wait "$child"
}

Ubuntu 17.04 has reached end of life. No further bugfixes will be applied to this version.

I don't see anything here left to sponsor so I'm unsubscribing the sponsors team.

The apt side should be OK. But it depends on interaction with other services, so it cannot be reliably tested on its own I guess.

We'll get a better fix eventually that makes the apt side work better by making it wait on the upgrade itself.

Currently, we basically stop the controlling script; and then u-u continues running and the shutdown is blocked by u-u.service waiting for it

This bug was fixed in the package apt - 1.2.25

---------------
apt (1.2.25) xenial; urgency=medium

  * Microrelease covering 1.4.7 (LP: #1702326) and 1.4.8

  [ Robert Luberda ]
  * fix a "critical" typo in old changelog entry (Closes: 866358)

  [ David Kalnischkies ]
  * use port from SRV record instead of initial port
  * don't ask an uninit _system for supported archs (LP: #1613184)

  [ Julian Andres Klode ]
  * Reset failure reason when connection was successful
  * http: A response with Content-Length: 0 has no content
  * apt-daily: Pull in network-online.target in service, not timer
    (LP: #1716973)

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

 -- Julian Andres Klode <email address hidden> Tue, 26 Sep 2017 16:14:54 +0200

The verification of the Stable Release Update for apt has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

Hello ethan.hsieh, or anyone else affected,

Accepted unattended-upgrades into xenial-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/unattended-upgrades/1.1ubuntu1.18.04.7~16.04.0 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, without details of your testing we will not be able to proceed.

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

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

Hello ethan.hsieh, or anyone else affected,

Accepted unattended-upgrades into xenial-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/unattended-upgrades/1.1ubuntu1.18.04.7~16.04.1 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, without details of your testing we will not be able to proceed.

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

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

Hello ethan.hsieh, or anyone else affected,

Accepted unattended-upgrades into xenial-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/unattended-upgrades/1.1ubuntu1.18.04.7~16.04.2 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, without details of your testing we will not be able to proceed.

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

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

Tested 1.1ubuntu1.18.04.7~16.04.2 on Xenial:

root@x-uu-lp-1690980:~# tail -f /var/log/unattended-upgrades/unattended-upgrades.log
2019-04-09 13:08:24,515 INFO Initial blacklisted packages:
2019-04-09 13:08:24,516 INFO Initial whitelisted packages:
2019-04-09 13:08:24,516 INFO Starting unattended upgrades script
2019-04-09 13:08:24,516 INFO Allowed origins are: ['o=Ubuntu,a=xenial', 'o=Ubuntu,a=xenial-security', 'o=UbuntuESM,a=xenial', 'o=Ubuntu,a=xenial-updates']
2019-04-09 15:01:44,987 INFO Initial blacklisted packages:
2019-04-09 15:01:44,988 INFO Initial whitelisted packages:
2019-04-09 15:01:44,988 INFO Starting unattended upgrades script
2019-04-09 15:01:44,988 INFO Allowed origins are: o=Ubuntu,a=xenial, o=Ubuntu,a=xenial-security, o=UbuntuESM,a=xenial, o=Ubuntu,a=xenial-updates
2019-04-09 15:02:06,773 INFO Packages that will be upgraded: adwaita-icon-theme dirmngr fontconfig fontconfig-config gir1.2-gdkpixbuf-2.0 gir1.2-gtk-3.0 glib-networking glib-networking-common glib-networking-services gnupg-agent gnupg2 gstreamer1.0-plugins-base gstreamer1.0-plugins-good gstreamer1.0-pulseaudio gstreamer1.0-x hicolor-icon-theme humanity-icon-theme hwdata libarchive13 libavahi-client3 libavahi-common-data libavahi-common3 libboost-filesystem1.58.0 libboost-iostreams1.58.0 libboost-system1.58.0 libcaca0 libcups2 libdrm-amdgpu1 libdrm-intel1 libdrm-nouveau2 libdrm-radeon1 libegl1-mesa libepoxy0 libexempi3 libfontconfig1 libgbm1 libgd3 libgdk-pixbuf2.0-0 libgdk-pixbuf2.0-common libgl1-mesa-dri libgl1-mesa-glx libglapi-mesa libgraphite2-3 libgstreamer-plugins-base1.0-0 libgstreamer-plugins-good1.0-0 libgstreamer1.0-0 libgtk-3-0 libgtk-3-bin libgtk-3-common libharfbuzz0b libinput10 libjpeg-turbo8 libksba8 liblcms2-2 libllvm3.8 libmirclient9 libmirprotobuf3 libnautilus-extension1a libnspr4 libnss3 libnss3-nssdb libpam-systemd libpulse0 libsane libsane-common libsndfile1 libsoup-gnome2.4-1 libsoup2.4-1 libsystemd0 libtiff5 libtracker-sparql-1.0-0 libudev1 libvorbis0a libvorbisenc2 libwacom-bin libwacom-common libwacom2 libwavpack1 libwayland-client0 libwayland-cursor0 libwayland-egl1-mesa libwayland-server0 libx11-xcb1 libxcursor1 libxkbcommon0 libxpm4 systemd systemd-sysv ubuntu-mono udev wget x11-common
2019-04-09 15:02:06,774 INFO Writing dpkg log to /var/log/unattended-upgrades/unattended-upgrades-dpkg.log
^C
root@x-uu-lp-1690980:~# dbus-send --system --print-reply --dest=org.freedesktop.login1 /org/freedesktop/login1 "org.freedesktop.login1.Manager.Reboot" boolean:false
method return time=1554822131.758122 sender=:1.1 -> destination=:1.7 serial=33 reply_serial=2
root@x-uu-lp-1690980:~#
root@x-uu-lp-1690980:~# tail -f /var/log/unattended-upgrades/unattended-upgrades.log
2019-04-09 13:08:24,516 INFO Allowed origins are: ['o=Ubuntu,a=xenial', 'o=Ubuntu,a=xenial-security', 'o=UbuntuESM,a=xenial', 'o=Ubuntu,a=xenial-updates']
2019-04-09 15:01:44,987 INFO Initial blacklisted packages:
2019-04-09 15:01:44,988 INFO Initial whitelisted packages:
2019-04-09 15:01:44,988 INFO Starting unattended upgrades script
2019-04-09 15:01:44,988 INFO Allowed origins are: o=Ubuntu,a=xenial, o=Ubuntu,a=xenial-security, o=UbuntuESM,a=xenial, o=Ubuntu,a=xenial-upda...

This bug was fixed in the package unattended-upgrades - 1.1ubuntu1.18.04.7~16.04.2

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

  * Don't check blacklist too early and report updates from not allowed origins
    as kept back. (LP: #1781176)
  * test/test_blacklisted_wrong_origin.py: Fix and enable test
  * Filter out progress indicator from dpkg log (LP: #1599646)
  * Clear cache when autoremoval fails (LP: #1779157)
  * Find autoremovable kernel packages using the patterns in APT's way
    (LP: #1815494)

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

  * Start service after systemd-logind.service to be able to take inhibition
    lock (LP: #1806487)
  * Handle gracefully when logind is down (LP: #1806487)

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

  * Backport to Xenial (LP: #1702793)
  * Revert to build-depending on debhelper (>= 9~) and dh-systemd
  * Revert configuration example changes to avoid triggering a debconf question
  * debian/postinst: Update recovery to be triggered on Xenial's package versions

unattended-upgrades (1.1ubuntu1.18.04.7) bionic; urgency=medium

  * Trigger unattended-upgrade-shutdown actions with PrepareForShutdown()
    Performing upgrades in service's ExecStop did not work when the upgrades
    involved restarting services because systemd blocked other stop/start
    actions making maintainer scripts time out and be killed leaving a broken
    system behind.
    Running unattended-upgrades.service before shutdown.target as a oneshot
    service made it run after unmounting filesystems and scheduling services
    properly on shutdown is a complex problem and adding more services to the
    mix make it even more fragile.
    The solution of monitoring PrepareForShutdown() signal from DBus
    allows Unattended Upgrade to run _before_ the jobs related to shutdown are
    queued thus package upgrades can safely restart services without
    risking causing deadlocks or breaking part of the shutdown actions.
    Also ask running unattended-upgrades to stop when shutdown starts even in
    InstallOnShutdown mode and refactor most of unattended-upgrade-shutdown to
    UnattendedUpgradesShutdown class. (LP: #1778219)
  * Increase logind's InhibitDelayMaxSec to 30s. (LP: #1778219)
    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 node are advised to increase
    InhibitDelayMaxSec even further possibly to 30 minutes.
    - Add NEWS entry about increasing InhibitDelayMaxSec and InstallOnShutdown
      changes
  * Ignore "W503 line break before binary operator"
    because it will become the best practice and breaks the build
  * Stop using ActionGroups, they interfere with apt.Cache.clear()
    causing all autoremovable packages to be handled as newly autoremovable
    ones and be removed by default. Dropping ActionGroup usage does not slow
    down the most frequent case of not having anything to upgrade a...