Bug 23853

Summary: [fixed in git] Crash with tp_connection_manager_got_protocols: assertion failed: (self->priv->found_protocols == NULL)
Product: Telepathy Reporter: Guillaume Desmottes <guillaume.desmottes>
Component: tp-glibAssignee: Telepathy bugs list <telepathy-bugs>
Status: RESOLVED FIXED QA Contact: Telepathy bugs list <telepathy-bugs>
Severity: normal    
Priority: high CC: bugzilla
Version: unspecified   
Hardware: Other   
OS: All   
URL: http://git.collabora.co.uk/?p=user/smcv/telepathy-glib-smcv.git;a=shortlog;h=refs/heads/08-cm-crash
Whiteboard:
i915 platform: i915 features:

Description Guillaume Desmottes 2009-09-10 14:43:10 UTC
To reproduce:
- Empathy master
- Haze 0.3.2 with the .manager file removed
- pidgin-facebookchat installed
- No Haze existing haze account

- Try to add a Facebook account
- File the username and password
- MC5 sometimes crashes with:

** (process:22390): DEBUG: _mcd_account_manager_create_account: called
** (process:22390): DEBUG: _mcd_account_constructed: 0x1b66440 (haze/facebook/test0)
** (process:22390): DEBUG: [mcd-manager.c:266]: Referencing (8) object 0x1b60010 of type McdDispatcher
** (process:22390): DEBUG: mcd_manager_setup: Manager haze created
** (process:22390): DEBUG: _mcd_mission_set_parent: child = 0x1b67190, parent = 0x1b56840
** (process:22390): DEBUG: [mcd-mission.c:213]: Referencing (6) object 0x1b56840 of type McdService
** (process:22390): DEBUG: [mcd-account.c:571]: Referencing (1) object 0x1b67190 of type McdManager
** (process:22390): DEBUG: on_manager_ready: manager haze is ready
** (process:22390): DEBUG: [mcd-misc.c:187]: Referencing (2) object 0x1b67190 of type McdManager
** (process:22390): DEBUG: on_manager_ready: got error: Connection manager process exited during introspection
** (process:22390): DEBUG: [mcd-account.c:293]: Referencing (1) object 0x1b66440 of type McdAccount
** (process:22390): DEBUG: [mcd-misc.c:187]: Referencing (2) object 0x1b66440 of type McdAccount
** (process:22390): DEBUG: _mcd_account_set_parameters: called
** (process:22390): DEBUG: [mcd-account-manager.c:451]: Unreferencing (3) object 0x1b66440 of type McdAccount
** (process:22390): DEBUG: [mcd-misc.c:193]: Unreferencing (2) object 0x1b66440 of type McdAccount
** (process:22390): DEBUG: _mcd_account_maybe_autoconnect: haze/facebook/test0 not Enabled
** (process:22390): DEBUG: [mcd-account.c:337]: Unreferencing (1) object 0x1b66440 of type McdAccount
** (process:22390): DEBUG: _mcd_account_dispose: 0x1b66440 (haze/facebook/test0)
** (process:22390): DEBUG: [mcd-account.c:2111]: Unreferencing (3) object 0x1b67190 of type McdManager
** (process:22390): DEBUG: _mcd_account_finalize: 0x1b66440 (haze/facebook/test0)
** (process:22390): DEBUG: [mcd-misc.c:193]: Unreferencing (2) object 0x1b67190 of type McdManager
**
tp-glib:ERROR:connection-manager.c:618:tp_connection_manager_got_protocols: assertion failed: (self->priv->found_protocols == NULL)


Empathy logs:

empathy:22391): empathy-DEBUG: account_widget_applied_cb: Could not apply changes to account: Protocol facebook not found
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(:1.54,  -> :1.54)
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(:1.54,  -> :1.54)
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(im.pidgin.purple.PurpleService,  -> :1.54)
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(im.pidgin.purple.PurpleService,  -> :1.54)
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(im.pidgin.purple.PurpleService, :1.54 -> )
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(im.pidgin.purple.PurpleService, :1.54 -> )
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.ConnectionManager.haze,  -> :1.54)
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.ConnectionManager.haze,  -> :1.54)
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.AccountManager, :1.49 -> )
(empathy:22391): empathy-DEBUG: account_manager_name_owner_cb: Name owner changed for org.freedesktop.Telepathy.AccountManager, new name: 
(empathy:22391): tp-glib-DEBUG: tp_proxy_borrow_interface_by_id: 0x2aee4c0: org.freedesktop.DBus.Peer DBusGProxy is 0x2af71c0
(empathy:22391): tp-glib-DEBUG: tp_proxy_dispose: 0x2aee4c0
(empathy:22391): tp-glib-DEBUG: tp_proxy_invalidate: 0x2aee4c0: Proxy unreferenced
(empathy:22391): tp-glib-DEBUG: tp_proxy_finalize: 0x2aee4c0
(empathy:22391): tp-glib-DEBUG: tp_proxy_dispose: 0x24b7120
(empathy:22391): tp-glib-DEBUG: tp_proxy_invalidate: 0x24b7120: Proxy unreferenced
(empathy:22391): tp-glib-DEBUG: tp_proxy_signal_connection_proxy_invalidated: 0x295a190: TpProxy 0x24b7120 invalidated (I have 0x24b7120): Proxy unreferenced
(empathy:22391): tp-glib-DEBUG: tp_proxy_finalize: 0x24b7120
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.AccountManager, :1.49 -> )
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.MissionControl5, :1.49 -> )
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.MissionControl5, :1.49 -> )
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.ChannelDispatcher, :1.49 -> )
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.ChannelDispatcher, :1.49 -> )
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(:1.49, :1.49 -> )
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(:1.49, :1.49 -> )
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(:1.55,  -> :1.55)
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(:1.55,  -> :1.55)
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.ChannelDispatcher,  -> :1.55)
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.ChannelDispatcher,  -> :1.55)
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.MissionControl5,  -> :1.55)
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.MissionControl5,  -> :1.55)
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.AccountManager,  -> :1.55)
(empathy:22391): empathy-DEBUG: account_manager_name_owner_cb: Name owner changed for org.freedesktop.Telepathy.AccountManager, new name: :1.55
(empathy:22391): tp-glib-DEBUG: tp_proxy_borrow_interface_by_id: 0x2af7310: org.freedesktop.Telepathy.AccountManager DBusGProxy is 0x2af7230
(empathy:22391): tp-glib-DEBUG: tp_proxy_borrow_interface_by_id: 0x2af7310: org.freedesktop.DBus.Properties DBusGProxy is 0x2a96a50
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.AccountManager,  -> :1.55)
(empathy:22391): empathy-DEBUG: empathy_account_got_all_cb: Got whole set of properties for /org/freedesktop/Telepathy/Account/idle/irc/dev0
(empathy:22391): empathy-DEBUG: emp_account_connection_cb: Signalling connection (nil) of account /org/freedesktop/Telepathy/Account/idle/irc/dev0
(empathy:22391): empathy-DEBUG: empathy_account_got_all_cb: Got whole set of properties for /org/freedesktop/Telepathy/Account/gabble/jabber/cassidy_2dtest1_40jabber_2ebelnet_2ebe0
(empathy:22391): empathy-DEBUG: idle_presence_changed_cb: Presence changed to '(null)' (1) "(null)"
(empathy:22391): empathy-DEBUG: empathy_account_got_all_cb: Got whole set of properties for /org/freedesktop/Telepathy/Account/salut/local_2dxmpp/account0
(empathy:22391): empathy-DEBUG: emp_account_connection_cb: Signalling connection (nil) of account /org/freedesktop/Telepathy/Account/salut/local_2dxmpp/account0
(empathy:22391): empathy-DEBUG: empathy_account_got_all_cb: Got whole set of properties for /org/freedesktop/Telepathy/Account/gabble/jabber/alice_40localhost1
(empathy:22391): empathy-DEBUG: emp_account_connection_cb: Signalling connection (nil) of account /org/freedesktop/Telepathy/Account/gabble/jabber/alice_40localhost1
(empathy:22391): empathy-DEBUG: idle_presence_changed_cb: Presence changed to 'available' (2) ""
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.ConnectionManager.haze, :1.54 -> )
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(org.freedesktop.Telepathy.ConnectionManager.haze, :1.54 -> )
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(:1.54, :1.54 -> )
(empathy:22391): tp-glib-DEBUG: noc_idle_context_invoke: NameOwnerChanged(:1.54, :1.54 -> )
Comment 1 Guillaume Desmottes 2009-09-10 14:48:09 UTC
Oh, I'm running MC 5.2.2 with tp-glib 0.7.36
Comment 2 Simon McVittie 2009-09-14 07:18:09 UTC
Could you get a backtrace, please?

I thought this was fixed in telepathy-glib 0.7.36 - are you sure your MC instance was using that version?
Comment 3 Guillaume Desmottes 2009-09-14 08:29:37 UTC
Just reproduced this crash with MC5 master and tp-glib .36

(process:6602): mcd-DEBUG: _mcd_account_manager_create_account: called
(process:6602): mcd-DEBUG: _mcd_account_constructed: 0x669c40 (haze/facebook/cass_40skynet_2ebe0)
(process:6602): mcd-DEBUG: mcd_manager_setup: Manager haze created
(process:6602): mcd-DEBUG: _mcd_mission_set_parent: child = 0x66a990, parent = 0x659840
(process:6602): mcd-DEBUG: on_manager_ready: manager haze is ready
(process:6602): mcd-DEBUG: on_manager_ready: got error: Connection manager process exited during introspection
(process:6602): mcd-DEBUG: _mcd_account_set_parameters: called
(process:6602): mcd-DEBUG: _mcd_account_maybe_autoconnect: haze/facebook/cass_40skynet_2ebe0 not Enabled
(process:6602): mcd-DEBUG: _mcd_account_dispose: 0x669c40 (haze/facebook/cass_40skynet_2ebe0)
(process:6602): mcd-DEBUG: _mcd_account_finalize: 0x669c40 (haze/facebook/cass_40skynet_2ebe0)
**
tp-glib:ERROR:connection-manager.c:618:tp_connection_manager_got_protocols: assertion failed: (self->priv->found_protocols == NULL)

