[systemd-devel] service timeout during startup

[Johnny Karlsson]

Hi!

I'm investigating an issue with systemd(225) services that has
type=Dbus which time out during startup. I've also tested om 228 and
the problem doesn't seem to occur any more but I would like to be sure
that it's solved in the later version. It could be related to
https://github.com/systemd/systemd/issues/2019

This issue doesn't happen all the time but quite often and during
early startup when there is high system load. Basically systemd logs
"..Start operation timed out.Terminating", but I can confirm that the
services actually has started and it has appears on the bus. I've
added some tracing trying to figure out what is happening.

I created a small service that just runs "ExecStart=/bin/bash -c
'/usr/bin/busctl monitor org.freedesktop.DBus'" which will print out
when a service appears on the bus.
I have also added some debug traces in the systemd source in
src/core/unit.c for the functions unit_install_bus_match and the
callback signal_name_owner_changed so that I can see when systemd
calls AddMatch and when the callback is called:

diff --git a/src/core/unit.c b/src/core/unit.c
index 43a5ca1..cc61b9b 100644
--- a/src/core/unit.c
+++ b/src/core/unit.c
@@ -2517,6 +2517,8 @@ static int
signal_name_owner_changed(sd_bus_message *message, void *userdata, sd
                 return 0;
         }

+       log_warning("!!Got name owner changed: %s New owner:
%s",new_owner, name);
+
         if (UNIT_VTABLE(u)->bus_name_owner_change)
                 UNIT_VTABLE(u)->bus_name_owner_change(u, name,
old_owner, new_owner);

@@ -2543,7 +2545,8 @@ int unit_install_bus_match(sd_bus *bus, Unit *u,
const char *name) {
                         NULL);
         if (!match)
                 return -ENOMEM;
-
+
+       log_warning("!Adding bus match: %s", match);
         return sd_bus_add_match(bus, &u->match_bus_slot, match,
signal_name_owner_changed, u);
 }



so the log, for testing purposes I have DefaultTimeoutStartSec=20s:

[    1.592474] test-target systemd[1]: !Adding bus match:
type='signal',sender='org.freedesktop.DBus',path='/org/freedesktop/DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',arg0='com.test.exampleservice'
.
.
[    2.507479] test-target bash[1826]: ‣ Type=signal  Endian=l
Flags=1  Version=1  Priority=0 Cookie=13
[    2.507770] test-target bash[1826]: Sender=org.freedesktop.DBus
Path=/org/freedesktop/DBus  Interface=org.freedesktop.DBus
Member=NameOwnerChanged
[    2.508055] test-target bash[1826]: MESSAGE "sss" {
[    2.508314] test-target bash[1826]: STRING ":1.30";
[    2.508586] test-target bash[1826]: STRING "";
[    2.508845] test-target bash[1826]: STRING ":1.30";
[    2.509146] test-target bash[1826]: };
[    2.509400] test-target bash[1826]: ‣ Type=signal  Endian=l
Flags=1  Version=1  Priority=0 Cookie=14
[    2.509651] test-target bash[1826]: Sender=org.freedesktop.DBus
Path=/org/freedesktop/DBus  Interface=org.freedesktop.DBus
Member=NameOwnerChanged
[    2.509922] test-target bash[1826]: MESSAGE "sss" {
[    2.510206] test-target bash[1826]: STRING "com.test.exampleservice";
[    2.510469] test-target bash[1826]: STRING "";
[    2.510730] test-target bash[1826]: STRING ":1.30";
[    2.510985] test-target bash[1826]: };
.
.
[   22.944202] test-target systemd[1]: example.service: Start
operation timed out. Terminating.
[   22.955929] test-target systemd[1]: example.service: Unit entered
failed state.
[   22.956538] test-target systemd[1]: example.service: Failed with
result 'timeout'.

So there is never a call to signal_name_owner_changed.

On a good boot I get:

[   22.969615] test-target systemd[1]: !!Got name owner changed:  New
owner: com.test.exampleservice

It seem that either systemd never gets the NameOwnerChanged signal or
for some reason systemd never calls AddMatch. Like I wrote, the
problem doesn't seem to persist in 228 but I can't find a commit that
specifically
fixes this issue.

Cheers

Johnny Karlsson