auto-start problem in v0.50

Tue Nov 8 05:15:32 PST 2005

Hi,

I have an interesting problem with D-BUS v0.50. A service is authenticated
and can talk normally in the system bus if I start it manually, but if I
try to auto-start (activate) it, the authentication fails. It seems that
the service sends different credentials when it is auto-started. The result
is the same whether I use DBUS_BUS_SYSTEM or DBUS_BUS_STARTER in the
service, or whether I run the bus as 'messagebus' or as my user name.

I'm porting software from v0.23, so maybe there's something additional needed
to configuration files?

Partial debug output from the daemon follows.

-Kimmo

------ manual starting (succeeds): ---------

17058: Connection 0x80977f0 authentication expires in 29999 milliseconds
17058: Enabled expire timeout with interval 29999
17058: _dbus_connection_handle_watch start
17058:   LOCK: _dbus_connection_handle_watch
17058:   UNLOCK: _dbus_connection_acquire_io_path
17058: _dbus_connection_acquire_io_path locking io_path_mutex
17058: _dbus_connection_acquire_io_path start connection->io_path_acquired = 0 timeout = -1
17058: _dbus_connection_acquire_io_path end connection->io_path_acquired = 1 we_acquired = 1
17058: _dbus_connection_acquire_io_path unlocking io_path_mutex
17058:   LOCK: _dbus_connection_acquire_io_path
17058: handling read watch 0x8097c38 flags = 1
17058: read credentials byte
17058: Credentials:  pid 17876  uid 1000  gid 1000
17058:  server auth state: waiting for input
17058:  read 24 bytes in auth phase
17058: server: got command "AUTH EXTERNAL 31303030"
17058: server: Trying mechanism EXTERNAL
17058: server: data: '1000'
17058: server: going from state WaitingForAuth to state WaitingForBegin
17058: server: authenticated client with UID 1000 matching socket credentials UID 1000
17058:  server auth state: bytes to send
17058: check_read_watch: fd = 7
17058:   setting read watch enabled = 0
17058:   UNLOCK: protected_change_watch
17058:   LOCK: protected_change_watch
17058: check_write_watch(): needed = 1 on connection 0x80977f0 watch 0x8097970 fd = 7 outgoing messages exist 0
17058:   UNLOCK: protected_change_watch
17058:   LOCK: protected_change_watch
17058: do_reading: fd = 7
17058: _dbus_connection_release_io_path locking io_path_mutex
17058: _dbus_connection_release_io_path start connection->io_path_acquired = 1
17058: _dbus_connection_release_io_path unlocking io_path_mutex
17058: _dbus_connection_handle_watch middle
17058: dispatch status = complete is_connected = 1

--------- activation (fails): -------------

