| Summary: | MC crashes when GOA is restarted | ||
|---|---|---|---|
| Product: | Telepathy | Reporter: | Guillaume Desmottes <guillaume.desmottes> |
| Component: | mission-control | Assignee: | Telepathy bugs list <telepathy-bugs> |
| Status: | RESOLVED FIXED | QA Contact: | Telepathy bugs list <telepathy-bugs> |
| Severity: | major | ||
| Priority: | medium | CC: | bigon |
| Version: | unspecified | Keywords: | patch |
| Hardware: | Other | ||
| OS: | All | ||
| Whiteboard: | |||
| i915 platform: | i915 features: | ||
| Attachments: |
use G_STRFUNC in mission-control-plugins's DEBUG macro
mcd-account: add unregister_dbus_service() mcd-account: unregister the account once we're done deleting it mcd_account_delete: make sure that the account stays alive |
||
Full logs when GOA is restarted: (process:13703): tp-glib/proxy-DEBUG: noc_idle_context_invoke: NameOwnerChanged(:1.310, -> :1.310) (process:13703): tp-glib/proxy-DEBUG: noc_idle_context_invoke: NameOwnerChanged(:1.310, -> :1.310) (process:13703): tp-glib/proxy-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.gnome.OnlineAccounts, :1.296 -> :1.310) (process:13703): tp-glib/proxy-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.gnome.OnlineAccounts, :1.296 -> :1.310) (process:13703): mcd-DEBUG: deleted_cb: goa reported deletion of gabble/jabber/goa_google_account_1384426078 (0x1570520) (process:13703): mcd-DEBUG: unref_account: called for gabble/jabber/goa_google_account_1384426078 (process:13703): mc-plugins-DEBUG: account-storage.c:806: goa: ** (process:13703): DEBUG: mcp_account_manager_goa_delete: (gabble/jabber/goa_google_account_1384426078, (null)) (process:13703): mc-plugins-DEBUG: account-storage.c:806: default-gkeyfile: (process:13703): mcd-DEBUG: mcd_storage_commit: flushing plugin goa gabble/jabber/goa_google_account_1384426078 to long term storage (process:13703): mc-plugins-DEBUG: account-storage.c:907: goa: called for gabble/jabber/goa_google_account_1384426078 (process:13703): mc-plugins-DEBUG: account-storage.c:849: goa: committing all accounts ** (process:13703): DEBUG: Save config to /home/cassidy/.local/share/telepathy/mission-control/accounts-goa.cfg (process:13703): mcd-DEBUG: mcd_storage_commit: flushing plugin default-gkeyfile gabble/jabber/goa_google_account_1384426078 to long term storage (process:13703): mc-plugins-DEBUG: account-storage.c:907: default-gkeyfile: called for gabble/jabber/goa_google_account_1384426078 (process:13703): mcd-DEBUG: _mcd_account_dispose: 0x1570520 (gabble/jabber/goa_google_account_1384426078) (process:13703): mcd-DEBUG: _mcd_account_finalize: 0x1570520 (gabble/jabber/goa_google_account_1384426078) (process:13703): mcd-DEBUG: deleted_cb: goa reported deletion of gabble/jabber/goa_facebook_account_1377685019 (0x15703d0) (process:13703): mcd-DEBUG: unref_account: called for gabble/jabber/goa_facebook_account_1377685019 (process:13703): mc-plugins-DEBUG: account-storage.c:644: goa: (process:13703): mc-plugins-DEBUG: account-storage.c:602: goa: ** (process:13703): DEBUG: mcp_account_manager_goa_set: (gabble/jabber/goa_facebook_account_1377685019, Enabled, false) (process:13703): mcd-DEBUG: update_storage: MCP:goa -> store gabble/jabber/goa_facebook_account_1377685019.Enabled (process:13703): mcd-DEBUG: update_storage: MCP:default-gkeyfile -> delete gabble/jabber/goa_facebook_account_1377685019.Enabled (process:13703): mc-plugins-DEBUG: account-storage.c:806: default-gkeyfile: (process:13703): mcd-DEBUG: mcd_account_changed_property: called: Enabled (process:13703): mcd-DEBUG: mcd_account_changed_property: First changed property (process:13703): mc-plugins-DEBUG: account-storage.c:806: goa: ** (process:13703): DEBUG: mcp_account_manager_goa_delete: (gabble/jabber/goa_facebook_account_1377685019, (null)) (process:13703): mc-plugins-DEBUG: account-storage.c:806: default-gkeyfile: (process:13703): mcd-DEBUG: mcd_storage_commit: flushing plugin goa gabble/jabber/goa_facebook_account_1377685019 to long term storage (process:13703): mc-plugins-DEBUG: account-storage.c:907: goa: called for gabble/jabber/goa_facebook_account_1377685019 (process:13703): mc-plugins-DEBUG: account-storage.c:849: goa: committing all accounts ** (process:13703): DEBUG: Save config to /home/cassidy/.local/share/telepathy/mission-control/accounts-goa.cfg (process:13703): mcd-DEBUG: mcd_storage_commit: flushing plugin default-gkeyfile gabble/jabber/goa_facebook_account_1377685019 to long term storage (process:13703): mc-plugins-DEBUG: account-storage.c:907: default-gkeyfile: called for gabble/jabber/goa_facebook_account_1377685019 (process:13703): mcd-DEBUG: mcd_account_delete: Forcing Account.Removed for gabble/jabber/goa_facebook_account_1377685019 (process:13703): mc-plugins-DEBUG: account-storage.c:548: goa: ** (process:13703): DEBUG: mcp_account_manager_goa_get: gabble/jabber/goa_facebook_account_1377685019, (null) (process:13703): mcd-DEBUG: _mcd_account_constructed: 0x1570520 (gabble/jabber/goa_facebook_account_1377685019) (process:13703): mc-plugins-DEBUG: account-storage.c:644: goa: (process:13703): mc-plugins-DEBUG: account-storage.c:602: goa: ** (process:13703): DEBUG: mcp_account_manager_goa_set: (gabble/jabber/goa_facebook_account_1377685019, AutomaticPresence, 0;;;) (process:13703): mcd-DEBUG: update_storage: MCP:goa -> store gabble/jabber/goa_facebook_account_1377685019.AutomaticPresence (process:13703): mcd-DEBUG: update_storage: MCP:default-gkeyfile -> delete gabble/jabber/goa_facebook_account_1377685019.AutomaticPresence (process:13703): mc-plugins-DEBUG: account-storage.c:806: default-gkeyfile: (process:13703): mcd-DEBUG: mcd_storage_commit: flushing plugin goa gabble/jabber/goa_facebook_account_1377685019 to long term storage (process:13703): mc-plugins-DEBUG: account-storage.c:907: goa: called for gabble/jabber/goa_facebook_account_1377685019 (process:13703): mc-plugins-DEBUG: account-storage.c:849: goa: committing all accounts ** (process:13703): DEBUG: Save config to /home/cassidy/.local/share/telepathy/mission-control/accounts-goa.cfg (process:13703): mcd-DEBUG: mcd_storage_commit: flushing plugin default-gkeyfile gabble/jabber/goa_facebook_account_1377685019 to long term storage (process:13703): mc-plugins-DEBUG: account-storage.c:907: default-gkeyfile: called for gabble/jabber/goa_facebook_account_1377685019 (process:13703): mcd-DEBUG: mcd_account_check_parameters: called for gabble/jabber/goa_facebook_account_1377685019 (process:13703): mcd-DEBUG: mcd_account_would_like_to_connect: gabble/jabber/goa_facebook_account_1377685019 does not ConnectAutomatically, and its RequestedPresence (1, 'offline', '') doesn't indicate the user wants to be online ** (process:13703): ERROR **: Failed to register GObject with DBusConnection: org.freedesktop.DBus.Error.ObjectPathInUse A handler is already registered for /org/freedesktop/Telepathy/Account/gabble/jabber/goa_facebook_account_1377685019 Note that I had to fix bug #79832 first before being able to reproduce this issue with MC master. When GOA is restarted, here is what happens from MC's pov: - Each GOA account is removed - Each GOA account is created We are hitting this assertion because the old McdAccount is still alive when the new one is created for the account. There are two reasons for this: - In mcd_account_delete_async() we call _mcd_account_set_enabled () to disable enabled accounts. This calls mcd_account_changed_property() which is going to do this change async and so ref the McdAccount will doing so. - mcd_account_delete_async() uses a GTask internally; it doesn't really need it as all its work in sync but it's a convenient object to report error or success to the user callback. But when it calls g_task_return_boolean() GTask will internally calls the user callback in an idle callback and so keeping its source object (the McdAccount) alive longer. We could solve the first problem by not updating the Account.Enabled property of the account when deleting it. Does it really make sense to update it for an account which is about to disappear anyway? An easy hackish solution for the second issue could be to use GSimpleAsyncResult instead of GTask with g_simple_async_result_complete() so the user callback is called right away. Or maybe mcd_account_delete_async() should just be a sync function as it doesn't really do any async work anyway? Another option could be to unregister the Account D-Bus object earlier in the deletion process to avoid such tricky issues. (In reply to comment #3) > - mcd_account_delete_async() uses a GTask internally; it doesn't really need > it as all its work in sync but it's a convenient object to report error or > success to the user callback. It is an API convention that async functions should always return in an async way, even if their implementation could have been sync: callers should be able to say "this will happen synchronously" or "this will take time" but never "this will happen sync or async depending on implementation and I can't tell which". Deleting accounts calls out to a potentially-external backend, so it can (conceptually) take time, so it is always async (even if the GOA backend is in fact blocking). > We could solve the first problem by not updating the Account.Enabled > property of the account when deleting it. Does it really make sense to > update it for an account which is about to disappear anyway? I believe the idea was: * if the account cannot be deleted, we do the closest thing we can * disabling the account has side-effects, like taking it offline and cancelling its channel requests, and we want those to happen regardless > Another option could be to unregister the Account D-Bus object earlier in > the deletion process to avoid such tricky issues. I feel as though this: > (process:13703): mcd-DEBUG: mcd_account_delete: Forcing Account.Removed for > gabble/jabber/goa_facebook_account_1377685019 ought to be the point at which the account is unregistered: that's the point at which we have "officially" removed it. Does that actually take place? When this code was written, dbus-glib had a bug (well, major feature omission): objects could only be removed from the bus via last-unref. We fixed that: you can now unregister objects explicitly. Our daemons should behave accordingly. > (process:13703): mc-plugins-DEBUG: account-storage.c:907: default-gkeyfile: > called for gabble/jabber/goa_facebook_account_1377685019 If this debug message logged the function name instead of the file+line, it would make a lot more sense. I can't tell which is "added" and which is "removed". The debug messages seem to have been written with the assumption that DEBUG() would log the function name. Created attachment 100740 [details] [review] use G_STRFUNC in mission-control-plugins's DEBUG macro Created attachment 100741 [details] [review] mcd-account: add unregister_dbus_service() Created attachment 100742 [details] [review] mcd-account: unregister the account once we're done deleting it Comment on attachment 100740 [details] [review] use G_STRFUNC in mission-control-plugins's DEBUG macro Review of attachment 100740 [details] [review]: ----------------------------------------------------------------- r+ Comment on attachment 100742 [details] [review] mcd-account: unregister the account once we're done deleting it Review of attachment 100742 [details] [review]: ----------------------------------------------------------------- r+, and so is the commit above that it depends on. That other commit would be wrong on its own (unused static function would break the build), so I would personally squash those two, taking the commit message from this one. Merged both commits to 5.16 for 5.16.2 and merged it back to master as well. OK mc is not crashing anymore, but now I'm seeing the following when using goa-daemon --replace mcd/-CRITICAL: 11/06/14 07:10:34.590511: unregister_dbus_service: assertion 'MCD_IS_ACCOUNT (self)' failed Goa/-WARNING: 11/06/14 07:10:34.626550: Error setting property 'ChatDisabled' on interface org.gnome.OnlineAccounts.Account: GDBus.Error:org.freedesktop.DBus.Error.NoReply: Message did not receive a reply (timeout by message bus) (g-dbus-error-quark, 4) Goa/-WARNING: 11/06/14 07:10:34.626638: Error setting property 'ChatDisabled' on interface org.gnome.OnlineAccounts.Account: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name :1.16 was not provided by any .service files (g-dbus-error-quark, 2) mcd/-WARNING: 11/06/14 07:10:34.627469: disconnect_cb: Disconnect failed: Method "Disconnect" with signature "" on interface "org.freedesktop.Telepathy.Connection" doesn't exist mcd/-WARNING: 11/06/14 07:10:59.583623: disconnect_cb: Disconnect failed: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken. (In reply to comment #11) > OK mc is not crashing anymore, but now I'm seeing the following when using > goa-daemon --replace > > mcd/-CRITICAL: 11/06/14 07:10:34.590511: unregister_dbus_service: assertion > 'MCD_IS_ACCOUNT (self)' failed Looks like I introduced this bug when backporting the patch from master to 5.16; patch on the way. Created attachment 100867 [details] [review] mcd_account_delete: make sure that the account stays alive Hey, OK, all the MC related warnings/error when goa is restarted are gone for me now. I still have the 'ChatDisabled' goa warning, but I guess this is a separate issue Comment on attachment 100867 [details] [review] mcd_account_delete: make sure that the account stays alive Review of attachment 100867 [details] [review]: ----------------------------------------------------------------- r+ Merged to 5.16. |
Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.
- Have at least one GOA TP account - restart GOA ( /usr/libexec/goa-daemon --replace ) ** (process:13357): ERROR **: Failed to register GObject with DBusConnection: org.freedesktop.DBus.Error.ObjectPathInUse A handler is already registered for /org/freedesktop/Telepathy/Account/gabble/jabber/goa_facebook_account_1377685019 #0 0x00000035164504e9 in g_logv (log_domain=0x0, log_level=G_LOG_LEVEL_ERROR, format=<optimized out>, args=args@entry=0x7fff67f811e0) at gmessages.c:989 #1 0x000000351645063f in g_log (log_domain=<optimized out>, log_level=<optimized out>, format=<optimized out>) at gmessages.c:1025 #2 0x0000003da760f10d in dbus_g_connection_register_g_object () from /lib64/libdbus-glib-1.so.2 #3 0x0000000000425b82 in _mcd_account_constructed () #4 0x0000003517015d87 in g_object_new_with_custom_constructor (n_params=4, params=0x7fff67f81640, class=0x1418a00) at gobject.c:1721 #5 g_object_new_internal (class=class@entry=0x1418a00, params=params@entry=0x7fff67f81640, n_params=4) at gobject.c:1744 #6 0x0000003517017814 in g_object_new_valist (object_type=object_type@entry=21063776, first_property_name=first_property_name@entry=0x44191d "storage", var_args=var_args@entry=0x7fff67f81790) at gobject.c:2002 #7 0x0000003517017c11 in g_object_new (object_type=21063776, first_property_name=0x44191d "storage") at gobject.c:1559 #8 0x0000000000420a7e in mcd_account_new () #9 0x0000000000429407 in created_cb () #10 0x0000003517010298 in g_closure_invoke (closure=0x14103a0, return_value=return_value@entry=0x0, n_param_values=2, param_values=param_values@entry=0x7fff67f81ab0, invocation_hint=invocation_hint@entry=0x7fff67f81a50) at gclosure.c:777 #11 0x000000351702235d in signal_emit_unlocked_R (node=node@entry=0x13917d0, detail=detail@entry=0, instance=instance@entry=0x1392030, emission_return=emission_return@entry=0x0, instance_and_params=instance_and_params@entry=0x7fff67f81ab0) at gsignal.c:3586 #12 0x000000351702a0f2 in g_signal_emit_valist (instance=instance@entry=0x1392030, signal_id=signal_id@entry=11, detail=detail@entry=0, var_args=var_args@entry=0x7fff67f81cb8) at gsignal.c:3330 #13 0x000000351702a8f8 in g_signal_emit_by_name (instance=0x1392030, detailed_signal=0x7f0513d9e1f6 "created") at gsignal.c:3426 #14 0x00007f0513d9d814 in _new_account () from /usr/lib64/mission-control-plugins.0/mcp-account-manager-goa.so #15 0x000000351701359b in g_cclosure_marshal_VOID__OBJECTv (closure=0x1420b20, return_value=<optimized out>, instance=<optimized out>, args=<optimized out>, marshal_data=0x0, n_params=<optimized out>, param_types=0x1393070) at gmarshal.c:1312 #16 0x00000035170104c7 in _g_closure_invoke_va (closure=closure@entry=0x1420b20, return_value=return_value@entry=0x0, instance=instance@entry=0x137a840, args=args@entry=0x7fff67f82030, n_params=1, param_types=0x1393070) at gclosure.c:840 #17 0x0000003517029749 in g_signal_emit_valist (instance=0x137a840, signal_id=<optimized out>, detail=0, var_args=var_args@entry=0x7fff67f82030) at gsignal.c:3238 #18 0x000000351702a3af in g_signal_emit (instance=<optimized out>, signal_id=<optimized out>, detail=<optimized out>) at gsignal.c:3386 #19 0x0000003517010298 in g_closure_invoke (closure=0x7f050c0293c0, return_value=return_value@entry=0x0, n_param_values=2, param_values=param_values@entry=0x7fff67f822a0, invocation_hint=invocation_hint@entry=0x7fff67f82240) at gclosure.c:777 #20 0x000000351702235d in signal_emit_unlocked_R (node=node@entry=0x7f050c003280, detail=detail@entry=0, instance=instance@entry=0x7f050c006070, emission_return=emission_return@entry=0x0, instance_and_params=instance_and_params@entry=0x7fff67f822a0) at gsignal.c:3586 #21 0x000000351702a0f2 in g_signal_emit_valist (instance=instance@entry=0x7f050c006070, signal_id=signal_id@entry=20, detail=detail@entry=0, var_args=var_args@entry=0x7fff67f824a8) at gsignal.c:3330 #22 0x000000351702a8f8 in g_signal_emit_by_name (instance=instance@entry=0x7f050c006070, detailed_signal=detailed_signal@entry=0x3da2b1c7c2 "object-added") at gsignal.c:3426 #23 0x0000003da2adb6c3 in add_interfaces (manager=manager@entry=0x7f050c006070, object_path=0x7f0504007480 "/org/gnome/OnlineAccounts/Accounts/account_1377685019", ifaces_and_properties=<optimized out>, name_owner=name_owner@entry=0x1474140 ":1.284") at gdbusobjectmanagerclient.c:1564 #24 0x0000003da2adc0d4 in process_get_all_result (manager=0x7f050c006070, value=<optimized out>, name_owner=0x1474140 ":1.284") at gdbusobjectmanagerclient.c:1650 #25 0x0000003da2adca6d in on_notify_g_name_owner (object=<optimized out>, pspec=<optimized out>, user_data=0x7f050c006070) at gdbusobjectmanagerclient.c:1311 #26 0x0000003517010298 in g_closure_invoke (closure=0x7f050c017bd0, return_value=return_value@entry=0x0, n_param_values=2, param_values=param_values@entry=0x7fff67f82ab0, invocation_hint=invocation_hint@entry=0x7fff67f82a50) at gclosure.c:777 #27 0x000000351702235d in signal_emit_unlocked_R (node=node@entry=0x13799f0, detail=detail@entry=419, instance=instance@entry=0x7f050c0055d0, emission_return=emission_return@entry=0x0, instance_and_params=instance_and_params@entry=0x7fff67f82ab0) at gsignal.c:3586 #28 0x000000351702a0f2 in g_signal_emit_valist (instance=<optimized out>, signal_id=<optimized out>, detail=<optimized out>, var_args=var_args@entry=0x7fff67f82c40) at gsignal.c:3330 #29 0x000000351702a3af in g_signal_emit (instance=<optimized out>, signal_id=<optimized out>, detail=<optimized out>) at gsignal.c:3386 #30 0x0000003517014945 in g_object_dispatch_properties_changed (object=0x7f050c0055d0, n_pspecs=0, pspecs=0x0) at gobject.c:1047 #31 0x0000003517017019 in g_object_notify_by_spec_internal (pspec=<optimized out>, object=0x7f050c0055d0) at gobject.c:1141 #32 g_object_notify (object=object@entry=0x7f050c0055d0, property_name=property_name@entry=0x3da2b1c927 "g-name-owner") at gobject.c:1183 #33 0x0000003da2acc1ca in on_name_owner_changed (connection=<optimized out>, sender_name=<optimized out>, object_path=<optimized out>, interface_name=<optimized out>, signal_name=<optimized out>, parameters=<optimized out>, user_data=0x7f050c012360) at gdbusproxy.c:1361 #34 0x0000003da2abc435 in emit_signal_instance_in_idle_cb (data=0x7f05040069b0) at gdbusconnection.c:3743 #35 0x00000035164492a6 in g_main_dispatch (context=0x13838d0) at gmain.c:3066 #36 g_main_context_dispatch (context=context@entry=0x13838d0) at gmain.c:3642 ---Type <return> to continue, or q <return> to quit--- #37 0x0000003516449628 in g_main_context_iterate (context=0x13838d0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3713 #38 0x0000003516449a3a in g_main_loop_run (loop=0x1384310) at gmain.c:3907 #39 0x000000000040ebaf in main ()