D-Bus assertion when a ZeitgeistMonitor is finalised before its ZeitgeistLog

Bug #1074993 reported by Philip Withnall on 2012-11-04
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
libzeitgeist
Undecided
Unassigned

Bug Description

See: https://bugzilla.gnome.org/show_bug.cgi?id=686715

Assume a ZeitgeistLog and ZeitgeistMonitor have been instantiated, and the ZeitgeistMonitor has been installed on the ZeitgeistLog. If the ZeitgeistMonitor is finalised, _zeitgeist_log_on_monitor_destroyed() will be called by the weak notify handler. It will call zeitgeist_log_remove_monitor() which then checks some of the properties of the (now finalised) ZeitgeistMonitor. I suspect this results in generating an invalid GVariant for the RemoveMonitor D-Bus call, which is what we’re seeing happen in libfolks.

Stacktrace:

(/home/treitter/collabora/folks/tests/telepathy/.libs/lt-init:3800): GLib-GIO-CRITICAL **: g_dbus_proxy_call_internal: assertion `parameters == NULL || g_variant_is_of_type (parameters, G_VARIANT_TYPE_TUPLE)' failed
Detaching after fork from child process 3806.

Program received signal SIGTRAP, Trace/breakpoint trap.
g_logv (log_domain=0x7ffff74c11a1 "GLib-GIO", log_level=G_LOG_LEVEL_CRITICAL,
    format=<optimized out>, args=args@entry=0x7fffffffd548) at gmessages.c:974
974 g_private_set (&g_log_depth, GUINT_TO_POINTER (depth));
(gdb) bt
#0 g_logv (log_domain=0x7ffff74c11a1 "GLib-GIO",
    log_level=G_LOG_LEVEL_CRITICAL, format=<optimized out>,
    args=args@entry=0x7fffffffd548) at gmessages.c:974
#1 0x00007ffff6c608a2 in g_log (
    log_domain=log_domain@entry=0x7ffff74c11a1 "GLib-GIO",
    log_level=log_level@entry=G_LOG_LEVEL_CRITICAL,
    format=format@entry=0x7ffff6cc941a "%s: assertion `%s' failed")
    at gmessages.c:1003
#2 0x00007ffff6c608c9 in g_return_if_fail_warning (
    log_domain=log_domain@entry=0x7ffff74c11a1 "GLib-GIO",
    pretty_function=pretty_function@entry=0x7ffff74e6080 "g_dbus_proxy_call_internal",
    expression=expression@entry=0x7ffff74e2738 "parameters == NULL || g_variant_is_of_type (parameters, G_VARIANT_TYPE_TUPLE)") at gmessages.c:1012
#3 0x00007ffff749d08a in g_dbus_proxy_call_internal (proxy=0x6345a0,
    method_name=0x7ffff7ba9a7b "RemoveMonitor", parameters=0x6bd030,
    flags=G_DBUS_CALL_FLAGS_NONE, timeout_msec=-1, fd_list=fd_list@entry=0x0,
    cancellable=0x0,
    callback=callback@entry=0x7ffff7b9e37b <monitor_removed_cb>,
    user_data=user_data@entry=0x637120) at gdbusproxy.c:2707
#4 0x00007ffff749ea44 in g_dbus_proxy_call (proxy=<optimized out>,
    method_name=<optimized out>, parameters=<optimized out>,
    flags=<optimized out>, timeout_msec=<optimized out>,
    cancellable=<optimized out>, callback=0x7ffff7b9e37b <monitor_removed_cb>,
    user_data=0x637120) at gdbusproxy.c:3017
#5 0x00007ffff7b9e6cc in zeitgeist_log_remove_monitor ()
   from /opt/gnome/lib64/libzeitgeist-1.0.so.1
#6 0x00007ffff7b9e767 in _zeitgeist_log_on_monitor_destroyed ()
   from /opt/gnome/lib64/libzeitgeist-1.0.so.1
#7 0x00007ffff6f466f2 in weak_refs_notify (data=0x6bfea0) at gobject.c:2469
#8 0x00007ffff6f47684 in g_object_unref (_object=0x7ffff0007240)
    at gobject.c:2986
#9 0x00007ffff7dcf7ae in tpf_persona_store_finalize (obj=0x642150)
    at /home/treitter/collabora/folks/backends/telepathy/lib/tpf-persona-store.vala:101
