Bug#769069: systemd: Failed to start Login Service

[Martin Pitt]

Control: tag -1 moreinfo

Hello Paul,

Paul Menzel [2014-11-11 8:40 +0100]:
> starting the Debian Sid/unstable system this morning, it did not boot.
>
> `Failed to start Login Service` was shown repeatedly as trying to start
> it again did not work.

Can you please boot with adding "systemd.debug-shell" to the kernel
command line in grub, then after the failure press Alt+F9 to get to
the debug root shell? There you can run
"systemctl status systemd-logind.service" to see what's going on.

Thanks,

Martin

--
Martin Pitt | http://www.piware.de
Ubuntu Developer (www.ubuntu.com) | Debian Developer (www.debian.org)

[Michael Biebl]

Sounds like dbus is not installed. Paul, can you confirm that?

Am 11. November 2014 08:55:00 MEZ, schrieb Martin Pitt <mp...@debian.org>:

Control: tag -1 moreinfo

Hello Paul,

Paul Menzel [2014-11-11  8:40 +0100]:
 starting the Debian Sid/unstable system this morning, it did not boot.
 
 `Failed to start Login Service` was shown repeatedly as trying to start
 it again did not work.

Can you please boot with adding "systemd.debug-shell" to the kernel
command line in grub, then after the failure press Alt+F9 to get to
the debug root shell? There you can run
"systemctl status systemd-logind.service" to see what's going on.

Thanks,

Martin

--

Diese Nachricht wurde von meinem Android-Mobiltelefon mit K-9 Mail gesendet.

[Paul Menzel]

Am Dienstag, den 11.11.2014, 13:34 +0100 schrieb Michael Biebl:
> Sounds like dbus is not installed. Paul, can you confirm that?

It is installed. The failure happened with 1.8.8-2, now it was upgraded
to 1.8.10-1.

> Am 11. November 2014 08:55:00 MEZ, schrieb Martin Pitt <mp...@debian.org>:

> >Paul Menzel [2014-11-11 8:40 +0100]:
> >> starting the Debian Sid/unstable system this morning, it did not boot.
> >>
> >> `Failed to start Login Service` was shown repeatedly as trying to start
> >> it again did not work.
> >
> >Can you please boot with adding "systemd.debug-shell" to the kernel
> >command line in grub, then after the failure press Alt+F9 to get to
> >the debug root shell? There you can run
> >"systemctl status systemd-logind.service" to see what's going on.

It only happened once until now. I have no idea how to reproduce it.


Thanks,

Paul

[Michael Biebl]

Since it's not reproducible and if you have no further logs from the
incident, I'd suggest we close the bug report and re-open once you run
into it again and can reproduce it.

Are you ok with that?


--
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[Paul Menzel]

Not yet. ;-) Does the following help?

$ journalctl -b -3 -u dbus.service -u logind.service
-- Logs begin at Sa 2014-09-27 16:08:57 CEST, end at Mi 2014-11-12 09:41:28 CET. --
Nov 11 07:45:46 asrock-350m1 dbus[945]: [system] Activating systemd to hand-off: service name='org.freedesktop.PolicyKit1' unit='polkitd.servi
Nov 11 07:45:58 asrock-350m1 dbus[945]: [system] Activating systemd to hand-off: service name='org.freedesktop.login1' unit='dbus-org.freedesk
Nov 11 07:46:16 asrock-350m1 dbus[945]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
Nov 11 07:46:16 asrock-350m1 dbus[945]: [system] Failed to activate service 'org.freedesktop.PolicyKit1': timed out
Nov 11 07:46:16 asrock-350m1 dbus[945]: [system] Activating systemd to hand-off: service name='org.freedesktop.Avahi' unit='dbus-org.freedeskt
Nov 11 07:46:23 asrock-350m1 dbus[945]: [system] Failed to activate service 'org.freedesktop.login1': timed out
Nov 11 07:46:23 asrock-350m1 dbus[945]: [system] Activating systemd to hand-off: service name='org.freedesktop.PolicyKit1' unit='polkitd.servi
Nov 11 07:46:41 asrock-350m1 dbus[945]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
Nov 11 07:46:41 asrock-350m1 dbus[945]: [system] Failed to activate service 'org.freedesktop.Avahi': timed out
Nov 11 07:46:48 asrock-350m1 dbus[945]: [system] Failed to activate service 'org.freedesktop.PolicyKit1': timed out
Nov 11 07:46:52 asrock-350m1 dbus[945]: [system] Activating systemd to hand-off: service name='fi.w1.wpa_supplicant1' unit='wpa_supplicant.ser
Nov 11 07:46:52 asrock-350m1 dbus[945]: [system] Activating systemd to hand-off: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.f
Nov 11 07:47:06 asrock-350m1 dbus[945]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
Nov 11 07:47:17 asrock-350m1 dbus[945]: [system] Failed to activate service 'fi.w1.wpa_supplicant1': timed out
Nov 11 07:47:17 asrock-350m1 dbus[945]: [system] Failed to activate service 'org.freedesktop.nm_dispatcher': timed out
Nov 11 07:47:31 asrock-350m1 dbus[945]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
Nov 11 07:47:56 asrock-350m1 dbus[945]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
Nov 11 07:48:21 asrock-350m1 dbus[945]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
Nov 11 07:48:46 asrock-350m1 dbus[945]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
$ journalctl -b -3 -u systemd-logind.service
-- Logs begin at Sa 2014-09-27 16:08:57 CEST, end at Mi 2014-11-12 09:41:28 CET. --
Nov 11 07:46:11 asrock-350m1 systemd[1]: systemd-logind.service: main process exited, code=exited, status=1/FAILURE
Nov 11 07:46:11 asrock-350m1 systemd[1]: Failed to start Login Service.
Nov 11 07:46:11 asrock-350m1 systemd[1]: Unit systemd-logind.service entered failed state.
Nov 11 07:46:41 asrock-350m1 systemd[1]: systemd-logind.service: main process exited, code=exited, status=1/FAILURE
Nov 11 07:46:41 asrock-350m1 systemd[1]: Failed to start Login Service.
Nov 11 07:46:41 asrock-350m1 systemd[1]: Unit systemd-logind.service entered failed state.
Nov 11 07:47:06 asrock-350m1 systemd[1]: systemd-logind.service: main process exited, code=exited, status=1/FAILURE
Nov 11 07:47:06 asrock-350m1 systemd[1]: Failed to start Login Service.
Nov 11 07:47:06 asrock-350m1 systemd[1]: Unit systemd-logind.service entered failed state.
Nov 11 07:47:31 asrock-350m1 systemd[1]: systemd-logind.service: main process exited, code=exited, status=1/FAILURE
Nov 11 07:47:31 asrock-350m1 systemd[1]: Failed to start Login Service.
Nov 11 07:47:31 asrock-350m1 systemd[1]: Unit systemd-logind.service entered failed state.
Nov 11 07:47:56 asrock-350m1 systemd[1]: systemd-logind.service: main process exited, code=exited, status=1/FAILURE
Nov 11 07:47:56 asrock-350m1 systemd[1]: Failed to start Login Service.
Nov 11 07:47:56 asrock-350m1 systemd[1]: Unit systemd-logind.service entered failed state.
Nov 11 07:48:21 asrock-350m1 systemd[1]: systemd-logind.service: main process exited, code=exited, status=1/FAILURE
Nov 11 07:48:21 asrock-350m1 systemd[1]: Failed to start Login Service.
Nov 11 07:48:21 asrock-350m1 systemd[1]: Unit systemd-logind.service entered failed state.
Nov 11 07:48:46 asrock-350m1 systemd[1]: systemd-logind.service: main process exited, code=exited, status=1/FAILURE
Nov 11 07:48:46 asrock-350m1 systemd[1]: Failed to start Login Service.
Nov 11 07:48:46 asrock-350m1 systemd[1]: Unit systemd-logind.service entered failed state.


