[Bug 1602536] Re: /usr/bin/unattended-upgrade:apt.cache.LockFailedException:/usr/bin/unattended-upgrade at 1468:main:do_auto_remove:cache_commit:commit:_fetch_archives

[Balint Reczey]

Verified with 1.1ubuntu1.18.04.1:

Log from shell "A":
rbalint at xenial-test:~$ lxc exec bb-uu-fixed -- bash
root at bb-uu-fixed:~# unattended-upgrade --dry-run --verbose
Initial blacklisted packages: 
Initial whitelisted packages: 
Starting unattended upgrades script
Allowed origins are: o=Ubuntu,a=bionic, o=Ubuntu,a=bionic-security, o=UbuntuESM,a=bionic
Option --dry-run given, *not* performing real actions
Packages that will be upgraded: libgcrypt20 libssl1.0.0 libssl1.1 openssl
Writing dpkg log to /var/log/unattended-upgrades/unattended-upgrades-dpkg.log
/usr/bin/dpkg --status-fd 9 --no-triggers --unpack --auto-deconfigure /var/cache/apt/archives/libgcrypt20_1.8.1-4ubuntu1.1_amd64.deb 
/usr/bin/dpkg --status-fd 9 --no-triggers --configure libgcrypt20:amd64 
/usr/bin/dpkg --status-fd 9 --configure --pending 
Preconfiguring packages ...
/usr/bin/dpkg --status-fd 9 --no-triggers --unpack --auto-deconfigure /var/cache/apt/archives/libssl1.0.0_1.0.2n-1ubuntu5.1_amd64.deb 
/usr/bin/dpkg --status-fd 9 --configure --pending 
Preconfiguring packages ...
/usr/bin/dpkg --status-fd 9 --no-triggers --unpack --auto-deconfigure /var/cache/apt/archives/libssl1.1_1.1.0g-2ubuntu4.1_amd64.deb 
/usr/bin/dpkg --status-fd 9 --configure --pending 
/usr/bin/dpkg --status-fd 9 --no-triggers --unpack --auto-deconfigure /var/cache/apt/archives/openssl_1.1.0g-2ubuntu4.1_amd64.deb 
/usr/bin/dpkg --status-fd 9 --configure --pending 
All upgrades installed

Attaching log for shell "B", since it is quite long.
In the attached log it can be observed that the lock is still lost by u-u for small windows (due to python-apt losing it), but u-u then reacquires it, which is what the fix for u-u should do.

Unfixed unattended-upgrades 1.1ubuntu1, shell "B":

root at bb-uu:~# while sleep 0.3; do python3 -c 'import apt; import apt_pkg; print(apt_pkg.pkgsystem_lock())' ; done
True
True
True
True
True
True
True
True
True
True
True
True
True
True
True
Traceback (most recent call last):
  File "<string>", line 1, in <module>
apt_pkg.Error: E:Could not get lock /var/lib/dpkg/lock - open (11: Resource temporarily unavailable), E:Unable to lock the administration directory (/var/lib/dpkg/), is another process using it?
Traceback (most recent call last):
  File "<string>", line 1, in <module>
apt_pkg.Error: E:Could not get lock /var/lib/dpkg/lock - open (11: Resource temporarily unavailable), E:Unable to lock the administration directory (/var/lib/dpkg/), is another process using it?
Traceback (most recent call last):
  File "<string>", line 1, in <module>
apt_pkg.Error: E:Could not get lock /var/lib/dpkg/lock - open (11: Resource temporarily unavailable), E:Unable to lock the administration directory (/var/lib/dpkg/), is another process using it?
Traceback (most recent call last):
  File "<string>", line 1, in <module>
apt_pkg.Error: E:Could not get lock /var/lib/dpkg/lock - open (11: Resource temporarily unavailable), E:Unable to lock the administration directory (/var/lib/dpkg/), is another process using it?
Traceback (most recent call last):
  File "<string>", line 1, in <module>
apt_pkg.Error: E:Could not get lock /var/lib/dpkg/lock - open (11: Resource temporarily unavailable), E:Unable to lock the administration directory (/var/lib/dpkg/), is another process using it?
True
True
True
True
True
True
True
True
True
True
True
True
True
True
True
True
True
True
True
True
True
^C
root at bb-uu:~# exit

In the unfixed version u-u just loses the lock.

** Attachment added: "u-u-1.1ubuntu1.18.04.1-shell-B.log"
   https://bugs.launchpad.net/ubuntu/+source/unattended-upgrades/+bug/1602536/+attachment/5162110/+files/u-u-1.1ubuntu1.18.04.1-shell-B.log

** Tags removed: verification-needed verification-needed-bionic
** Tags added: verification-done verification-done-bionic

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to python-apt in Ubuntu.
https://bugs.launchpad.net/bugs/1602536

Title:
  /usr/bin/unattended-upgrade:apt.cache.LockFailedException:/usr/bin
  /unattended-
  upgrade at 1468:main:do_auto_remove:cache_commit:commit:_fetch_archives

Status in python-apt package in Ubuntu:
  Fix Committed
Status in unattended-upgrades package in Ubuntu:
  Fix Released
Status in python-apt source package in Xenial:
  New
Status in unattended-upgrades source package in Xenial:
  New
Status in python-apt source package in Bionic:
  New
Status in unattended-upgrades source package in Bionic:
  Fix Committed

Bug description:
  [Impact]

   * Unattended-upgrades fails to autoremove packages after installing
  updates or fails to install updates due to a parallel process
  acquiring apt or dpkg lock while u-u is running.

  [Test Case]

   * Set up a system with packages (> 30) to be upgraded. In case of
  Bionic -security has a low number of updates, thus set up the system
  to install -updates to have more packages for u-u to upgrade:

   echo 'Unattended-Upgrade::Allowed-Origins::
  "${distro_id}:${distro_codename}-updates";' >
  /etc/apt/apt.conf.d/51-updates

   * Set up two shells to run commands in parallel
   * In shell "A" run sudo apt update && sudo unattended-upgrade --dry-run --verbose --debug
   * After u-u started run the following command in shell "B":
   while sleep 1; do python3 -c 'import apt; import apt_pkg; print(apt_pkg.pkgsystem_lock())' ; done
   * Observe the following exception repeated while running u-u and True being printed after u-u is finished:
  ...
  Traceback (most recent call last):
    File "<string>", line 1, in <module>
  apt_pkg.Error: E:Could not get lock /var/lib/dpkg/lock - open (11: Resource temporarily unavailable), E:Unable to lock the administration directory (/var/lib/dpkg/), is another process using it?
  Traceback (most recent call last):
    File "<string>", line 1, in <module>
  apt_pkg.Error: E:Could not get lock /var/lib/dpkg/lock - open (11: Resource temporarily unavailable), E:Unable to lock the administration directory (/var/lib/dpkg/), is another process using it?
  True
  Traceback (most recent call last):
    File "<string>", line 1, in <module>
  apt_pkg.Error: E:Could not get lock /var/lib/dpkg/lock - open (11: Resource temporarily unavailable), E:Unable to lock the administration directory (/var/lib/dpkg/), is another process using it?
  True
  True
  True
  True
  ...

  [Regression Potential WIP]

   * Unattended-upgrade may crash

  [Other Info]

  It looks like python-apt also releases the lock sometimes unexpectedly
  thus the both packages need to be fixed to avoid loosing the lock.

  [Original Bug Text]

  The Ubuntu Error Tracker has been receiving reports about a problem
  regarding unattended-upgrades.  This problem was most recently seen
  with version 0.90, the problem page at
  https://errors.ubuntu.com/problem/19f99745d7dce5aea118eb31bfffcbdcdf238c4f
  contains more details.

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/python-apt/+bug/1602536/+subscriptions