#10 0x00007ffff6f47718 in g_object_unref (_object=0x642150) at gobject.c:3023
#11 0x00007ffff7dc5ea2 in _tpf_persona_store_populate_counters_data_free (
    _data=0x6e4000)
    at /home/treitter/collabora/folks/backends/telepathy/lib/tpf-persona-store.vala:41
#12 0x00007ffff743fd78 in clear_op_res (simple=0x6ce6c0)
    at gsimpleasyncresult.c:257
#13 g_simple_async_result_finalize (object=0x6ce6c0)
    at gsimpleasyncresult.c:277
#14 0x00007ffff6f47718 in g_object_unref (_object=0x6ce6c0) at gobject.c:3023
#15 0x00007ffff7dca4f6 in _tpf_persona_store_populate_counters_co (
    _data_=0x6e4000)
    at /home/treitter/collabora/folks/backends/telepathy/lib/tpf-persona-store.vala:1741
#16 0x00007ffff7b9b0ae in dispatch_async_callback ()
   from /opt/gnome/lib64/libzeitgeist-1.0.so.1
---Type <return> to continue, or q <return> to quit---
#17 0x00007ffff7440ba7 in g_simple_async_result_complete (simple=0x6ce5e0)
    at gsimpleasyncresult.c:775
#18 0x00007ffff749aa9a in reply_cb (connection=<optimized out>,
    res=<optimized out>, user_data=0x6ce5e0) at gdbusproxy.c:2632
#19 0x00007ffff7440ba7 in g_simple_async_result_complete (simple=0x6ce570)
    at gsimpleasyncresult.c:775
#20 0x00007ffff7490efe in g_dbus_connection_call_done (source=<optimized out>,
    result=<optimized out>, user_data=0x636600) at gdbusconnection.c:5333
#21 0x00007ffff7440ba7 in g_simple_async_result_complete (simple=0x66fc30)
    at gsimpleasyncresult.c:775
#22 0x00007ffff7440ca9 in complete_in_idle_cb (data=<optimized out>)
    at gsimpleasyncresult.c:787
#23 0x00007ffff6c59565 in g_main_dispatch (context=0x631ff0) at gmain.c:2715
#24 g_main_context_dispatch (context=context@entry=0x631ff0) at gmain.c:3219
#25 0x00007ffff6c59898 in g_main_context_iterate (context=0x631ff0,
    block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at gmain.c:3290
#26 0x00007ffff6c59c92 in g_main_loop_run (loop=0x64b650) at gmain.c:3484
#27 0x0000000000413e02 in tp_tests_proxy_run_until_dbus_queue_processed (
    proxy=0x638840) at util.c:113
#28 0x000000000040c2cb in tp_tests_backend_tear_down (self=<optimized out>)
    at backend.c:361
#29 0x00007ffff6c7ba41 in test_case_run (tc=0x62c030) at gtestutils.c:1689
#30 g_test_run_suite_internal (suite=suite@entry=0x62a440,
    path=<optimized out>, path@entry=0x7ffff6cefd7e "") at gtestutils.c:1732
#31 0x00007ffff6c7bb66 in g_test_run_suite_internal (
    suite=suite@entry=0x62a420, path=<optimized out>,
    path@entry=0x7ffff6cefd7e "") at gtestutils.c:1743
#32 0x00007ffff6c7becb in g_test_run_suite (suite=0x62a420)
    at gtestutils.c:1788
#33 0x00007ffff6c7bf15 in g_test_run () at gtestutils.c:1308
#34 0x0000000000409c17 in _vala_main (args=0x7fffffffde08, args_length1=1)
    at /home/treitter/collabora/folks/tests/telepathy/init.vala:106
#35 0x00000036c7621735 in __libc_start_main (main=0x409550 <main>, argc=1,
    ubp_av=0x7fffffffde08, init=<optimized out>, fini=<optimized out>,
    rtld_fini=<optimized out>, stack_end=0x7fffffffddf8) at libc-start.c:226
#36 0x0000000000409599 in _start ()

Philip Withnall (drbob) wrote :

This is still a fairly serious problem for libfolks, since it’s causing spurious failures in our test suite, and I can find no way to work around it.

On further digging, there’s a second (separate) problem which is triggered at the same time: the monitor isn’t removed from the ZeitgeistLog’s list of monitors until the async D-Bus call returns. Calls to zeitgeist_log_remove_monitor() are predicated on whether the monitor is present in the list of monitors. Therefore it’s possible for multiple D-Bus calls to be started before the first one returns.

