Crash: dbus_timeout_handle for already deleted pending calls via dbus_connection_send_with_reply_and_block()

[Ville M. Vainio]

I have a problem. I don't understand why I have 'timeouts' for pending
calls that don't exist anymore.

I have (rare) crashes that look like this (no, I don't have a core for this):

QQQ

#0  _dbus_connection_lock (connection=0x616d6740) at dbus-connection.c:355
#0  _dbus_connection_lock (connection=0x616d6740) at dbus-connection.c:355
#1  0x41263cf8 in _dbus_pending_call_get_connection_and_lock (pending=0x1756c0)
at dbus-pending-call.c:309
#2  0x4125695c in reply_handler_timeout (data=0x616d6740) at
dbus-connection.c:3116
#3  0x41268910 in dbus_timeout_handle (timeout=0x1756f0) at dbus-timeout.c:473
#4  0x4138e9cc in timeout_handler_dispatch (data=<value optimized out>) at
dbus-gmain.c:343
#5  0x4119f2a8 in g_timeout_dispatch (source=0x175718, callback=0x4138e9bc
<timeout_handler_dispatch>, user_data=0x616d6740) at gmain.c:3587
#6  0x4119e9dc in IA__g_main_context_dispatch (context=0xb3748) at gmain.c:2142
#7  0x411a2470 in g_main_context_iterate (context=0xb3748, block=1, dispatch=1,
self=<value optimized out>) at gmain.c:2776

QQQ

Note that NO dbus_connection_send_with_reply_and_block calls are in
flight at that moment. The crash above seems to suggest a destroyed
DBusConnection, but I'm more suspicious about this incident that was
reported by valgrind memcheck:

QQQ

==20919== Invalid read of size 4
==20919==    at 0x4F34C87: (within /targets/fi/usr/lib/libdbus-1.so.3.4.0)
==20919==    by 0x4F27C6D: (within /targets/fi/usr/lib/libdbus-1.so.3.4.0)
==20919==    by 0x4F3990F: dbus_timeout_handle (in
/targets/fi/usr/lib/libdbus-1.so.3.4.0)
==20919==    by 0x4B7DEFE: (within /targets/fi/usr/lib/libdbus-glib-1.so.2.1.0)
==20919==    by 0x4FBF2A3: g_timeout_dispatch (gmain.c:3587)
==20919==    by 0x4FBEAFB: g_main_context_dispatch (gmain.c:2142)
==20919==    by 0x4FC211E: g_main_context_iterate (gmain.c:2776)
==20919==    by 0x4FC2487: g_main_loop_run (gmain.c:2984)
==20919==    by 0x49589D8: gtk_main (gtkmain.c:1163)
==20919==    by 0x806769B: main (my-main.c:196)
==20919==  Address 0x64f3d48 is 16 bytes inside a block of size 40 free'd
==20919==    at 0x4020509: free (vg_replace_malloc.c:323)
==20919==    by 0x4F405C2: dbus_free (in /targets/fi/usr/lib/libdbus-1.so.3.4.0)
==20919==    by 0x4F35132: (within /targets/fi/usr/lib/libdbus-1.so.3.4.0)
==20919==    by 0x4F35196: dbus_pending_call_unref (in
/targets/fi/usr/lib/libdbus-1.so.3.4.0)
==20919==    by 0x4F27B74: dbus_connection_send_with_reply_and_block
(in /targets/fi/usr/lib/libdbus-1.so.3.4.0)
==20919==    by 0x59A471A: my_secret_stuff (foo.c:777)

QQQ

That is, the DBusPendingCall object that was created by
dbus_connection_send_with_reply_and_block() got a timeout when it was
already deleted. Here's the interesting portion from
dbus_connection_send_with_reply_and_block:

QQQ

  if (!dbus_connection_send_with_reply (connection, message,
                                        &pending, timeout_milliseconds))
    {...
    }

...


  dbus_pending_call_block (pending);

  reply = dbus_pending_call_steal_reply (pending);
  dbus_pending_call_unref (pending);

QQQ

This is happening in a multithreaded environment where the dbus
connection handle is opened from multiple places, call handling
filters have been installed with glib mainloop and there is frequent
dbus traffic going on. Any insight?

-- 
Ville M. Vainio
http://tinyurl.com/vainio