[Bug 1806487] Re: [regression] Crashing with dbus.exceptions.DBusException when logind can't be started (yet)

Wed Dec 19 18:44:55 UTC 2018

Verifed 1.1ubuntu1.18.04.7~16.04.1 on Xenial:

root at x-lp-1806487-uu:~# ln -s /dev/null /etc/systemd/system/systemd-logind.service
root at x-lp-1806487-uu:~# service systemd-logind stop1.1ubuntu1.18.04.7~16.04.1
root at x-lp-1806487-uu:~# vi /etc/apt/sources.list
root at x-lp-1806487-uu:~# apt update -qq
23 packages can be upgraded. Run 'apt list --upgradable' to see them.
root at x-lp-1806487-uu:~# apt install -qq unattended-upgrades 
The following package was automatically installed and is no longer required:
  libfreetype6
Use 'apt autoremove' to remove it.
Suggested packages:
  bsd-mailx default-mta | mail-transport-agent needrestart
The following packages will be upgraded:
  unattended-upgrades
1 upgraded, 0 newly installed, 0 to remove and 22 not upgraded.
Need to get 40.2 kB of archives.
After this operation, 69.6 kB of additional disk space will be used.
Preconfiguring packages ...
(Reading database ... 25709 files and directories currently installed.)
Preparing to unpack .../unattended-upgrades_1.1ubuntu1.18.04.7~16.04.1_all.deb ...
Unpacking unattended-upgrades (1.1ubuntu1.18.04.7~16.04.1) over (0.90ubuntu0.9) ...
Processing triggers for systemd (229-4ubuntu21.10) ...
Processing triggers for ureadahead (0.100.0-19) ...
Processing triggers for man-db (2.7.5-1) ...
Setting up unattended-upgrades (1.1ubuntu1.18.04.7~16.04.1) ...
Installing new version of config file /etc/kernel/postinst.d/unattended-upgrades ...
Installing new version of config file /etc/pm/sleep.d/10_unattended-upgrades-hibernate ...
root at x-lp-1806487-uu:~# systemctl daemon-reload
root at x-lp-1806487-uu:~# service systemd-logind status
● systemd-logind.service
   Loaded: masked (/dev/null; bad)
   Active: inactive (dead) since Wed 2018-12-19 18:41:11 UTC; 1min 14s ago
 Main PID: 376 (code=killed, signal=TERM)
   Status: "Processing requests..."