18442: Credentials:  pid 18576  uid 1000  gid 1000
18442:  server auth state: waiting for input
18442: check_read_watch: fd = 9
18442:   setting read watch enabled = 1
18442:   UNLOCK: protected_change_watch
18442:   LOCK: protected_change_watch
18442: check_write_watch(): needed = 0 on connection 0x809b300 watch 0x809b0d0 f
d = 9 outgoing messages exist 0
18442:   UNLOCK: protected_change_watch
18442:   LOCK: protected_change_watch
18442: do_reading: fd = 9
18442: _dbus_connection_release_io_path locking io_path_mutex
18442: _dbus_connection_release_io_path start connection->io_path_acquired = 1
18442: _dbus_connection_release_io_path unlocking io_path_mutex
18442: _dbus_connection_handle_watch middle
18442: dispatch status = complete is_connected = 1
18442:   UNLOCK: _dbus_connection_update_dispatch_status_and_unlock
18442:   LOCK: dbus_connection_unref
18442:   UNLOCK: dbus_connection_unref
18442: _dbus_connection_handle_watch end
18576: wrote credentials byte
18576:  client auth state: bytes to send
18442: _dbus_connection_handle_watch start
18442:   LOCK: _dbus_connection_handle_watch
18442:   UNLOCK: _dbus_connection_acquire_io_path
18442: _dbus_connection_acquire_io_path locking io_path_mutex
18442: _dbus_connection_acquire_io_path start connection->io_path_acquired = 0 t
imeout = -1
18442: _dbus_connection_acquire_io_path end connection->io_path_acquired = 1 we_
acquired = 1
18442: _dbus_connection_acquire_io_path unlocking io_path_mutex
18442:   LOCK: _dbus_connection_acquire_io_path
18442: handling read watch 0x809b0f8 flags = 1
18442:  server auth state: waiting for input
18442:  read 18 bytes in auth phase
18442: server: got command "AUTH EXTERNAL 30"
18442: server: Trying mechanism EXTERNAL
18442: server: data: '0'
18442: server: credentials uid=1000 gid=1000 do not allow uid=0 gid=4294967295
18442: server: Shutting down mechanism EXTERNAL
18442: server: going from state WaitingForAuth to state WaitingForAuth
18442:  server auth state: bytes to send
18442: check_read_watch: fd = 9
18442:   setting read watch enabled = 0
18442:   UNLOCK: protected_change_watch
18442:   LOCK: protected_change_watch
18442: check_write_watch(): needed = 1 on connection 0x809b300 watch 0x809b0d0 f
d = 9 outgoing messages exist 0
18442:   UNLOCK: protected_change_watch
18442:   LOCK: protected_change_watch
18442: do_reading: fd = 9
18442: _dbus_connection_release_io_path locking io_path_mutex
18442: _dbus_connection_release_io_path start connection->io_path_acquired = 1
18442: _dbus_connection_release_io_path unlocking io_path_mutex
18442: _dbus_connection_handle_watch middle
18442: dispatch status = complete is_connected = 1
18442:   UNLOCK: _dbus_connection_update_dispatch_status_and_unlock
18442:   LOCK: dbus_connection_unref
18442:   UNLOCK: dbus_connection_unref
18442: _dbus_connection_handle_watch end
18442: _dbus_connection_handle_watch start
18442:   LOCK: _dbus_connection_handle_watch
18442:   UNLOCK: _dbus_connection_acquire_io_path
18442: _dbus_connection_acquire_io_path locking io_path_mutex
18442: _dbus_connection_acquire_io_path start connection->io_path_acquired = 0 t
imeout = -1
18442: _dbus_connection_acquire_io_path end connection->io_path_acquired = 1 we_
acquired = 1
18442: _dbus_connection_acquire_io_path unlocking io_path_mutex
18442:   LOCK: _dbus_connection_acquire_io_path
18442: handling write watch, have_outgoing_messages = 0
18442:  server auth state: bytes to send
18442: server: Sent 36 bytes of: REJECTED EXTERNAL DBUS_COOKIE_SHA1

18442:  server auth state: waiting for input
18442: check_read_watch: fd = 9
18442:   setting read watch enabled = 1
18442:   UNLOCK: protected_change_watch
18442:   LOCK: protected_change_watch
18442: check_write_watch(): needed = 0 on connection 0x809b300 watch 0x809b0d0 f
d = 9 outgoing messages exist 0
18442:   UNLOCK: protected_change_watch
18442:   LOCK: protected_change_watch
18442: Not authenticated, not writing anything
18442: check_write_watch(): needed = 0 on connection 0x809b300 watch 0x809b0d0 f
d = 9 outgoing messages exist 0
18442:   UNLOCK: protected_change_watch
18442:   LOCK: protected_change_watch
18442: _dbus_connection_release_io_path locking io_path_mutex
18442: _dbus_connection_release_io_path start connection->io_path_acquired = 1
18442: _dbus_connection_release_io_path unlocking io_path_mutex
18442: _dbus_connection_handle_watch middle
18442: dispatch status = complete is_connected = 1
18442:   UNLOCK: _dbus_connection_update_dispatch_status_and_unlock
18442:   LOCK: dbus_connection_unref
18442:   UNLOCK: dbus_connection_unref
18442: _dbus_connection_handle_watch end
18576: client: Sent 18 bytes of: AUTH EXTERNAL 30

18576:  client auth state: waiting for input
18576: check_read_watch: fd = 3
18576:   setting read watch enabled = 1
18576:   UNLOCK: protected_change_watch
18576:   LOCK: protected_change_watch
18576: check_write_watch(): needed = 0 on connection 0x804b5f8 watch 0x804b298 f
d = 3 outgoing messages exist 1
18576:   UNLOCK: protected_change_watch
18576:   LOCK: protected_change_watch
18576: Not authenticated, not writing anything
18576: check_write_watch(): needed = 0 on connection 0x804b5f8 watch 0x804b298 f
d = 3 outgoing messages exist 1
18576:   UNLOCK: protected_change_watch
18576:   LOCK: protected_change_watch
18576:  ... leaving do_iteration()
18576: _dbus_transport_do_iteration end
18576: _dbus_connection_release_io_path locking io_path_mutex
18576: _dbus_connection_release_io_path start connection->io_path_acquired = 1
18576: _dbus_connection_release_io_path unlocking io_path_mutex
18576: _dbus_connection_do_iteration_unlocked end
18576: dbus_connection_send_with_reply middle
18576: dispatch status = complete is_connected = 1
18576:   UNLOCK: _dbus_connection_update_dispatch_status_and_unlock
18576:   LOCK: dbus_connection_unref
18576:   UNLOCK: dbus_connection_unref
18576:   LOCK: dbus_connection_flush
18576: doing iteration in dbus_connection_flush
18576: _dbus_connection_do_iteration_unlocked start
18576:   UNLOCK: _dbus_connection_acquire_io_path
18576: _dbus_connection_acquire_io_path locking io_path_mutex
18576: _dbus_connection_acquire_io_path start connection->io_path_acquired = 0 t
imeout = -1
18576: _dbus_connection_acquire_io_path end connection->io_path_acquired = 1 we_
acquired = 1
18576: _dbus_connection_acquire_io_path unlocking io_path_mutex
18576:   LOCK: _dbus_connection_acquire_io_path
18576: Transport iteration flags 0x7 timeout -1 connected = 1
18576:  iteration flags = readwrite timeout = -1 read_watch = 0x804b2c0 write_wa
tch = 0x804b298 fd = 3
18576: unlock unix_do_iteration pre poll
18576:   UNLOCK: _dbus_connection_unlock
18576: lock unix_do_iteration post poll
18576:   LOCK: _dbus_connection_lock
18576: in iteration, need_read=1 need_write=0
18576:  client auth state: waiting for input
18576:  read 36 bytes in auth phase
18576: client: got command "REJECTED EXTERNAL DBUS_COOKIE_SHA1"
18576: client: Adding mechanism EXTERNAL to list we will try
18576: client: Adding mechanism DBUS_COOKIE_SHA1 to list we will try
18576: client: Shutting down mechanism EXTERNAL
18576: client: going from state WaitingForData to state WaitingForData
18576: client: Trying mechanism EXTERNAL
18576:  client auth state: bytes to send
18576: check_read_watch: fd = 3
18576:   setting read watch enabled = 0
18576:   UNLOCK: protected_change_watch
18576:   LOCK: protected_change_watch
18576: check_write_watch(): needed = 1 on connection 0x804b5f8 watch 0x804b298 f
d = 3 outgoing messages exist 1
18576:   UNLOCK: protected_change_watch
18576:   LOCK: protected_change_watch
18576: do_reading: fd = 3
18576: check_write_watch(): needed = 1 on connection 0x804b5f8 watch 0x804b298 f
d = 3 outgoing messages exist 1
18576:   UNLOCK: protected_change_watch
...