activation_timeout crash [was Re: Crash: dbus_timeout_handle for already deleted pending calls via dbus_connection_send_with_reply_and_block()]

[Ville M. Vainio]

On Thu, Feb 5, 2009 at 9:00 AM, Ville M. Vainio <vivainio at gmail.com> wrote:

> 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 a followup on this, in case anyone cares:

My theory is that the problem is/was in a code (somewhere far away
from my dbus code, but still in the same process) that tried to invoke
a dbus method that required dbus to activate
(bus_activation_activate_service) another service (bluez). The
activation never succeeded, which possibly screwed up dbus in one way
or another. I  was lead to this by being able to reproduce the crash
in my environment, and noting that the bad timeout was for 25000
msecs, which just happens to be the dbus "activation" timeout.

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