Thanks,

Paul

[Michael Biebl]

Am 12.11.2014 um 09:45 schrieb Paul Menzel:
> Am Mittwoch, den 12.11.2014, 02:10 +0100 schrieb Michael Biebl:

>> incident, I'd suggest we close the bug report and re-open once you run
>> into it again and can reproduce it.
>>
>> Are you ok with that?
>
> Not yet. ;-) Does the following help?

Not quite, all it shows is that the problem is most likely in dbus and
not systemd itself. As you can see, other D-Bus activated services fail
as well.

[Simon McVittie]

On 12/11/14 13:33, Michael Biebl wrote:
> Not quite, all it shows is that the problem is most likely in dbus and
> not systemd itself.

Based on the log you quoted, I'm not sure I agree. The problem is
certainly in the interaction between dbus and systemd, but it doesn't
look as though systemd is doing its side of that interaction by
connecting to the system dbus-daemon?

Paul, while you still have the relevant logs, could you please provide
the full journalctl output or syslog for the boot in question, or if
that's too large or too private, at least a censored version, or the
lines for dbus.service and systemd itself?

This might help:

journalctl -b -3 _PID=1 _PID=945

or maybe

journalctl -b -3 SYSLOG_IDENTIFIER=systemd SYSLOG_IDENTIFIER=dbus

> As you can see, other D-Bus activated services fail
> as well.

...

>> $ journalctl -b -3 -u dbus.service -u logind.service
>> -- Logs begin at Sa 2014-09-27 16:08:57 CEST, end at Mi 2014-11-12 09:41:28 CET. --
>> Nov 11 07:45:46 asrock-350m1 dbus[945]: [system] Activating systemd to hand-off: service name='org.freedesktop.PolicyKit1' unit='polkitd.servi
>> Nov 11 07:45:58 asrock-350m1 dbus[945]: [system] Activating systemd to hand-off: service name='org.freedesktop.login1' unit='dbus-org.freedesk
>> Nov 11 07:46:16 asrock-350m1 dbus[945]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
>> Nov 11 07:46:16 asrock-350m1 dbus[945]: [system] Failed to activate service 'org.freedesktop.PolicyKit1': timed out
>> Nov 11 07:46:16 asrock-350m1 dbus[945]: [system] Activating systemd to hand-off: service name='org.freedesktop.Avahi' unit='dbus-org.freedeskt
>> Nov 11 07:46:23 asrock-350m1 dbus[945]: [system] Failed to activate service 'org.freedesktop.login1': timed out

When running dbus-daemon --system --systemd-activation (as we do under
systemd) and a D-Bus system service is marked as having a corresponding
systemd service, dbus-daemon does not activate the service itself: it
just waits for systemd to connect to the system dbus-daemon and claim
its well-known bus name org.freedesktop.systemd1, then sends systemd a
request "hey, activate this for me please?" and waits for it to happen.

There are two possible places for this to time out: either systemd does
not connect to the dbus-daemon, or systemd does connect to dbus-daemon,
dbus-daemon sends the request, but the service is never started or never
takes its name.

In this log, it looks as though systemd has not connected to
dbus-daemon. There isn't a whole lot dbus-daemon can do about that...

S


--
To UNSUBSCRIBE, email to debian-bugs-...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org

[Simon McVittie]

Unfortunately I don't see a "smoking gun" in your log.

It looks as though the system might have been having performance
issues in general:

On 13/11/14 23:36, Paul Menzel wrote:
> Nov 11 07:45:44 asrock-e350m1 systemd[1]: Looping too fast.
> Throttling execution a little.

which might have contributed to timeouts, possibly?