Dec 19 14:19:03 x-lp-1806487-uu systemd-logind[376]: New seat seat0.
Dec 19 14:19:03 x-lp-1806487-uu systemd[1]: Started Login Service.
Dec 19 18:40:20 x-lp-1806487-uu systemd-logind[376]: New session c1 of user root.
Dec 19 18:41:11 x-lp-1806487-uu systemd[1]: Stopping Login Service...
Dec 19 18:41:11 x-lp-1806487-uu systemd[1]: Stopped Login Service.
root at x-lp-1806487-uu:~# /usr/share/unattended-upgrades/unattended-upgrade-shutdown --debug
root at x-lp-1806487-uu:~# tail /var/log/unattended-upgrades/unattended-upgrades-shutdown.log
2018-12-19 18:42:33,848 WARNING - Could not get delay inhibitor lock
2018-12-19 18:42:33,849 DEBUG - Skip waiting for signals, starting operation now
2018-12-19 18:42:33,849 DEBUG - Starting countdown of 25.0 minutes
2018-12-19 18:42:33,850 DEBUG - Initializing apt_pkg configuration
2018-12-19 18:42:33,850 DEBUG - get_lock returned 7
2018-12-19 18:42:33,851 DEBUG - lock not taken
root at x-lp-1806487-uu:~# rm /etc/systemd/system/systemd-logind.service
root at x-lp-1806487-uu:~# systemctl daemon-reload
root at x-lp-1806487-uu:~# service unattended-upgrades restart
root at x-lp-1806487-uu:~# service unattended-upgrades restart
root at x-lp-1806487-uu:~# service unattended-upgrades status
● unattended-upgrades.service - Unattended Upgrades Shutdown
   Loaded: loaded (/lib/systemd/system/unattended-upgrades.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2018-12-19 18:43:05 UTC; 6s ago
     Docs: man:unattended-upgrade(8)
 Main PID: 1505 (unattended-upgr)
    Tasks: 2
   Memory: 8.4M
      CPU: 66ms
   CGroup: /system.slice/unattended-upgrades.service
           └─1505 /usr/bin/python3 /usr/share/unattended-upgrades/unattended-upgrade-shutdown --wait-for-signal

Dec 19 18:43:05 x-lp-1806487-uu systemd[1]: Started Unattended Upgrades Shutdown.
root at x-lp-1806487-uu:~#  tail /var/log/unattended-upgrades/unattended-upgrades-shutdown.log
2018-12-19 18:42:33,848 WARNING - Could not get delay inhibitor lock
2018-12-19 18:42:33,849 DEBUG - Skip waiting for signals, starting operation now
2018-12-19 18:42:33,849 DEBUG - Starting countdown of 25.0 minutes
2018-12-19 18:42:33,850 DEBUG - Initializing apt_pkg configuration
2018-12-19 18:42:33,850 DEBUG - get_lock returned 7
2018-12-19 18:42:33,851 DEBUG - lock not taken
2018-12-19 18:43:05,014 WARNING - SIGTERM or SIGHUP received, stopping unattended-upgradesonly if it is running
root at x-lp-1806487-uu:~#

** Tags removed: verification-needed verification-needed-bionic verification-needed-cosmic verification-needed-xenial
** Tags added: verification-done verification-done-bionic verification-done-cosmic 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/1806487

Title:
  [regression] Crashing with dbus.exceptions.DBusException when logind
  can't be started (yet)

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 Committed
Status in unattended-upgrades source package in Cosmic:
  Fix Committed

Bug description:
  [Impact]

   * Unattended-upgrades.service may crash due to starting earlier than dbus and logind are up or due to logind failing to start.
   * Unattended-upgrades.service not starting prevents installation of upgrades on shutdown (when u-u is configured to do that) and also prevents gracefully stopping running u-u _before_ shutdown as implemented in LP: #1803137. U-u is still stopped gracefully after the shutdown transaction is started, but that may let service restarts hang the upgrade process.
   * The fix is adding an After service dependency on systemd-logind to ensure starting u-u.service after logind at least tried to start and also changing u-u-s to start even with logind's absence.

  [Test Case]

   * Stop systemd-logind and make it unable to start for example by
  masking it:

  root at bb-logind:~# ln -s /dev/null /etc/systemd/system/systemd-logind.service
  root at bb-logind:~# systemctl daemon-reload
  root at bb-logind:~# service systemd-logind stop
  root at bb-logind:~# service systemd-logind status
  ● systemd-logind.service
     Loaded: masked (/dev/null; bad)
     Active: inactive (dead) since Thu 2018-12-13 13:02:44 UTC; 1s ago
   Main PID: 1938 (code=killed, signal=TERM)
     Status: "Processing requests..."
  ...

   * Run u-u-s and observe it crashing in unfixed version and starting
  with falling back to polling logind instead taking the inhibition lock
  at its start:

  root at bb-logind:~# /usr/share/unattended-upgrades/unattended-upgrade-shutdown --debug 
  root at bb-logind:~# tail /var/log/unattended-upgrades/unattended-upgrades-shutdown.log 
  ...
  2018-12-13 14:30:17,600 WARNING - Could not get delay inhibitor lock
  2018-12-13 14:30:17,601 DEBUG - Skip waiting for signals, starting operation now
  2018-12-13 14:30:17,601 DEBUG - Starting countdown of 25.0 minutes
  2018-12-13 14:30:17,602 DEBUG - Initializing apt_pkg configuration
  2018-12-13 14:30:17,602 DEBUG - get_lock returned 7
  2018-12-13 14:30:17,602 DEBUG - lock not taken

   * Restore logind's ability to start

  root at bb-logind:~# rm /etc/systemd/system/systemd-logind.service
  root at bb-logind:~# systemctl daemon-reload

   * Restart unattended-upgrades.service

  root at bb-logind:~# service unattended-upgrades restart
  root at bb-logind:~# service unattended-upgrades status 
  ● unattended-upgrades.service - Unattended Upgrades Shutdown
     Loaded: loaded (/lib/systemd/system/unattended-upgrades.service; enabled; vendor preset: enabled)
     Active: active (running) since Thu 2018-12-13 14:31:43 UTC; 3s ago
       Docs: man:unattended-upgrade(8)
   Main PID: 4129 (unattended-upgr)
      Tasks: 2 (limit: 4915)
     CGroup: /system.slice/unattended-upgrades.service
             └─4129 /usr/bin/python3 /usr/share/unattended-upgrades/unattended-upgrade-shutdown --wait-for-signal

  Dec 13 14:31:43 bb-logind systemd[1]: Started Unattended Upgrades Shutdown.
  root at bb-logind:~# tail /var/log/unattended-upgrades/unattended-upgrades-shutdown.log 
  2018-12-13 14:30:17,601 DEBUG - Starting countdown of 25.0 minutes
  2018-12-13 14:30:17,602 DEBUG - Initializing apt_pkg configuration
  2018-12-13 14:30:17,602 DEBUG - get_lock returned 7
  2018-12-13 14:30:17,602 DEBUG - lock not taken
  2018-12-13 14:31:43,595 WARNING - SIGTERM or SIGHUP received, stopping unattended-upgradesonly if it is running
  2018-12-13 14:31:43,688 WARNING - Could not get delay inhibitor lock
  2018-12-13 14:31:43,691 WARNING - Unable to monitor PrepareForShutdown() signal, polling instead.
  2018-12-13 14:31:43,691 WARNING - Maybe systemd-logind service is not running.
  2018-12-13 14:31:43,691 WARNING - Unable to monitor PrepareForShutdown() signal, polling instead.
  2018-12-13 14:31:43,691 WARNING - To enable monitoring the PrepareForShutdown() signal instead of polling please install the python3-gi package

  root at bb-logind:~# systemd-analyze dot | grep unattended
  ...
  "unattended-upgrades.service"->"systemd-logind.service" [color="green"];
  ...

  [Regression Potential]

   * The change to service ordering is unlikely to cause any issue, but
  the graceful handling of missing logind involved a small-scale
  refactoring of u-u-s's code. Extensive testing did not reveal
  regressions in that area, but potential bugs may cause u-u.service
  fail to start and affect graceful shutdown of u-u the same way as
  detailed in [Impact].

  [Original Bug Text]

  The Ubuntu Error Tracker has been receiving reports about a problem regarding unattended-upgrades.  This problem was most recently seen with package version 1.1ubuntu1.18.04.7, the problem page at https://errors.ubuntu.com/problem/caf5d885046359f4857cee6c4a61e1d72d0913b1 contains more details, including versions of packages affected, stacktrace or traceback, and individual crash reports.
  If you do not have access to the Ubuntu Error Tracker and are a software developer, you can request it at http://forms.canonical.com/reports/.

  Also seen as:
   * https://errors.ubuntu.com/problem/ac61b23e0ec25a291427b875bf213fdd5b097fa5

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