libzeitgeist

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

Bug #1074993 reported by Philip Withnall on 2012-11-04

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	libzeitgeist	New	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 ()

Revision history for this message

Philip Withnall (drbob) wrote on 2012-12-29:

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.

Revision history for this message

Philip Withnall (drbob) wrote on 2012-12-29:

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’).

Revision history for this message

Travis Reitter (treitter) wrote on 2013-02-18:

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.

Revision history for this message

Seif Lotfy (seif) wrote on 2013-02-18: Re: [Bug 1074993] Re: D-Bus assertion when a ZeitgeistMonitor is finalised before its ZeitgeistLog

Download full text (7.3 KiB)

On it.

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

On it.

On Mon, Feb 18, 2013 at 8:08 AM, Travis Reitter
<1074993@bugs.launchpad.net>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 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 ()
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/libzeitgeist/+bug/1074993/+subscriptions
>

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

gnome-bugs #686715
[RESOLVED FIXED] Edit

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