[systemd-devel] systemd+dbus: system boot stops at terminal login screen sometimes

[Chen Jie]

Hey,

2011/12/1 Chen Jie <chenj at lemote.com>:
> Hi,
>
> Thanks for the reply.
>
> 2011/11/30 Michal Schmidt <mschmidt at redhat.com>:
>> On 11/30/2011 10:49 AM, Chen Jie wrote:
>>>
>>> (see the full syslog at
>>>
>>> http://lists.freedesktop.org/archives/dbus/attachments/20111125/e9c204bb/attachment-0001.obj)
>>
>>
>> The kernel modules failing to load indicate a problem with your kernel
>> installation. Please sort this problem out first before attempting to debug
>> anything else.
> I didn't install the modules of matched version for convenient. I've
> built-in basic modules, and this problem can be easily reproduced on a
> "sanity" kernel (just do a repeat reboot).
>
> I added more logs, and found two paths may cause the
> "bus_context_log()" to spend ~25s -- then "Failed to add_match for
> 'NameOwnerChanged' in bus_init_api():
> 1. "ExecStartPre=/bin/systemctl stop systemd-kmsg-syslogd.service"
> spent too much time in need_daemon_reload(), it encountered timeout at
> http://cgit.freedesktop.org/systemd/tree/src/systemctl.c?id=v29#n1080
>
> 2. In http://cgit.freedesktop.org/systemd/tree/src/manager.c?id=v29#n2051,
> a previous "UNIT_VTABLE(u)->sigchld_event" spent too much time
> ((1322740559, 397870)->(1322740585,528000))

After did many experiments, I found it was one iteration of
manager_loop spent ~25s:
* dbus.service: service_enter_start_post()
 -> service_enter_running()
 --> service_set_state(s, SERVICE_RUNNING)
 ---> unit_notify()
 ----> bus_init() -> bus_init_api()
bus_ini_api()  failed to add_match for 'NameOwnerChanged' (reason:
timeout, and the default timeout value in dbus lib was 25s)

In another hand, dbus-daemon failed to reply in time because it tried
to log a message, meanwhile rsyslog.service was starting:
1. In ExecStartPre stage(/bin/systemctl stop
systemd-kmsg-syslogd.service), systemctl failed to receive replies in
time because the manager_loop of systemd was blocked!   or
2. After ExecStartPre stage, manager_loop was blocked for 25s, and
then do ExecStart.

Then dbus-daemon prompted "Failed to activate service
'org.freedesktop.systemd1': timed out", and then entered a busy-loop
in pending_activation_failed()
http://cgit.freedesktop.org/dbus/dbus/tree/bus/activation.c?id=7dbfa45153167ee53487630f8109d32860cb6263#n1280
(An _dbus_return_val_if_fail(reply_serial != 0, FALSE)  failure was
observed in gdb, still don't how this happened)



Regards,
-- Chen Jie