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

Balint Reczey balint.reczey at canonical.com
Wed Dec 19 18:40:34 UTC 2018 

Verified 1.1ubuntu1.18.04.8 on Bionic:

root at bb-lp-1806487-uu:~#  ln -s /dev/null /etc/systemd/system/systemd-logind.service
root at bb-lp-1806487-uu:~# service systemd-logind stop

root at bb-lp-1806487-uu:~# 
root at bb-lp-1806487-uu:~#  service systemd-logind status
● systemd-logind.service - Login Service
   Loaded: loaded (/lib/systemd/system/systemd-logind.service; masked; vendor preset: enabled)
   Active: inactive (dead) since Wed 2018-12-19 18:37:18 UTC; 4s ago
     Docs: man:systemd-logind.service(8)
           man:logind.conf(5)
           https://www.freedesktop.org/wiki/Software/systemd/logind
           https://www.freedesktop.org/wiki/Software/systemd/multiseat
  Process: 196 ExecStart=/lib/systemd/systemd-logind (code=killed, signal=TERM)
 Main PID: 196 (code=killed, signal=TERM)
   Status: "Processing requests..."

Dec 19 14:08:17 bb-lp-1806487-uu systemd[1]: Starting Login Service...
Dec 19 14:08:17 bb-lp-1806487-uu systemd-logind[196]: New seat seat0.
Dec 19 14:08:17 bb-lp-1806487-uu systemd[1]: Started Login Service.
Dec 19 18:35:38 bb-lp-1806487-uu systemd-logind[196]: New session c1 of user root.
Dec 19 18:36:17 bb-lp-1806487-uu systemd[1]: systemd-logind.service: Failed to reset devices.list: Operation not per
Dec 19 18:36:17 bb-lp-1806487-uu systemd[1]: systemd-logind.service: Failed to reset devices.list: Operation not per
Dec 19 18:36:18 bb-lp-1806487-uu systemd[1]: systemd-logind.service: Failed to reset devices.list: Operation not per
Dec 19 18:37:18 bb-lp-1806487-uu systemd[1]: Stopping Login Service...
Dec 19 18:37:18 bb-lp-1806487-uu systemd[1]: Stopped Login Service.
root at bb-lp-1806487-uu:~# systemctl daemon-reload
root at bb-lp-1806487-uu:~# service systemd-logind stop
root at bb-lp-1806487-uu:~# service systemd-logind status
● systemd-logind.service
   Loaded: masked (/dev/null; bad)
   Active: inactive (dead) since Wed 2018-12-19 18:37:18 UTC; 32s ago
 Main PID: 196 (code=killed, signal=TERM)
   Status: "Processing requests..."

Dec 19 14:08:17 bb-lp-1806487-uu systemd[1]: Starting Login Service...
Dec 19 14:08:17 bb-lp-1806487-uu systemd-logind[196]: New seat seat0.
Dec 19 14:08:17 bb-lp-1806487-uu systemd[1]: Started Login Service.
Dec 19 18:35:38 bb-lp-1806487-uu systemd-logind[196]: New session c1 of user root.
Dec 19 18:36:17 bb-lp-1806487-uu systemd[1]: systemd-logind.service: Failed to reset devices.list: Operation not per
Dec 19 18:36:17 bb-lp-1806487-uu systemd[1]: systemd-logind.service: Failed to reset devices.list: Operation not per
Dec 19 18:36:18 bb-lp-1806487-uu systemd[1]: systemd-logind.service: Failed to reset devices.list: Operation not per
Dec 19 18:37:18 bb-lp-1806487-uu systemd[1]: Stopping Login Service...
Dec 19 18:37:18 bb-lp-1806487-uu systemd[1]: Stopped Login Service.
root at bb-lp-1806487-uu:~# /usr/share/unattended-upgrades/unattended-upgrade-shutdown --debug
root at bb-lp-1806487-uu:~# tail /var/log/unattended-upgrades/unattended-upgrades-shutdown.log
2018-12-19 18:37:58,922 WARNING - Could not get delay inhibitor lock
2018-12-19 18:37:58,922 DEBUG - Skip waiting for signals, starting operation now
2018-12-19 18:37:58,923 DEBUG - Starting countdown of 25.0 minutes
2018-12-19 18:37:58,923 DEBUG - Initializing apt_pkg configuration
2018-12-19 18:37:58,923 DEBUG - get_lock returned 7
2018-12-19 18:37:58,923 DEBUG - lock not taken
root at bb-lp-1806487-uu:~# rm /etc/systemd/system/systemd-logind.service
root at bb-lp-1806487-uu:~# systemctl daemon-reload
root at bb-lp-1806487-uu:~#  service unattended-upgrades restart
root at bb-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:38:28 UTC; 4s ago
     Docs: man:unattended-upgrade(8)
 Main PID: 1149 (unattended-upgr)
    Tasks: 2 (limit: 4915)
   CGroup: /system.slice/unattended-upgrades.service
           └─1149 /usr/bin/python3 /usr/share/unattended-upgrades/unattended-upgrade-shutdown --wait-for-signal

