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
Task Type Bug Report
Category Packages: Core
Status Closed
Assigned To Thomas Bächler (brain0)
Dave Reisner (falconindy)
Architecture x86_64
Severity High
Priority Normal
Reported Version
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 8
Private No

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
Comment by Steven Noonan (neunon) - Friday, 08 May 2015, 21:32 GMT
I've been seeing this happen on multiple systems off and on -- one of which refuses to boot because it's failing to start systemd-logind 100% of the time. I am not at all clear on why this is happening yet.
Comment by Steven Noonan (neunon) - Friday, 08 May 2015, 22:23 GMT
On the system reproducing the issue 100% of the time, I downgraded systemd to 217 and things started behaving. So this appears to be a regression.
Comment by Frank Carlyle McLaughlin (frankspace) - Saturday, 16 May 2015, 01:18 GMT
I am also having this problem intermittently on bootup. I am using the latest version 219-6 of systemd. Every so often bootup simply hangs until I power-cycle, and usually, but not always, the machine boots fine the next try. Journalctl indicates that systemd is repeatedly spitting out "Looping too fast. Throttling execution a little." when this occurs. The only thing I notice that appears to happen at the same time is that the systemd-logind.service fails.
Comment by AK (Andreaskem) - Saturday, 16 May 2015, 08:43 GMT
I would assume passing the "debug" kernel parameter would allow you to get more verbose systemd output to help debug this issue.
Comment by hamelg (hamelg) - Monday, 18 May 2015, 12:39 GMT
I encounter this bug.

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.
Comment by Frank Carlyle McLaughlin (frankspace) - Friday, 29 May 2015, 01:01 GMT
Okay, I added "debug" to the kernel parameters. Things go weird at different points in the boot process. I'm attaching a few failed boots on a couple of different machines. One of them went all the way to the login, albeit very slowly, and eventually ran aground when I tried to reboot. All of these eventually ended in me having to power off with the physical power button. For what it's worth, "Mondas" is a Thinkpad X230, and "Gallifrey" is a somewhat elderly desktop. EDIT: sorry, didn't realize I can attach multiple files. Editing this comment to attach all at once. Sorry.
Comment by AK (Andreaskem) - Saturday, 30 May 2015, 08:22 GMT
Might be related / identical to  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.
Comment by Frank Carlyle McLaughlin (frankspace) - Monday, 08 June 2015, 03:43 GMT
Could be; I'm not a programmer but the problem sure does seem give a very convincing impression of systemd choking on itself somehow. For whatever it's worth, the most recent update to dbus 1.8.18 did NOT fix the problem.
Comment by Frank Carlyle McLaughlin (frankspace) - Tuesday, 09 June 2015, 02:12 GMT
I've had a couple of screwed-up boots that made it to a login prompt; it's obvious that something is wrong simply because actually logging in takes a very long time. I don't boot directly into a graphical environment; if I startx, my desktop shows up and all but I can't interact with it in any way and have to power off with the power button. I've attached the two most recent such boots, one of which I immediately shut down and the other of which I went to X and had to use the power button. In case this is helpful to anyone.
Comment by AK (Andreaskem) - Thursday, 11 June 2015, 18:29 GMT
Did anybody try systemd 220? All the logs are from 219.
Comment by Dave Reisner (falconindy) - Sunday, 12 June 2016, 19:00 GMT
Is this still a problem with v230?
Comment by hamelg (hamelg) - Sunday, 12 June 2016, 19:29 GMT

Loading...