Program received signal SIGABRT, Aborted.
0x00007ffff67f54b5 in *__GI_raise (sig=<value optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
64	../nptl/sysdeps/unix/sysv/linux/raise.c: Aucun fichier ou dossier de ce type.
	in ../nptl/sysdeps/unix/sysv/linux/raise.c
(gdb) bt
#0  0x00007ffff67f54b5 in *__GI_raise (sig=<value optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1  0x00007ffff67f8f50 in *__GI_abort () at abort.c:92
#2  0x00007ffff6b92720 in IA__g_assertion_message (domain=<value optimized out>, file=<value optimized out>, line=<value optimized out>, 
    func=0x7ffff7986ee0 "tp_connection_manager_got_protocols", message=0x68a980 "assertion failed: (self->priv->found_protocols == NULL)")
    at /build/buildd/glib2.0-2.21.6/glib/gtestutils.c:1316
#3  0x00007ffff6b92c90 in IA__g_assertion_message_expr (domain=0x7ffff797b76b "tp-glib", file=0x7ffff797df45 "connection-manager.c", line=618, 
    func=0x7ffff7986ee0 "tp_connection_manager_got_protocols", expr=<value optimized out>) at /build/buildd/glib2.0-2.21.6/glib/gtestutils.c:1327
#4  0x00007ffff79390c2 in tp_connection_manager_got_protocols (self=0x659b40, protocols=0x68c5f0, error=0x11, user_data=<value optimized out>, 
    user_object=<value optimized out>) at connection-manager.c:618
#5  0x00007ffff7939578 in _tp_cli_connection_manager_invoke_callback_list_protocols (self=0x659b40, error=0x0, args=0x68ba80, 
    generic_callback=0x7ffff7938fe0 <tp_connection_manager_got_protocols>, user_data=<value optimized out>, weak_object=0x26)
    at ../telepathy-glib/_gen/tp-cli-connection-manager-body.h:477
#6  0x00007ffff79685d7 in tp_proxy_pending_call_idle_invoke (p=0x657400) at proxy-methods.c:153
#7  0x00007ffff6b6cc4e in g_main_dispatch (context=0x652f00) at /build/buildd/glib2.0-2.21.6/glib/gmain.c:1960
#8  IA__g_main_context_dispatch (context=0x652f00) at /build/buildd/glib2.0-2.21.6/glib/gmain.c:2513
#9  0x00007ffff6b70618 in g_main_context_iterate (context=0x652f00, block=<value optimized out>, dispatch=<value optimized out>, self=<value optimized out>)
    at /build/buildd/glib2.0-2.21.6/glib/gmain.c:2591
#10 0x00007ffff6b70a75 in IA__g_main_loop_run (loop=0x658360) at /build/buildd/glib2.0-2.21.6/glib/gmain.c:2799
#11 0x000000000040bafe in main (argc=<value optimized out>, argv=<value optimized out>) at mc-server.c:80
Comment 4 Simon McVittie 2009-10-14 13:12:36 UTC
This can happen in other telepathy-glib users, such as the accounts UI in Maemo (and presumably also the accounts UI in Empathy, although I haven't seen it happen there).

It's easier to reproduce on slow Maemo devices than on fast laptops, because it's basically a race condition.

The crash occurs in the following situation:

* client calls ListProtocols [A] due to an initial tp_connection_manager_activate() (self->running has not been set explicitly, and is initially FALSE)
* client discovers that CM is definitely not running
* tp_connection_manager_end_introspection is called because the CM has been discovered not to be running; it is wrongly assumed that there will be no reply from [A]
* client calls ListProtocols [B] in an idle, because there's no .manager file
* CM starts up (it was activated by [A])
* ListProtocols [A] returns; its result is treated as if it was the result of [B]
* ListProtocols [B] returns; crash!
Comment 5 Simon McVittie 2009-10-14 14:35:55 UTC
Here's a branch. I think this fixes it (tested on an N900 with all .manager files deleted).
Comment 6 Simon McVittie 2009-10-14 14:39:30 UTC
This is a crash fix; perfect candidate for 0.8.

High priority because instability with haze.manager deleted blocks us deleting that file, which we've wanted to do for ages...
Comment 7 Jonny Lamb 2009-10-14 15:47:39 UTC
The first two patches look fine.

In the most recent commit, the only thing I can see is you should write "if (foo != NULL)" instead of "if (foo)".

Other than that, I think it's fine. Consider my small comment instareviewed and get merging!
Comment 8 Simon McVittie 2009-10-15 06:53:16 UTC
Merged without changes, after agreeing on IRC that Jonny's criticism was misplaced (he thought name_known was a pointer). This will be fixed in 0.8.1 and 0.9.1.

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.