> Nov 11 07:45:33 asrock-e350m1 systemd-remount-fs[385]: mount: /usr
> not mounted or bad option Nov 11 07:45:33 asrock-e350m1
> systemd-remount-fs[385]: In some cases useful info is found in
> syslog - try Nov 11 07:45:33 asrock-e350m1 systemd-remount-fs[385]:
> dmesg | tail or so.

I don't know whether this is related but it doesn't look great. Is
this a known problem that you have subsequently fixed?

> Nov 11 07:46:16 asrock-e350m1 NetworkManager[942]: <info> caught
> signal 15, shutting down normally. Nov 11 07:46:16 asrock-e350m1
> avahi-daemon[929]: Got SIGTERM, quitting.
...
> Nov 11 07:46:52 asrock-e350m1 NetworkManager[942]: <info> startup
> complete Nov 11 07:46:52 asrock-e350m1 NetworkManager[942]: <info>
> exiting (success)

Any idea why these might have happened? They both use libdbus, so
getting disconnected from D-Bus with exit-on-disconnect enabled would
cause an _exit(1) rather than the raise(SIGTERM) you'd get from GDBus.

It looks vaguely as though *everything* on the system bus might have
been failing to connect to it?

Did you / do you have any unusual systemd or dbus configuration in use?

If you can't reproduce this, then I don't think we'll be able to work
out what is going on from that log, sorry.

[Sjoerd Simons]

On Sat, Nov 15, 2014 at 01:16:36AM +0100, Paul Menzel wrote:

> Am Freitag, den 14.11.2014, 10:18 +0000 schrieb Simon McVittie:
> > > signal 15, shutting down normally. Nov 11 07:46:16 asrock-e350m1
> > > avahi-daemon[929]: Got SIGTERM, quitting.
> > ...
> > > Nov 11 07:46:52 asrock-e350m1 NetworkManager[942]: <info> startup
> > > complete Nov 11 07:46:52 asrock-e350m1 NetworkManager[942]: <info>
> > > exiting (success)
> >
> > Any idea why these might have happened? They both use libdbus, so
> > getting disconnected from D-Bus with exit-on-disconnect enabled would
> > cause an _exit(1) rather than the raise(SIGTERM) you'd get from GDBus.
> >
> > It looks vaguely as though *everything* on the system bus might have
> > been failing to connect to it?
> >
> > Did you / do you have any unusual systemd or dbus configuration in use?
>

> Not that I know of. I am using the packaged configuration.

Yes this indeed looks like nothing can connect to the systemd bus.

>
> > If you can't reproduce this, then I don't think we'll be able to work
> > out what is going on from that log, sorry.
>

> It happened again, but I forgot to add the systemd debug stuff. It
> stopped for a while after the start message of D-Bus and then continued
> until the point where the “Logind failed to start” messages were shown.

One thing stood out:
> Nov 14 23:39:05 asrock-e350m1 systemd[1]: var.mount: Directory /var to mount over is not empty, mounting anyway.

The dbus system socket is in unix:path=/var/run/dbus/system_bus_socket. So one
possible explanation might be that your just mounted a file system over the
/var/run dbus got its socket put in..

In principle this should not occur, but lets first work out if my theory is
correct. Could you:

0: Check where your final /var/run/ is pointing to (should a symlink to /run)
1: If it isn't a symlink, can you check whats in both the /var/run of your /var
partition *and* the var of your / partition (to see if you masked out the
dbus socket in any way)

--
When you know absolutely nothing about the topic, make your forecast by
asking a carefully selected probability sample of 300 others who don't
know the answer either.
-- Edgar R. Fiedler

[Paul Menzel]

From a working boot, the symlink is correct.

$ ls -l /var/run
lrwxrwxrwx 1 root root 4 Mai 17 2011 /var/run -> /run

> 1: If it isn't a symlink, can you check whats in both the /var/run of your /var
> partition *and* the var of your / partition (to see if you masked out the
> dbus socket in any way)

When I hit this bug, I could not log in (probably due to logind not
running). The login prompt was shown and I was able to enter a password
but I could not log in and the shell was not usable.

