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

[Chen Jie]

2011/12/2 Chen Jie <chenj at lemote.com>:
> Hey,
> 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)

Let me explain it further.
First syslogv() in dbus may block, while rsyslog.service is starting
and meanwhile the kernel socket buffer was full.
Attachment syslog-test.c was a program simulates the situation.

So while rsyslog.service is starting, on the systemd side:
1. [ExecStartPre] stops systemd-kmsg-syslogd.service
2. It now running bus_init() to publish its API to dbus
3. Step 2 timeout, because dbus-daemon didn't reply in time.

Why dbus-daemon didn't response quickly? Because it blocked on
syslogv(), which was waiting for someone consumes the message(the
kernel socket buffer was full), but sadly the consumer -- rsyslog
didn't be started because systemd blocked.

So systemd waits for dbus, and dbus waits for startup of rsyslog,
rsyslog waits for systemd to start it.

IMHO, We need to put functions that may block in separate threads, for
example bus_init(), shutdown_connection(), log_meta().

Attachment 0001-Add-new-API-manager_add_work_thread.patch and
0002-dbus.c-hooks-to-the-manager_add_work_thread-API.patch are two
patches that make bus_init run in thread and hence not block the
manager_loop.



Regards,
-- Chen Jie
-------------- next part --------------
A non-text attachment was scrubbed...
Name: syslog-test.c
Type: text/x-csrc
Size: 971 bytes
Desc: not available
URL: <http://lists.freedesktop.org/archives/dbus/attachments/20111214/942cdc2d/attachment-0001.c>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 0001-Add-new-API-manager_add_work_thread.patch
Type: text/x-patch
Size: 11016 bytes
Desc: not available
URL: <http://lists.freedesktop.org/archives/dbus/attachments/20111214/942cdc2d/attachment-0002.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 0002-dbus.c-hooks-to-the-manager_add_work_thread-API.patch
Type: text/x-patch
Size: 21983 bytes
Desc: not available
URL: <http://lists.freedesktop.org/archives/dbus/attachments/20111214/942cdc2d/attachment-0003.bin>