Problem with waiting for a service to be available

[Randell Jesup]

There seems to be a designed-in timing hole in the DBus architecture, or
perhaps it isn't obvious (or explained) how you're supposed to wait for
a service to be available.  Note that "ServiceName" is using dbus-c++
(the working "git" tree branch with ecore integration).  Perhaps even
it's a dbus-c++ issue, though it doesn't seem like it.


If (like Qt's wrapper does to update ::isValid()) your application
watches for NameOwnerChanged to know when a destination is available to
send methods to, the ordering of operations leaves a timing hole.  To
whit:

(From what dbus-monitor sees, what my Qt apps sees, and what another
application would probably see):

:1.17 sends AddMatch to DBus for NameOwnerChanged signal

Assumes: we've connected NameOwnerChanged signal to internal Qt slot
Time goes by, and then we start up the server for ServiceName

signal NameOwnerChanged for :1.35
:1.35 sends Hello to DBus
signal NameOwnerChanged for ServiceName
:1.35 sends RequestName to DBus for ServiceName

At this point, the listener notices NameOwnerChanged, and sends a method
(init()) to to ServiceName.  Note that it may do this as soon as
NameOwnerChanged for ServiceName is delivered to :1.17

:1.17 sends init to Servicename
:1.35 sends AddMatch to DBus for ServiceName

Wait around 15-30 seconds....

:1.35 finally acts like it got method init() (and I think sends a reply,
         which dbus isn't configured to let dbus-monitor see)
:1.17 sends version to ServiceName

Note that if ServiceName is already registered before :1.17 starts up,
there are no unusual delays.

Simplified profile (sorry, I didn't have the initial signal of
NameOwnerChanged for :1.35 in here)

mc	1253210449	162033	1	:1.35	/org/freedesktop/DBus	org.freedesktop.DBus	Hello
sig	1253210449	204469	10	/org/freedesktop/DBus	org.freedesktop.DBus	NameOwnerChanged
mc	1253210449	204727	2	:1.35	/org/freedesktop/DBus	org.freedesktop.DBus	RequestName
mc	1253210449	223718	52	:1.17	/com/foo/ServiceName	com.foo.ServiceName	init
mc	1253210449	250102	3	:1.35	/org/freedesktop/DBus	org.freedesktop.DBus	AddMatch
mc	1253210474	268186	53	:1.17	/com/foo/ServiceName	com.foo.ServiceName	version
mc	1253210475	397637	54	:1.17	/com/foo/ServiceName	com.foo.ServiceName	command

So, I assume the delay is a retry within dbus to deliver the message
before giving up.  Even if it's queued in dbus, why isn't it delivered
when :1.35 (ServiceName) does the AddMatch?

Also note: the previous owner of ServiceName had been killed, and
appropriate NameOwnerChanged had occurred.  From another run:

sig	1253221607	797520	17	/org/freedesktop/DBus	org.freedesktop.DBus	NameOwnerChanged
mc	1253221607	797769	11	:1.44	/org/freedesktop/DBus	org.freedesktop.DBus	ReleaseName
sig	1253221607	867286	18	/org/freedesktop/DBus	org.freedesktop.DBus	NameOwnerChanged

The first NameOwnerChanged is for com.foo.ServiceName, the second is for :1.44
-- 
Randell Jesup, Worldgate
rjesup at wgate.com