[Bug 1260041] Re: Unattended-Upgrades crashes with a dpkg error

Balint Reczey balint.reczey at canonical.com
Thu Feb 7 13:12:06 UTC 2019 

Tested with 0.90ubuntu0.10 (not fixed) and 1.1ubuntu1.18.04.7~16.04.1
(fixed):

With the not fixed version the lock is lost by u-u, while u-u kept running:
...
SystemError: E:Could not get lock /var/lib/dpkg/lock-frontend - open (11: Resource temporarily unavailable), E:Unable to acquire the dpkg frontend lock (/var/lib/dpkg/lock-frontend), is another process using it?
Traceback (most recent call last):
  File "<string>", line 1, in <module>
SystemError: E:Could not get lock /var/lib/dpkg/lock-frontend - open (11: Resource temporarily unavailable), E:Unable to acquire the dpkg frontend lock (/var/lib/dpkg/lock-frontend), is another process using it?
Traceback (most recent call last):
  File "<string>", line 1, in <module>
SystemError: E:Could not get lock /var/lib/dpkg/lock-frontend - open (11: Resource temporarily unavailable), E:Unable to acquire the dpkg frontend lock (/var/lib/dpkg/lock-frontend), is another process using it?
True
True
True
True
True
True
True
True
True
True
...


With the fixed version but keeping unfixed python-apt the lock is still lost by u-u, but u-u crashes. This is expected and is safer than the unfixed behaviour:
...
conffile line: /etc/rsyslog.d/21-cloudinit.conf d4cf2e5d3cb9914cf7e6cdc08d298339
current md5: d4cf2e5d3cb9914cf7e6cdc08d298339
blacklist: []
whitelist: []
Option --dry-run given, *not* performing real actions
Packages that will be upgraded: cloud-init curl kmod libc-bin libc6 libcurl3-gnutls libkmod2 locales multiarch-support python-apt-common python3-apt snapd ubuntu-core-launcher
Writing dpkg log to /var/log/unattended-upgrades/unattended-upgrades-dpkg.log
applying set ['python-apt-common']
/usr/bin/dpkg --status-fd 9 --unpack --auto-deconfigure /var/cache/apt/archives/python-apt-common_1.1.0~beta1ubuntu0.16.04.3_all.deb 
/usr/bin/dpkg --status-fd 11 --configure python-apt-common:all 
/usr/bin/dpkg --status-fd 13 --configure --pending 
Exception happened during upgrade.
Traceback (most recent call last):
  File "/usr/bin/unattended-upgrade", line 374, in __exit__
    apt_pkg.pkgsystem_lock_inner()
AttributeError: module 'apt_pkg' has no attribute 'pkgsystem_lock_inner'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/bin/unattended-upgrade", line 558, in cache_commit
    res = cache.commit(install_progress=iprogress)
  File "/usr/bin/unattended-upgrade", line 376, in __exit__
    apt_pkg.pkgsystem_lock()
SystemError: E:Could not get lock /var/lib/dpkg/lock-frontend - open (11: Resource temporarily unavailable), E:Unable to acquire the dpkg frontend lock (/var/lib/dpkg/lock-frontend), is another process using it?
Exception happened during upgrade.
NoneType
Installing the upgrades failed!
error message: E:Could not get lock /var/lib/dpkg/lock-frontend - open (11: Resource temporarily unavailable), E:Unable to acquire the dpkg frontend lock (/var/lib/dpkg/lock-frontend), is another process using it?
dpkg returned a error! See /var/log/unattended-upgrades/unattended-upgrades-dpkg.log for details
InstCount=0 DelCount=0 BrokenCount=0
root at x-uu:~#

With both u-u and python-apt fixed u-u keeps the lock for the whole run:
...
SystemError: E:Could not get lock /var/lib/dpkg/lock-frontend - open (11: Resource temporarily unavailable), E:Unable to acquire the dpkg frontend lock (/var/lib/dpkg/lock-frontend), is another process using it?
Traceback (most recent call last):
  File "<string>", line 1, in <module>
SystemError: E:Could not get lock /var/lib/dpkg/lock-frontend - open (11: Resource temporarily unavailable), E:Unable to acquire the dpkg frontend lock (/var/lib/dpkg/lock-frontend), is another process using it?
Traceback (most recent call last):
  File "<string>", line 1, in <module>
SystemError: E:Could not get lock /var/lib/dpkg/lock-frontend - open (11: Resource temporarily unavailable), E:Unable to acquire the dpkg frontend lock (/var/lib/dpkg/lock-frontend), is another process using it?

Traceback (most recent call last):
  File "<string>", line 1, in <module>
SystemError: E:Could not get lock /var/lib/dpkg/lock-frontend - open (11: Resource temporarily unavailable), E:Unable to acquire the dpkg frontend lock (/var/lib/dpkg/lock-frontend), is another process using it?
True
True
...

...
Writing dpkg log to /var/log/unattended-upgrades/unattended-upgrades-dpkg.log
applying set ['python-apt-common']
/usr/bin/dpkg --status-fd 9 --unpack --auto-deconfigure /var/cache/apt/archives/python-apt-common_1.1.0~beta1ubuntu0.16.04.3_all.deb 
/usr/bin/dpkg --status-fd 11 --configure python-apt-common:all 
/usr/bin/dpkg --status-fd 13 --configure --pending 
left to upgrade {'libc-bin', 'libcurl3-gnutls', 'libkmod2', 'curl', 'libc6', 'ubuntu-core-launcher', 'multiarch-support', 'snapd', 'locales', 'kmod', 'cloud-init'}
applying set ['libc-bin']
/usr/bin/dpkg --status-fd 9 --unpack --auto-deconfigure /var/cache/apt/archives/libc-bin_2.23-0ubuntu11_amd64.deb 
/usr/bin/dpkg --status-fd 11 --configure libc-bin:amd64 
/usr/bin/dpkg --status-fd 13 --configure --pending 
left to upgrade {'libcurl3-gnutls', 'libkmod2', 'curl', 'libc6', 'ubuntu-core-launcher', 'multiarch-support', 'kmod', 'locales', 'snapd', 'cloud-init'}
applying set ['libc6']
Preconfiguring packages ...
/usr/bin/dpkg --status-fd 9 --unpack --auto-deconfigure /var/cache/apt/archives/libc6_2.23-0ubuntu11_amd64.deb 
/usr/bin/dpkg --status-fd 11 --configure libc6:amd64 
/usr/bin/dpkg --status-fd 13 --configure --pending 
left to upgrade {'libcurl3-gnutls', 'libkmod2', 'curl', 'ubuntu-core-launcher', 'multiarch-support', 'snapd', 'locales', 'kmod', 'cloud-init'}
applying set ['multiarch-support']
/usr/bin/dpkg --status-fd 9 --unpack --auto-deconfigure /var/cache/apt/archives/multiarch-support_2.23-0ubuntu11_amd64.deb 
/usr/bin/dpkg --status-fd 11 --configure multiarch-support:amd64 
/usr/bin/dpkg --status-fd 13 --configure --pending 
left to upgrade {'libcurl3-gnutls', 'libkmod2', 'curl', 'ubuntu-core-launcher', 'kmod', 'locales', 'snapd', 'cloud-init'}
applying set ['locales']
Preconfiguring packages ...
/usr/bin/dpkg --status-fd 9 --unpack --auto-deconfigure /var/cache/apt/archives/locales_2.23-0ubuntu11_all.deb 
/usr/bin/dpkg --status-fd 11 --configure locales:all 
/usr/bin/dpkg --status-fd 13 --configure --pending 
left to upgrade {'libcurl3-gnutls', 'libkmod2', 'curl', 'ubuntu-core-launcher', 'snapd', 'kmod', 'cloud-init'}
applying set ['cloud-init']
Preconfiguring packages ...
/usr/bin/dpkg --status-fd 9 --unpack --auto-deconfigure /var/cache/apt/archives/cloud-init_18.5-21-g8ee294d5-0ubuntu1~16.04.1_all.deb 
/usr/bin/dpkg --status-fd 11 --configure cloud-init:all 
/usr/bin/dpkg --status-fd 13 --configure --pending 
left to upgrade {'libcurl3-gnutls', 'libkmod2', 'curl', 'ubuntu-core-launcher', 'snapd', 'kmod'}
applying set ['snapd', 'ubuntu-core-launcher']
/usr/bin/dpkg --status-fd 9 --unpack --auto-deconfigure /var/cache/apt/archives/ubuntu-core-launcher_2.37.1_amd64.deb /var/cache/apt/archives/snapd_2.37.1_amd64.deb 
/usr/bin/dpkg --status-fd 11 --configure snapd:amd64 ubuntu-core-launcher:amd64 
/usr/bin/dpkg --status-fd 13 --configure --pending 
left to upgrade {'libkmod2', 'curl', 'kmod', 'libcurl3-gnutls'}
applying set ['libkmod2', 'kmod']
/usr/bin/dpkg --status-fd 9 --unpack --auto-deconfigure /var/cache/apt/archives/kmod_22-1ubuntu5.2_amd64.deb /var/cache/apt/archives/libkmod2_22-1ubuntu5.2_amd64.deb 
/usr/bin/dpkg --status-fd 11 --configure libkmod2:amd64 kmod:amd64 
/usr/bin/dpkg --status-fd 13 --configure --pending 
left to upgrade {'curl', 'libcurl3-gnutls'}
applying set ['curl', 'libcurl3-gnutls']
/usr/bin/dpkg --status-fd 9 --unpack --auto-deconfigure /var/cache/apt/archives/curl_7.47.0-1ubuntu2.12_amd64.deb /var/cache/apt/archives/libcurl3-gnutls_7.47.0-1ubuntu2.12_amd64.deb 
/usr/bin/dpkg --status-fd 11 --configure libcurl3-gnutls:amd64 curl:amd64 
/usr/bin/dpkg --status-fd 13 --configure --pending 
left to upgrade set()
All upgrades installed
InstCount=0 DelCount=0 BrokenCount=0
root at x-uu:~# 


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

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