Can I check what is going wrong in the systemd debug shell next time I
hit the problem?


Thanks,

Paul

[Simon McVittie]

On 15/11/14 00:16, Paul Menzel wrote:
> Am Freitag, den 14.11.2014, 10:18 +0000 schrieb Simon McVittie:

>> It looks as though the system might have been having performance
>> issues in general:

...

>> which might have contributed to timeouts, possibly?

I happened to notice (via LWN) that Mageia have reverted part of a
recent dbus denial-of-service fix. If D-Bus connections on your system
are legitimately taking more than 5 seconds to complete
authentication, then that could be causing this.

You could test that by adding

<limit name="auth_timeout">30000</limit>

to /etc/dbus-1/system.conf (just above the </busconfig> would work,
look at session.conf to see the right syntax). That would revert that
change, bringing it back up to 30 seconds.

I'll look into adding logging when this timeout is hit.

[Simon McVittie]

On 17/11/14 23:12, Simon McVittie wrote:
> I happened to notice (via LWN) that Mageia have reverted part of a
> recent dbus denial-of-service fix.

Now discussed upstream at
<https://bugs.freedesktop.org/show_bug.cgi?id=86431>

> I'll look into adding logging when this timeout is hit.

Paul, would you mind trying a patched dbus which can confirm whether
you're hitting this timeout or something else? Source and i386 binaries
here, with hashes signed by my key in the Debian keyring:

<https://www.pseudorandom.co.uk/~smcv/20141118dbus/>

or if you're comfortable rebuilding Debian packages, you can rebuild
dbus with the logging patch from
<https://bugs.freedesktop.org/show_bug.cgi?id=86431#c4>, like this:
<https://www.pseudorandom.co.uk/~smcv/20141118dbus/dbus_1.8.10-1+auth1.diff>.

With that installed, please configure dbus for the potentially
problematic 5-second timeout: if you have already configured a custom
<limit name="auth_timeout">, please remove it. Then reboot enough times
to see the bad behaviour, and collect the syslog or journalctl.

You can set an arbitrary timeout in milliseconds by putting something
like this in /etc/dbus-1/system-local.conf:

<busconfig>

<limit name="auth_timeout">30000</limit>

</busconfig>

The old default was 30000, and if this is indeed what's causing your
startup problems, I'm proposing to return to that.

On the oldest machine I had conveniently to hand, running testing with
systemd and the GNOME desktop task, I could go as low as 100 (0.1
second) and get to the gdm prompt without seeing any problems. 5 (0.005
seconds) caused ModemManager to fail, and 1 (0.001 seconds) caused lots
of services to fail, including systemd-logind.

[Paul Menzel]

Simon, thank you for looking into this further and the detailed reply!

I want to try this, but I won’t be able to do so before Sunday. :(

Here are the current timeout settings on my system.

$ sudo grep -Ri timeout /etc/dbus-1
/etc/dbus-1/session.conf: <limit name="service_start_timeout">120000</limit>
/etc/dbus-1/session.conf: <limit name="auth_timeout">240000</limit>
/etc/dbus-1/session.conf: <limit name="pending_fd_timeout">150000</limit>
$ ls -l /etc/dbus-1/session.conf
-rw-r--r-- 1 root root 2883 Sep 16 18:37 /etc/dbus-1/session.conf
$ md5sum /etc/dbus-1/session.conf
e88aa2383587cc773443d9be08e5a838 /etc/dbus-1/session.conf


Thanks,

Paul

[Simon McVittie]

On 18/11/14 22:44, Paul Menzel wrote:
> Here are the current timeout settings on my system.

Thanks. The session bus' timeouts are not relevant to the system bus,
which is what's breaking for you.

The system bus' default timeouts are hard-coded inside dbus-daemon, and
rarely overridden, so if you haven't taken steps to alter them (which
you don't seem to have done), they're at defaults. I reduced the
hard-coded default in 1.8.8 for CVE-2014-3639.