systemd+dbus: system boot stops at terminal login screen sometimes

[Chen Jie]

Hi all,

I found my system boot stops at terminal login screen sometimes under
systemd v29 + dbus 1.4.16. I tried to login, after supplied username
and password, it blocked with a blinking cursor.

A primary debug shows:
* dbus-daemon was doing a busy-loop in pending_activation_failed()
(see http://lists.freedesktop.org/archives/dbus/2011-November/014790.html)
* There was a message "Failed to activate service
'org.freedesktop.systemd1': timed out" in syslog (see the full syslog
at http://lists.freedesktop.org/archives/dbus/attachments/20111125/e9c204bb/attachment-0001.obj)

After I added more log funcs with gettimeofday generated timestamp
"(tv_sec, tv_usec)", I found:
* bus_init_api() calling dbus_bus_add_match failed with timeout -- the
function starts at (1322641754,371276), ends at  (1322641779,396943)
* In dbus side, I found it spends ~25s to send a log to syslog:
timestamp: (1322641754,372197)
bus_context_log (activation->context,
                               DBUS_SYSTEM_LOG_INFO, "Activating
systemd to hand-off: service name='%s' unit='%s'",
                               service_name,
                               entry->systemd_service);    //
bus_activation_activate_service() @bus/activation.c
timestamp: (1322641780,555)

I guess there was something wrong with startup of rsyslog.service, and I found:
* (1322641752,26061): [rsyslog.service]service_enter_start_pre()
* (1322641753,382491): systemd-kmsg-syslogd[705]: systemd-kmsg-syslogd
stopped as pid 705
* (1322641779,692927): [rsyslog.service]service_enter_start()

Start rsyslog.service will stop systemd-kmsg-syslogd.service first, so
I added more log funcs in systemctl:
* systemctl[1216]: start_unit_one(): (1322641753,229083)->(1322641753,383118)
* systemctl[1216]: wait_filter() (1322641753,465392)Got D-Bus request:
org.freedesktop.systemd1.Manager.JobRemoved() on
/org/freedesktop/systemd1
* systemctl[1216]: wait_for_jobs(): (1322641753,468987) finished
"while (!set_isempty(s) &&dbus_connection_read_write_dispatch(bus,
-1))"
systemctl stop systemd-kmsg-syslogd.service didn't much time.


The content of rsyslog.service:
[Unit]
Description=System Logging Service

[Service]
ExecStartPre=/bin/systemctl stop systemd-kmsg-syslogd.service
ExecStart=/usr/sbin/rsyslogd -n -c5
Sockets=syslog.socket

[Install]
WantedBy=multi-user.target


Any idea?

BTW, the gap between systemd-kmsg-syslogd.service stopped and rsyslog
not ready will make it lost some log messages.



Regards,
--- Chen Jie