Title:
  Unattended-Upgrades crashes with a dpkg error

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

Bug description:
  [Impact]

   * Unattended-upgrades fails upgrading packages in the middle of a dpkg/apt call due to a parallel process acquiring apt or dpkg lock while u-u is running, but u-u running apt/dpkg anyway without successfully re-acquiring the lock.
   * The fix is stopping processing updates when the lock is detected to be lost.

  [Test Case]

   * Set up a system with packages (> 30) to be upgraded:
  $ lxc launch ubuntu:b36ec647e374 uu-lock-bail

   * 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 installing the updates run the following command in shell "B":
  $  while sleep 0.1; do python3 -c 'import apt, apt_pkg, time; print(apt_pkg.pkgsystem_lock()); time.sleep(2)' ; done

  * With not fixed u-u observe the following exception repeated in shell "B", then True being printed when the lock is successfully stolen from u-u:
  ...
  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
  ...

  Buggy u-u continues operation even after the lock is stolen.

  Fixed u-u stops operation with a printout similar to the following when it detects the lock to be stolen:
  ...
  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/distro-info-data_0.37ubuntu0.1_all.deb 
  /usr/bin/dpkg --status-fd 9 --configure --pending 
  Exception happened during upgrade.
  Traceback (most recent call last):
    File "./unattended-upgrade", line 539, in cache_commit
      res = cache.commit(install_progress=iprogress)
    File "./unattended-upgrade", line 360, in __exit__
      apt_pkg.pkgsystem_lock()
  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?
  Exception happened during upgrade.
  NoneType: None
  Installing the upgrades failed!
  error message: 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?
  dpkg returned a error! See /var/log/unattended-upgrades/unattended-upgrades-dpkg.log for details
  ...

  [Regression Potential]

   * As a consequence of the fix unattended-upgrade stops installing
  security-updates when an other dpkg frontend's parallel activity is
  detected. This is intentional to prevent parallel execution of dpkg
  and potentially leaving the system in an inconsistent state. The full
  fix will be implemented in LP: #1781169 and changing u-u to use the
  new locking mechanism, and then u-u will never lose the lock.

  [Other Info]

  I believe parallel dpkg calls cause many breakages reported against
  u-u and other packages listing breaking maintainer scripts.

  [Original Bug Text]

  As per https://bugs.launchpad.net/ubuntu/+source/unattended-
  upgrades/+bug/1052360/comments/17, I am filing a new bug with the
  specific error I am running into. This has been going on for quite a
  while now.

  Also, my log files still show up as I described in
  https://bugs.launchpad.net/ubuntu/+source/unattended-
  upgrades/+bug/1052360/comments/14.

  ProblemType: Bug
  DistroRelease: Ubuntu 13.10
  Package: unattended-upgrades 0.79.3ubuntu8
  ProcVersionSignature: Ubuntu 3.11.0-14.21-generic 3.11.7
  Uname: Linux 3.11.0-14-generic x86_64
  NonfreeKernelModules: fglrx
  ApportVersion: 2.12.5-0ubuntu2.1
  Architecture: amd64
  Date: Wed Dec 11 11:07:09 2013
  MarkForUpload: True
  PackageArchitecture: all
  SourcePackage: unattended-upgrades
  UpgradeStatus: Upgraded to saucy on 2013-10-18 (54 days ago)

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/unattended-upgrades/+bug/1260041/+subscriptions

More information about the foundations-bugs mailing list