Bug#782456: plymouth: With plymouth installed, starting the DM sometimes fails

[Ralf Jung]

Hi all,

I finally had the time to experiment a bit more. Here are my latest
findings:

I removed all non-Debian kernels, just to be sure.
Immediately after enabling "splash" in grub again, the behavior of
"lightdm always fails to start" reappeared. Then I changed plymouth to
text mode, re-generated the initramdisk, and now I was back to the old
case of "lightdm fails to start in around 1/3 of the cases". So I
switched to "joy", and now lightdm reliably started! Going to "text"
again, I again see occasional failure.

So I conclude that something was borked in the initramdisk I used, and
that made things fail. With a fresh and shiny initramdisk, I tried
booting with "joy" >5 times, and it never failed.

*However*, with "text", booting still (again) fails sometimes. It would
be fine with me to downgrade the severity, though of course this is
still a serious bug.
I attached a (sanitized) part of the journalctl output of a failed boot,
and can provide the full log via private mail.

Kind regards,
Ralf

-------------- next part --------------
Apr 23 18:18:06 r-schnelltop lightdm[906]: ** (lightdm:906): WARNING **: Error getting user list from org.freedesktop.Accounts: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.Accounts was not provided by any .service files

Apr 23 18:18:06 r-schnelltop kernel: ip_tables: (C) 2000-2006 Netfilter Core Team
Apr 23 18:18:06 r-schnelltop kernel: nf_conntrack version 0.5.0 (16384 buckets, 65536 max)
Apr 23 18:18:06 r-schnelltop kernel: ip6_tables: (C) 2000-2006 Netfilter Core Team
Apr 23 18:18:06 r-schnelltop kernel: Ebtables v2.0 registered
Apr 23 18:18:06 r-schnelltop kernel: Bridge firewalling registered
Apr 23 18:18:06 r-schnelltop virtualbox[988]: Starting VirtualBox kernel moduleserror: unexpectedly disconnected from boot status daemon
Apr 23 18:18:06 r-schnelltop lightdm[906]: error: unexpectedly disconnected from boot status daemon
Apr 23 18:18:06 r-schnelltop kernel: vboxdrv: Found 4 processor cores.
Apr 23 18:18:06 r-schnelltop kernel: vboxdrv: fAsync=0 offMin=0x177 offMax=0x11ea
Apr 23 18:18:06 r-schnelltop kernel: vboxdrv: TSC mode is 'synchronous', kernel timer mode is 'normal'.
Apr 23 18:18:06 r-schnelltop kernel: vboxdrv: Successfully loaded version 4.3.18_Debian (interface 0x001a0008).
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> NetworkManager (version 0.9.10.0) is starting...
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> Read config: /etc/NetworkManager/NetworkManager.conf
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> WEXT support is enabled
Apr 23 18:18:06 r-schnelltop virtualbox[988]: libkmod: ERROR ../libkmod/libkmod-module.c:1903 kmod_module_get_holders: could not open '/sys/module/cfg80211/holders': No such file or directory
Apr 23 18:18:06 r-schnelltop lightdm[906]: ** (process:1022): WARNING **: Error getting user list from org.freedesktop.Accounts: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.Accounts was not provided by any .service files
Apr 23 18:18:06 r-schnelltop kernel: cfg80211: Calling CRDA to update world regulatory domain
Apr 23 18:18:06 r-schnelltop schroot[990]: Ending schroot sessions:.
Apr 23 18:18:06 r-schnelltop lightdm[1022]: pam_unix(lightdm-greeter:session): session opened for user lightdm by (uid=0)
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> VPN: loaded org.freedesktop.NetworkManager.openvpn
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> VPN: loaded org.freedesktop.NetworkManager.vpnc
Apr 23 18:18:06 r-schnelltop kernel: cfg80211: World regulatory domain updated:
Apr 23 18:18:06 r-schnelltop kernel: cfg80211:  DFS Master region: unset
Apr 23 18:18:06 r-schnelltop kernel: cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
Apr 23 18:18:06 r-schnelltop kernel: cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
Apr 23 18:18:06 r-schnelltop kernel: cfg80211:   (2457000 KHz - 2482000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
Apr 23 18:18:06 r-schnelltop kernel: cfg80211:   (2474000 KHz - 2494000 KHz @ 20000 KHz), (N/A, 2000 mBm), (N/A)
Apr 23 18:18:06 r-schnelltop kernel: cfg80211:   (5170000 KHz - 5250000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (N/A)
Apr 23 18:18:06 r-schnelltop kernel: cfg80211:   (5250000 KHz - 5330000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (0 s)
Apr 23 18:18:06 r-schnelltop kernel: cfg80211:   (5490000 KHz - 5730000 KHz @ 160000 KHz), (N/A, 2000 mBm), (0 s)
Apr 23 18:18:06 r-schnelltop kernel: cfg80211:   (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 2000 mBm), (N/A)
Apr 23 18:18:06 r-schnelltop kernel: cfg80211:   (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> VPN: loaded org.freedesktop.NetworkManager.pptp
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> VPN: loaded org.freedesktop.NetworkManager.openconnect
Apr 23 18:18:06 r-schnelltop systemd-logind[854]: New session c1 of user lightdm.
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> init!
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> update_system_hostname
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info>       interface-parser: parsing file /etc/network/interfaces
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info>       interface-parser: finished parsing file /etc/network/interfaces
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> management mode: unmanaged
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> devices added (path: /sys/devices/pci0000:00/0000:00:1c.5/0000:04:00.0/net/eth0, iface: eth0)
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> device added (path: /sys/devices/pci0000:00/0000:00:1c.5/0000:04:00.0/net/eth0, iface: eth0): no ifupdown configuration found.
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> devices added (path: /sys/devices/virtual/net/lo, iface: lo)
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> device added (path: /sys/devices/virtual/net/lo, iface: lo): no ifupdown configuration found.
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> end _init.
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> Loaded plugin ifupdown: (C) 2008 Canonical Ltd.  To report bugs please use the NetworkManager mailing list.
Apr 23 18:18:06 r-schnelltop systemd[1077]: pam_unix(systemd-user:session): session opened for user lightdm by (uid=0)
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> Loaded plugin keyfile: (c) 2007 - 2013 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> (36124576) ... get_connections.
Apr 23 18:18:06 r-schnelltop NetworkManager[985]: <info> (36124576) ... get_connections (managed=false): return empty list.
Apr 23 18:18:06 r-schnelltop virtualbox[988]: .
Apr 23 18:18:06 r-schnelltop kernel: vboxpci: IOMMU not found (not registered)
Apr 23 18:18:06 r-schnelltop systemd[1077]: Starting Paths.
Apr 23 18:18:06 r-schnelltop systemd[1077]: Reached target Paths.
Apr 23 18:18:06 r-schnelltop systemd[1077]: Starting Timers.
Apr 23 18:18:06 r-schnelltop systemd[1077]: Reached target Timers.
Apr 23 18:18:06 r-schnelltop systemd[1077]: Starting Sockets.
Apr 23 18:18:06 r-schnelltop systemd[1077]: Reached target Sockets.
Apr 23 18:18:06 r-schnelltop systemd[1077]: Starting Basic System.
Apr 23 18:18:06 r-schnelltop systemd[1077]: Reached target Basic System.
Apr 23 18:18:06 r-schnelltop systemd[1077]: Starting Default.
Apr 23 18:18:06 r-schnelltop systemd[1077]: Reached target Default.
Apr 23 18:18:06 r-schnelltop systemd[1077]: Startup finished in 10ms.

Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> get unmanaged devices count: 0
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> monitoring kernel firmware directory '/lib/firmware'.
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> monitoring ifupdown state file '/run/network/ifstate'.
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> WiFi hardware radio set disabled
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> WWAN hardware radio set disabled
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> Loaded device plugin: /usr/lib/x86_64-linux-gnu/NetworkManager/libnm-device-plugin-wwan.so
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> Loaded device plugin: /usr/lib/x86_64-linux-gnu/NetworkManager/libnm-device-plugin-adsl.so
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> Loaded device plugin: /usr/lib/x86_64-linux-gnu/NetworkManager/libnm-device-plugin-bluetooth.so
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> Loaded device plugin: /usr/lib/x86_64-linux-gnu/NetworkManager/libnm-device-plugin-wifi.so
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> WiFi enabled by radio killswitch; disabled by state file
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> WWAN enabled by radio killswitch; disabled by state file
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> WiMAX enabled by radio killswitch; enabled by state file
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> Networking is enabled by state file
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> (lo): link connected
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> (lo): carrier is ON
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> (lo): new Generic device (driver: 'unknown' ifindex: 1)
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> (lo): exported as /org/freedesktop/NetworkManager/Devices/0
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> (eth0): carrier is OFF
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> (eth0): new Ethernet device (driver: 'r8169' ifindex: 2)
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> (eth0): exported as /org/freedesktop/NetworkManager/Devices/1
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> (eth0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Apr 23 18:18:07 r-schnelltop kernel: r8169 0000:04:00.0: firmware: direct-loading firmware rtl_nic/rtl8168e-2.fw
Apr 23 18:18:07 r-schnelltop kernel: r8169 0000:04:00.0 eth0: link down
Apr 23 18:18:07 r-schnelltop kernel: IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> (eth0): preparing device
Apr 23 18:18:07 r-schnelltop NetworkManager[985]: <info> ModemManager available in the bus
Apr 23 18:18:07 r-schnelltop postfix[991]: Starting Postfix Mail Transport Agent: postfix.
Apr 23 18:18:07 r-schnelltop postfix/master[1345]: daemon started -- version 2.11.3, configuration /etc/postfix
Apr 23 18:18:07 r-schnelltop smartd[850]: Device: /dev/sda [SAT], is SMART capable. Adding to "monitor" list.
Apr 23 18:18:07 r-schnelltop smartd[850]: Device: /dev/sda [SAT], state read from /var/lib/smartmontools/smartd.Hitachi_HTS547575A9E384-J2540059C322KE.ata.state
Apr 23 18:18:07 r-schnelltop smartd[850]: Device: /dev/sdb, type changed from 'scsi' to 'sat'
Apr 23 18:18:07 r-schnelltop smartd[850]: Device: /dev/sdb [SAT], opened
Apr 23 18:18:07 r-schnelltop smartd[850]: Device: /dev/sdb [SAT], Samsung SSD 840 PRO Series, S/N:S1ATNSAD717874B, WWN:5-002538-5a00884b2, FW:DXM05B0Q, 256 GB
Apr 23 18:18:07 r-schnelltop smartd[850]: Device: /dev/sdb [SAT], found in smartd database: Samsung based SSDs
Apr 23 18:18:07 r-schnelltop smartd[850]: Device: /dev/sdb [SAT], can't monitor Current_Pending_Sector count - no Attribute 197
Apr 23 18:18:07 r-schnelltop smartd[850]: Device: /dev/sdb [SAT], can't monitor Offline_Uncorrectable count - no Attribute 198
Apr 23 18:18:07 r-schnelltop smartd[850]: Device: /dev/sdb [SAT], is SMART capable. Adding to "monitor" list.
Apr 23 18:18:07 r-schnelltop smartd[850]: Device: /dev/sdb [SAT], state read from /var/lib/smartmontools/smartd.Samsung_SSD_840_PRO_Series-S1ATNSAD717874B.ata.state
Apr 23 18:18:07 r-schnelltop smartd[850]: Monitoring 2 ATA and 0 SCSI devices
Apr 23 18:18:07 r-schnelltop dbus[862]: [system] Activating via systemd: service name='org.freedesktop.UPower' unit='upower.service'
Apr 23 18:18:07 r-schnelltop dbus[862]: [system] Successfully activated service 'org.freedesktop.UPower'
Apr 23 18:18:08 r-schnelltop smartd[850]: Device: /dev/sda [SAT], state written to /var/lib/smartmontools/smartd.Hitachi_HTS547575A9E384-J2540059C322KE.ata.state
Apr 23 18:18:08 r-schnelltop smartd[850]: Device: /dev/sdb [SAT], state written to /var/lib/smartmontools/smartd.Samsung_SSD_840_PRO_Series-S1ATNSAD717874B.ata.state
Apr 23 18:18:08 r-schnelltop ModemManager[847]: <warn>  Couldn't find support for device at '/sys/devices/pci0000:00/0000:00:1c.5/0000:04:00.0': not supported by any plugin
Apr 23 18:18:08 r-schnelltop systemd-fsck[1542]: storefs: clean, 195561/29786112 files, 79578471/119117056 blocks
Apr 23 18:18:08 r-schnelltop kernel: EXT4-fs (dm-4): mounted filesystem with ordered data mode. Opts: errors=remount-ro
Apr 23 18:18:12 r-schnelltop NetworkManager[985]: <info> startup complete
Apr 23 18:18:14 r-schnelltop lightdm[1559]: pam_unix(lightdm:auth): authentication failure; logname= uid=0 euid=0 tty=:0 ruser= rhost=  user=r
Apr 23 18:18:16 r-schnelltop lightdm[1560]: pam_unix(lightdm:auth): authentication failure; logname= uid=0 euid=0 tty=:0 ruser= rhost=  user=r
Apr 23 18:18:16 r-schnelltop login[1557]: pam_unix(login:session): session opened for user r by LOGIN(uid=0)
Apr 23 18:18:16 r-schnelltop systemd-logind[854]: New session 1 of user r.
Apr 23 18:18:16 r-schnelltop systemd[1562]: pam_unix(systemd-user:session): session opened for user r by (uid=0)
Apr 23 18:18:16 r-schnelltop systemd[1562]: Starting Paths.
Apr 23 18:18:16 r-schnelltop systemd[1562]: Reached target Paths.
Apr 23 18:18:16 r-schnelltop systemd[1562]: Starting Timers.
Apr 23 18:18:16 r-schnelltop systemd[1562]: Reached target Timers.
Apr 23 18:18:16 r-schnelltop systemd[1562]: Starting Sockets.
Apr 23 18:18:16 r-schnelltop systemd[1562]: Reached target Sockets.
Apr 23 18:18:16 r-schnelltop systemd[1562]: Starting Basic System.
Apr 23 18:18:16 r-schnelltop systemd[1562]: Reached target Basic System.
Apr 23 18:18:16 r-schnelltop systemd[1562]: Starting Default.
Apr 23 18:18:16 r-schnelltop systemd[1562]: Reached target Default.
Apr 23 18:18:16 r-schnelltop systemd[1562]: Startup finished in 12ms.
Apr 23 18:18:25 r-schnelltop lightdm[1575]: pam_unix(lightdm:auth): authentication failure; logname= uid=0 euid=0 tty=:0 ruser= rhost=  user=r
Apr 23 18:18:28 r-schnelltop sudo[1576]: r : TTY=tty2 ; PWD=/home/r ; USER=root ; COMMAND=/bin/journalctl -b 0
Apr 23 18:18:28 r-schnelltop sudo[1576]: pam_unix(sudo:session): session opened for user root by r(uid=0)
Apr 23 18:18:28 r-schnelltop lightdm[1577]: pam_unix(lightdm:auth): authentication failure; logname= uid=0 euid=0 tty=:0 ruser= rhost=  user=r