Philip Withnall (drbob) wrote :

Also (and I don’t know how I missed this before), the g_variant_new() call should be creating a singleton tuple (i.e. type ‘(o)’ rather than ‘o’).

Travis Reitter (treitter) wrote :

Is there any way we could get some help on this?

The test in folks that this affects (see bgo#686715) fails consistently, so it may be easier to debug than when this was originally filed.

Either way, it's pretty opaque to me exactly why this failure is happening, but I would really like to resolve it so our test suite succeeds consistently.

Download full text (7.3 KiB)

On it.

On Mon, Feb 18, 2013 at 8:08 AM, Travis Reitter
<email address hidden>wrote:

> Is there any way we could get some help on this?
>
> The test in folks that this affects (see bgo#686715) fails consistently,
> so it may be easier to debug than when this was originally filed.
>
> Either way, it's pretty opaque to me exactly why this failure is
> happening, but I would really like to resolve it so our test suite
> succeeds consistently.
>
> --
> You received this bug notification because you are subscribed to The
> Zeitgeist Project.
> https://bugs.launchpad.net/bugs/1074993
>
> Title:
> D-Bus assertion when a ZeitgeistMonitor is finalised before its
> ZeitgeistLog
>
> Status in Zeitgeist Client Library:
> New
>
> Bug description:
> See: https://bugzilla.gnome.org/show_bug.cgi?id=686715
>
> Assume a ZeitgeistLog and ZeitgeistMonitor have been instantiated, and
> the ZeitgeistMonitor has been installed on the ZeitgeistLog. If the
> ZeitgeistMonitor is finalised, _zeitgeist_log_on_monitor_destroyed()
> will be called by the weak notify handler. It will call
> zeitgeist_log_remove_monitor() which then checks some of the
> properties of the (now finalised) ZeitgeistMonitor. I suspect this
> results in generating an invalid GVariant for the RemoveMonitor D-Bus
> call, which is what we’re seeing happen in libfolks.
>
> Stacktrace:
>
> (/home/treitter/collabora/folks/tests/telepathy/.libs/lt-init:3800):
> GLib-GIO-CRITICAL **: g_dbus_proxy_call_internal: assertion `parameters ==
> NULL || g_variant_is_of_type (parameters, G_VARIANT_TYPE_TUPLE)' failed
> Detaching after fork from child process 3806.
>
> Program received signal SIGTRAP, Trace/breakpoint trap.
> g_logv (log_domain=0x7ffff74c11a1 "GLib-GIO",
> log_level=G_LOG_LEVEL_CRITICAL,
> format=<optimized out>, args=args@entry=0x7fffffffd548) at
> gmessages.c:974
> 974 g_private_set (&g_log_depth, GUINT_TO_POINTER (depth));
> (gdb) bt
> #0 g_logv (log_domain=0x7ffff74c11a1 "GLib-GIO",
> log_level=G_LOG_LEVEL_CRITICAL, format=<optimized out>,
> args=args@entry=0x7fffffffd548) at gmessages.c:974
> #1 0x00007ffff6c608a2 in g_log (
> log_domain=log_domain@entry=0x7ffff74c11a1 "GLib-GIO",
> log_level=log_level@entry=G_LOG_LEVEL_CRITICAL,
> format=format@entry=0x7ffff6cc941a "%s: assertion `%s' failed")
> at gmessages.c:1003
> #2 0x00007ffff6c608c9 in g_return_if_fail_warning (
> log_domain=log_domain@entry=0x7ffff74c11a1 "GLib-GIO",
> pretty_function=pretty_function@entry=0x7ffff74e6080
> "g_dbus_proxy_call_internal",
> expression=expression@entry=0x7ffff74e2738 "parameters == NULL ||
> g_variant_is_of_type (parameters, G_VARIANT_TYPE_TUPLE)") at
> gmessages.c:1012
> #3 0x00007ffff749d08a in g_dbus_proxy_call_internal (proxy=0x6345a0,
> method_name=0x7ffff7ba9a7b "RemoveMonitor", parameters=0x6bd030,
> flags=G_DBUS_CALL_FLAGS_NONE, timeout_msec=-1, fd_list=fd_list@entry
> =0x0,
> cancellable=0x0,
> callback=callback@entry=0x7ffff7b9e37b <monitor_removed_cb>,
> user_data=user_data@entry=0x637120) at gdbusproxy.c:2707
> #4 0x00007ffff749ea44 ...

Read more...

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.