Dec 19 18:38:28 bb-lp-1806487-uu systemd[1]: Started Unattended Upgrades Shutdown.
root at bb-lp-1806487-uu:~# tail /var/log/unattended-upgrades/unattended-upgrades-shutdown.log
2018-12-19 18:37:58,922 WARNING - Could not get delay inhibitor lock
2018-12-19 18:37:58,922 DEBUG - Skip waiting for signals, starting operation now
2018-12-19 18:37:58,923 DEBUG - Starting countdown of 25.0 minutes
2018-12-19 18:37:58,923 DEBUG - Initializing apt_pkg configuration
2018-12-19 18:37:58,923 DEBUG - get_lock returned 7
2018-12-19 18:37:58,923 DEBUG - lock not taken
2018-12-19 18:38:28,808 WARNING - SIGTERM or SIGHUP received, stopping unattended-upgradesonly if it is running
root at bb-lp-1806487-uu:~# service unattended-upgrades restart
root at bb-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:39:09 UTC; 2s ago
     Docs: man:unattended-upgrade(8)
 Main PID: 1163 (unattended-upgr)
    Tasks: 2 (limit: 4915)
   CGroup: /system.slice/unattended-upgrades.service
           └─1163 /usr/bin/python3 /usr/share/unattended-upgrades/unattended-upgrade-shutdown --wait-for-signal

Dec 19 18:39:09 bb-lp-1806487-uu systemd[1]: Started Unattended Upgrades Shutdown.
root at bb-lp-1806487-uu:~# tail /var/log/unattended-upgrades/unattended-upgrades-shutdown.logf
tail: cannot open '/var/log/unattended-upgrades/unattended-upgrades-shutdown.logf' for reading: No such file or directory
root at bb-lp-1806487-uu:~# tail /var/log/unattended-upgrades/unattended-upgrades-shutdown.log
2018-12-19 18:37:58,922 WARNING - Could not get delay inhibitor lock
2018-12-19 18:37:58,922 DEBUG - Skip waiting for signals, starting operation now
2018-12-19 18:37:58,923 DEBUG - Starting countdown of 25.0 minutes
2018-12-19 18:37:58,923 DEBUG - Initializing apt_pkg configuration
2018-12-19 18:37:58,923 DEBUG - get_lock returned 7
2018-12-19 18:37:58,923 DEBUG - lock not taken
2018-12-19 18:38:28,808 WARNING - SIGTERM or SIGHUP received, stopping unattended-upgradesonly if it is running
2018-12-19 18:39:09,702 WARNING - SIGTERM or SIGHUP received, stopping unattended-upgradesonly if it is running
root at bb-lp-1806487-uu:~# dpkg -l unattended-upgrades  | cat
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name                Version            Architecture Description
+++-===================-==================-============-===========================================
ii  unattended-upgrades 1.1ubuntu1.18.04.8 all          automatic installation of security upgrades

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

More information about the foundations-bugs mailing list