FS#44840 - [systemd] systemd-logind[436]: Failed to enable subscription: Connection timed out
Attached to Project:
Arch Linux
Opened by Razvan Cojocaru (rc) - Monday, 04 May 2015, 07:45 GMT
Last edited by Dave Reisner (falconindy) - Sunday, 12 June 2016, 19:36 GMT
Opened by Razvan Cojocaru (rc) - Monday, 04 May 2015, 07:45 GMT
Last edited by Dave Reisner (falconindy) - Sunday, 12 June 2016, 19:36 GMT
|
Details
Description:
I'm running up-to-date Arch Linux, on a Dell Latitude E5440 laptop with a SSHD Seagate hard drive. Recently (I think I've first noticed it on April 30th), the laptop gets stuck at boot time. Additional info: Systemd is core/libsystemd 219-6. Here's the relevant journalctl part: May 04 09:47:38 dell dhcpcd[440]: eno1: adding address fe80::d8e1:e09c:456f:1751 May 04 09:47:38 dell smartd[439]: smartd 6.3 2014-07-26 r3976 [x86_64-linux-4.0.1-1-ARCH] (local build) May 04 09:47:38 dell smartd[439]: Copyright (C) 2002-14, Bruce Allen, Christian Franke, www.smartmontools.org May 04 09:47:38 dell smartd[439]: Opened configuration file /etc/smartd.conf May 04 09:47:38 dell smartd[439]: Drive: DEVICESCAN, implied '-a' Directive on line 23 of file /etc/smartd.conf May 04 09:47:38 dell smartd[439]: Configuration file /etc/smartd.conf was parsed, found DEVICESCAN, scanning devices May 04 09:47:38 dell smartd[439]: Device: /dev/sda, type changed from 'scsi' to 'sat' May 04 09:47:38 dell smartd[439]: Device: /dev/sda [SAT], opened May 04 09:47:38 dell acpid[435]: starting up with netlink and the input layer May 04 09:47:38 dell smartd[439]: Device: /dev/sda [SAT], ST500LM000-1EJ162, S/N:W760EQNW, WWN:5-000c50-07818c2ee, FW:DEM8, 500 GB May 04 09:47:38 dell acpid[435]: 3 rules loaded May 04 09:48:03 dell acpid[435]: waiting for events: event logging is off May 04 09:48:03 dell smartd[439]: Device: /dev/sda [SAT], found in smartd database: Seagate Laptop SSHD May 04 09:48:03 dell dbus[441]: [system] Successfully activated service 'org.freedesktop.systemd1' May 04 09:48:03 dell dhcpcd[440]: eno1: waiting for carrier May 04 09:48:03 dell dhcpcd[440]: eno1: carrier acquired May 04 09:48:03 dell dbus[441]: [system] Activating via systemd: service name='org.freedesktop.ColorManager' unit='colord.service' May 04 09:48:03 dell systemd[1]: Unit systemd-logind.service entered failed state. May 04 09:48:03 dell systemd[1]: systemd-logind.service failed. May 04 09:47:38 dell systemd[1]: Started D-Bus System Message Bus. May 04 09:48:03 dell systemd-logind[436]: Failed to enable subscription: Connection timed out May 04 09:48:03 dell systemd-logind[436]: Failed to fully start up daemon: Connection timed out May 04 09:48:03 dell systemd[1]: Failed to register name: Connection timed out May 04 09:48:03 dell systemd[1]: Failed to set up API bus: Connection timed out May 04 09:48:03 dell systemd[1]: Starting D-Bus System Message Bus... May 04 09:48:03 dell systemd[1]: Started Restore Sound Card State. May 04 09:48:03 dell systemd[1]: Started Packet Filtering Framework. May 04 09:48:03 dell systemd[1]: Started Permit User Sessions. May 04 09:48:03 dell systemd[1]: systemd-logind.service: main process exited, code=exited, status=1/FAILURE May 04 09:48:03 dell systemd[1]: Failed to start Login Service. May 04 09:48:03 dell systemd[1]: Started Disk protection for HP machines.. May 04 09:48:03 dell haveged[433]: haveged: ver: 1.9.1; arch: x86; vend: GenuineIntel; build: (gcc 4.9.2 ITV); collect: 128K May 04 09:48:03 dell haveged[433]: haveged: cpu: (L4 VC); data: 32K (L4 V); inst: 32K (L4 V); idx: 21/40; sz: 31910/59039 May 04 09:48:03 dell haveged[433]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B): last entropy estimate 8.00123 May 04 09:48:03 dell haveged[433]: haveged: fills: 0, generated: 0 May 04 09:48:03 dell systemd[1]: systemd-logind.service has no holdoff time, scheduling restart. May 04 09:48:03 dell systemd[1]: Cannot add dependency job for unit cups.socket, ignoring: Unit cups.socket failed to load: No such fil May 04 09:48:03 dell systemd[1]: Cannot add dependency job for unit acpid.socket, ignoring: Unit acpid.socket failed to load: No such f May 04 09:48:03 dell dhcpcd[440]: DUID 00:01:00:01:1b:80:f1:b6:ec:f4:bb:4a:ce:f9 May 04 09:48:03 dell dhcpcd[440]: eno1: IAID bb:4a:ce:f9 May 04 09:48:03 dell systemd[1]: Cannot add dependency job for unit cups.socket, ignoring: Unit cups.socket failed to load: No such fil May 04 09:48:03 dell systemd[1]: Cannot add dependency job for unit acpid.socket, ignoring: Unit acpid.socket failed to load: No such f May 04 09:48:03 dell smartd[439]: Device: /dev/sda [SAT], is SMART capable. Adding to "monitor" list. May 04 09:48:03 dell smartd[439]: Monitoring 1 ATA and 0 SCSI devices May 04 09:48:03 dell systemd[1]: Looping too fast. Throttling execution a little. May 04 09:48:03 dell dhcpcd[440]: eno1: rebinding lease of 192.168.228.128 May 04 09:48:04 dell dhcpcd[440]: eno1: soliciting an IPv6 router May 04 09:48:04 dell systemd[1]: Started System Logger Daemon. May 04 09:48:04 dell systemd[1]: Looping too fast. Throttling execution a little. May 04 09:48:06 dell systemd[1]: Looping too fast. Throttling execution a little. May 04 09:48:07 dell systemd[1]: Looping too fast. Throttling execution a little. May 04 09:48:08 dell systemd[1]: Looping too fast. Throttling execution a little. May 04 09:48:08 dell dhcpcd[440]: timed out May 04 09:48:08 dell dhcpcd[440]: dhcpcd exited May 04 09:48:09 dell systemd[1]: dhcpcd@eno1.service: control process exited, code=exited status=1 May 04 09:48:09 dell systemd[1]: Failed to start dhcpcd on eno1. May 04 09:48:09 dell systemd[1]: Unit dhcpcd@eno1.service entered failed state. May 04 09:48:09 dell systemd[1]: dhcpcd@eno1.service failed. May 04 09:48:09 dell systemd[1]: Looping too fast. Throttling execution a little. May 04 09:48:10 dell systemd[1]: Looping too fast. Throttling execution a little. -- Reboot -- Where it says "-- Reboot --" I had to kill it by holding the power on / off button until the computer shut down. On restart, fsck looks at the disk and then all seems fine - until the next time this happens out of the blue. Steps to reproduce: Just start the machine, it seems to happen roughly in no more than 10 power ons. |
This task depends upon
Closed by Dave Reisner (falconindy)
Sunday, 12 June 2016, 19:36 GMT
Reason for closing: Fixed
Additional comments about closing: see upstream bug: https://github.com/systemd/systemd/issue s/1505
Sunday, 12 June 2016, 19:36 GMT
Reason for closing: Fixed
Additional comments about closing: see upstream bug: https://github.com/systemd/systemd/issue s/1505
during boot, systemd logs there errors :
systemd[1]: Failed to subscribe to activation signal: Connection timed out
systemd[1]: Failed to register name: Connection timed out
systemd[1]: Failed to set up API bus: Connection timed out
...
dbus[898]: [system] Failed to activate service 'org.freedesktop.ColorManager': timed out
dbus[898]: [system] Failed to activate service 'org.freedesktop.hostname1': timed out
dbus[898]: [system] Failed to activate service 'org.freedesktop.Avahi': timed out
the boot is stuck about 1mn then continues to reach graphical target.
Then, when i'm logging the session takes a long time to startup, and I see these errors :
kdm[1968]: :0[1968]: pam_systemd(kde:session): Failed to create session: Connection timed out
dbus[898]: [system] Failed to activate service 'org.freedesktop.UDisks2': timed out
dbus[898]: [system] Activating via systemd: service name='org.freedesktop.UDisks2' unit='udisks2.service'
dbus[898]: [system] Failed to activate service 'org.freedesktop.UDisks2': timed out
dbus[898]: [system] Activating via systemd: service name='org.freedesktop.UDisks2' unit='udisks2.service'
dbus[898]: [system] Activating via systemd: service name='org.freedesktop.UPower' unit='upower.service'
dbus[898]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon
dbus[898]: [system] Failed to activate service 'org.freedesktop.UDisks2': timed out
dbus[898]: [system] Activating via systemd: service name='org.freedesktop.UDisks2' unit='udisks2.service'
dbus[898]: [system] Failed to activate service 'org.freedesktop.UPower': timed out
dbus[898]: [system] Activating via systemd: service name='org.freedesktop.UPower' unit='upower.service'
dbus[898]: [system] Failed to activate service 'org.freedesktop.RealtimeKit1': timed out
dbus[898]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon
dbus[898]: [system] Failed to activate service 'org.freedesktop.UDisks2': timed out
dbus[898]: [system] Activating via systemd: service name='org.freedesktop.UDisks2' unit='udisks2.service'
dbus[898]: [system] Failed to activate service 'org.freedesktop.UPower': timed out
dbus[898]: [system] Failed to activate service 'org.freedesktop.RealtimeKit1': timed out
dbus[898]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon
dbus[898]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service
dbus[898]: [system] Activating via systemd: service name='org.freedesktop.UPower' unit='upower.service'
dbus[898]: [system] Failed to activate service 'org.freedesktop.UDisks2': timed out
logging at the console behaves identically :
login[2055]: pam_systemd(login:session): Failed to create session: Connection timed out
I reboot, then all works fine again :(
It looks like a race condition bug during system boot. It seems that dbus daemon miss behaves.
I have attached a 'systemd-analyse plot' on a boot when this bug happens.
failedboot2.txt (746.5 KiB)
failedboot3.txt (527.2 KiB)
FS#44016?https://bugs.archlinux.org/task/44016
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=778970
"One of the symptoms of this issue seems to be, that dbus doesn't seem to work properly and daemons like systemd-logind time out."
If so, systemd 220 in [testing] should fix the issue.
screwy_boot_plus_startx.txt (484.8 KiB)
https://github.com/systemd/systemd/issues/1505