Problem with waiting for a service to be available

[Randell Jesup]

For any on the dbus-cplusplus list, you can look at the dbus archives to
see the earlier messages here.  Note that the example below assumes the
patch to the dbus-c++ git tree for request_name() return values I
emailed to the list a week ago, though I don't think I've seen it appear
yet...

>>Just to reiterate and verify I'm not (or dbus-c++ isn't) doing something
>>wrong:
>>
>>When I receive signal "NameOwnerChanged" for ServiceName, if I send a
>>method to ServiceName *immediately* will it arrive there reliably (and
>>quickly)?  I'm seeing a 15-30 second delay (seems like a retry within
>>the dbus daemon) from when I send the method and the recipient appears
>>to receive it.  I know it's not queuing within Qt since dbus-monitor
>>shows the init method being sent immediately.
>
>Ok, I've resolved the problem.  There is a bit of a hole if you're not
>careful - dbus doesn't really protect you from it, and while a binding
>can, I suspect many of the them don't (include dbus-c++).
>
>The problem is that dbus-bus_request_name() will notify listeners that
>you own the name, but until you've created handlers for objects under
>that name people won't be able to successfully send you messages (though
>in practice, it appears that they're retried before giving up (15-30
>seconds later), and so by then the handlers exist).  If they're just
>itching to send you a message, they can beat the creation of the server
>object(s).
>
>In order to avoid all timing holes, you'd need to internally initialize
>all objects your entity supports before requesting the name.  Most
>sample code in dbus wrappers doesn't do this: it requests the name, then
>instantiates the object.  (Or at least so it seemed looking around the net).

Copied from below:
>The alternative (haven't tried it yet) is to put "FooService server(conn);"
>right before the "try {}" section, and dispense with server.Ready().

Note: at least in dbus-c++, the above does NOT work.  Even with creating
the FooService server object before request_name(), the first method
from someone watching NameOwnerChanged is delayed by ~25 seconds.
If the watcher waits 1 second after NameOwnerChanged or waits for
Ready() (per the example below), then everything works fast.

In dbus-monitor with --profile, I see that when the delay happens, the
AddMatch submitted by dbus-c++ following successful request_name()
occurs after the "watching" process has tried to send a method.  Eg:

(cleaned up for easier viewing)
sig	1253738585	/org/freedesktop/DBus	org.freedesktop.DBus	NameOwnerChanged
mc	1253738585	:1.17	/org/freedesktop/DBus	org.freedesktop.DBus	RequestName
mc	1253738585	:1.16	/com/foo/FooService	com.foo.FooService	init
mc	1253738585	:1.17	/org/freedesktop/DBus	org.freedesktop.DBus	AddMatch
mc	1253738610	:1.16	/com/foo/FooService	com.foo.FooService	version

Note the 25-second delay (and FooService doesn't see "init()" until the
end of those 25 seconds), and AddMatch is after init().  Note that
AddMatch is for FooService:

method call sender=:1.17 -> dest=org.freedesktop.DBus path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch
   string "destination='com.foo.FooService'"

If I add a 1-second delay to the watcher, you get this:

sig	1253738755	/org/freedesktop/DBus	org.freedesktop.DBus	NameOwnerChanged
mc	1253738755	:1.19	/org/freedesktop/DBus	org.freedesktop.DBus	RequestName
mc	1253738755	:1.19	/org/freedesktop/DBus	org.freedesktop.DBus	AddMatch
mc	1253738756	:1.18	/com/foo/FooService	com.foo.FooService	init
mc	1253738757	:1.18	/com/foo/FooService	com.foo.FooService	version

Note that AddMatch happens first, and no 25-second delay.

This may well be a hole in dbus-c++, however it feels like it might be a
race condition in the protocol itself - i.e. is the AddMatch after
dbus_bus_request_name needed in order to receive methods for that path/name?

>The other way to deal with it is to add an application-level protocol on
>top of DBus, like a "Ready()" signal raised when your service is ready
>to handle all requests.  Ugly but simple.  Example:
>
>>This is the dbus-c++ code for aquiring the name (assumes a patch to
>>dbus-c++ I sent in a few days ago to get the return code from 
>>dbus_bus_request_name()):
>>
>>    DBus::Connection conn = DBus::Connection::SessionBus();
>>    // Make sure we never get two instances running!
>>    try 
>>    {
>>        int result;
>>        syslog(LOG_INFO,"requesting name");
>>        if ((result = conn.request_name(SERVER_NAME,DBUS_NAME_FLAG_DO_NOT_QUEUE)) !=
>>            DBUS_REQUEST_NAME_REPLY_PRIMARY_OWNER)
>>        {
>>            syslog(LOG_ERR,"Request_name returned %d",result);
>>            ecore_shutdown();
>>            return 1;
>>        }
>>    }
>>    catch(DBus::Error &e) 
>>    {
>>        syslog(LOG_ERR,"Error: Request name failure: %s",e.message());
>>        ecore_shutdown();
>>        return 1;
>>    }
>
>     FooService server(conn);
>     server.Ready(); // tell the world - avoids races on ownership of the name


-- 
Randell Jesup, Worldgate
rjesup at wgate.com