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
_______________________________________________
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel
