Threading problems in (Win)DBus

Sat Jul 7 05:25:48 PDT 2007

Hello,

I am working wit Olivier on this problem, so I thought I'd post my
findings as well. :)

I have tried to reproduce the problem with Olivier's program on a Linux
box. I have activated the lock traces and verbose mode in dbus:

$ ./config.status --version
config.status
configured by ./configure, generated by GNU Autoconf 2.61,
  with options "'--enable-verbose-mode' '--enable-asserts'
'--prefix=/usr/local/stow/dbus' 'CFLAGS=-g' 'CXXFLAGS=-g'"

(dbus and dbus-c++ are the latest versions from CVS)

Running the echo-server and the client I get assert failures
"!(connection)->have_connection_lock" in varying functions of
dbus-connection.c, triggered either by the dispatcher thread or the
sender thread.

Example traces:
---------------------%<----------------------%<-----------------------
(...)
10357: _dbus_connection_do_iteration_unlocked start
10357:   UNLOCK: _dbus_connection_acquire_io_path [3082643152]
10357: _dbus_connection_acquire_io_path locking io_path_mutex
10357: _dbus_connection_acquire_io_path start
connection->io_path_acquired = 0 timeout = 2000
10357: _dbus_connection_acquire_io_path end connection->io_path_acquired
= 1 we_acquired = 1
10357: _dbus_connection_acquire_io_path unlocking io_path_mutex
10357:   LOCK: _dbus_connection_acquire_io_path [3082643152]
10357: Transport iteration flags 0x6 timeout 2000 connected = 1
10357:  iteration flags = read timeout = 2000 read_watch = 0x80504c0
write_watch = 0x8050498 fd = 3
10357: unlock socket_do_iteration pre poll
10357:   UNLOCK: _dbus_connection_unlock [3082643152]
In thread
10357:   LOCK: dbus_connection_get_is_connected [3082640272]
10357:   UNLOCK: dbus_connection_get_is_connected [3082640272]
10357: dbus_connection_dispatch
10357:   LOCK: dbus_connection_dispatch [3082640272]
10357:   UNLOCK: _dbus_connection_acquire_dispatch [3082640272]
10357: _dbus_connection_acquire_dispatch locking dispatch_mutex
10357: _dbus_connection_acquire_dispatch unlocking dispatch_mutex
10357:   LOCK: _dbus_connection_acquire_dispatch [3082640272]
10357: 10357: lock socket_do_iteration post poll
10357:   LOCK: _dbus_connection_lock [3082643152]
10357: assertion failed "!(connection)->have_connection_lock" file
"dbus-connection.c" line 353 function _dbus_connection_lock
  /usr/local/lib/libdbus-1.so.3 [0xb7ed1828]
  /usr/local/lib/libdbus-1.so.3 [0xb7ecc8af]
  /usr/local/lib/libdbus-1.so.3 [0xb7ebf044]
  /usr/local/lib/libdbus-1.so.3 [0xb7e8a396]
  /usr/local/lib/libdbus-1.so.3 [0xb7eba3de]
  /usr/local/lib/libdbus-1.so.3 [0xb7eb8250]
  /usr/local/lib/libdbus-1.so.3 [0xb7e8bae8]
  /usr/local/lib/libdbus-1.so.3 [0xb7e8e0ea]
  /usr/local/lib/libdbus-1.so.3(dbus_pending_call_block+0x96)
[0xb7eaec35]
  /usr/local/lib/libdbus-1.so.3(dbus_connection_send_with_reply_and_block+0x2bf)
[0xb7e90b98]
  /usr/local/lib/libdbus-c++-1.so.0(_ZN4DBus10Connection13send_blockingERNS_7MessageEi+0x63)
[0xb7f0c173]
  /usr/local/lib/libdbus-c++-1.so.0(_ZN4DBus11ObjectProxy14_invoke_methodERNS_11CallMessageE+0x5c)
[0xb7efbf9c]
  /usr/local/lib/libdbus-c++-1.so.0(_ZN4DBus14InterfaceProxy13invoke_methodERKNS_11CallMessageE+0x47)
[0xb7ef79c7]
  ./SandBoxDBusPosix [0x804cfd6]
  ./SandBoxDBusPosix [0x804ca7a]
  /lib/i686/cmov/libc.so.6(__libc_start_main+0xdc) [0xb7c24ebc]
  ./SandBoxDBusPosix(__gxx_personality_v0+0x65) [0x804a091]
Aborted
---------------------%<----------------------%<-----------------------
(...)
11703: check_read_watch: fd = 3
11703:   setting read watch enabled = 1
11703:   UNLOCK: protected_change_watch [3082446544]
11703:   LOCK: protected_change_watch [3082446544]
11703: check_write_watch(): needed = 0 on connection 0x80507f0 watch
0x8050498 fd = 3 outgoing messages exist 0
11703:   UNLOCK: protected_change_watch [3082446544]
11703:   LOCK: protected_change_watch [3082446544]
11703:  ... leaving do_iteration()
11703: _dbus_transport_do_iteration end
11703: _dbus_connection_release_io_path locking io_path_mutex
11703: _dbus_connection_release_io_path start
connection->io_path_acquired = 1
11703: _dbus_connection_release_io_path unlocking io_path_mutex
11703: _dbus_connection_do_iteration_unlocked end
11703: _dbus_connection_block_pending_call top of recheck
11703: check_for_reply_and_update_dispatch_unlocked checked for reply
11703: dbus_connection_send_with_reply_and_block(): got reply
11703:   handing message 0x80528c8 (method return) to pending call
serial 6
11703:   UNLOCK: _dbus_connection_unlock [3082446544]
11703:   LOCK: free_pending_call_on_hash_removal [3082446544]
11703:   UNLOCK: _dbus_connection_unlock [3082446544]
11703:   LOCK: check_for_reply_and_update_dispatch_unlocked [3082446544]
11703:   UNLOCK: _dbus_connection_update_dispatch_status_and_unlock
[3082446544]11703:   LOCK: _dbus_connection_lock [3082446544]
11703:   UNLOCK: _dbus_connection_unlock [3082446544]
11703: Freeing slot 0 on allocator 0xb7eb583c total 1 allocated 1 used
i = 2
11703:   LOCK: dbus_connection_send_with_reply [3082446544]
11703: Allocated slot 0 on allocator 0xb7eb583c total 1 slots allocated
1 used
11703:   LOCK: dbus_connection_get_is_connected [3082443664]
11703: assertion failed "!(connection)->have_connection_lock" file
"dbus-connection.c" line 2786 function dbus_connection_get_is_connected
  /usr/local/lib/libdbus-1.so.3 [0xb7ea1828]
  /usr/local/lib/libdbus-1.so.3 [0xb7e9c8af]
  /usr/local/lib/libdbus-1.so.3 [0xb7e8f044]
  /usr/local/lib/libdbus-1.so.3(dbus_connection_get_is_connected+0x103)
[0xb7e5f1f9]
  /usr/local/lib/libdbus-c++-1.so.0(_ZN4DBus10Connection7Private11do_dispatchEv+0x3e)
[0xb7edb88e]
  /usr/local/lib/libdbus-c++-1.so.0(_ZN4DBus10Dispatcher16dispatch_pendingEv+0x56)
[0xb7edffe6]
  /usr/local/lib/libdbus-c++-1.so.0(_ZN4DBus13BusDispatcher12do_iterationEv+0x22)
[0xb7ed4ba2]
  /usr/local/lib/libdbus-c++-1.so.0(_ZN4DBus13BusDispatcher5enterEv+0x38)
[0xb7ed4a58]
  ./SandBoxDBusPosix [0x804cb48]
  /lib/i686/cmov/libpthread.so.0 [0xb7bcd31b]
  /lib/i686/cmov/libc.so.6(clone+0x5e) [0xb7caf8ee]
Aborted
---------------------%<----------------------%<-----------------------

The number in [] that I added on LOCK/UNLOCK traces is the pthread_t of
the thread running it.

I don't know how reliable the order of the outputs in the traces are
among the threads, but it often seems that the problem appears at a
succession of two LOCK, which should not be possible...

Another problem that I noticed: for the pthread implementation of
threads in dbus-sysdeps-pthread.c, the _dbus_pthread_mutex_lock()
function appears to simulate a reentrant lock by using the pmutex->count
counter. Wouldn't the CONNECTION_LOCK macro then fail in case a lock is
acquired twice by the same thread (in TOOK_LOCK_CHECK)?

Are the two problems related?

That's all I have for now...

Thanks for any help!

Best regards,

-Christian