Bug 51528

Summary: Being signed in with both iChat and Adium, then messaging Salut, crashes Salut
Product: Telepathy Reporter: Will Thompson <will>
Component: salutAssignee: Telepathy bugs list <telepathy-bugs>
Status: RESOLVED FIXED QA Contact: Telepathy bugs list <telepathy-bugs>
Severity: normal    
Priority: medium Keywords: patch
Version: git master   
Hardware: Other   
OS: All   
URL: http://cgit.collabora.com/git/user/wjt/wocky/commit/?h=porter-validate-jid-sooner
Whiteboard: review+
i915 platform: i915 features:

Description Will Thompson 2012-06-28 10:18:28 UTC 
I have both iChat and Adium signed into “Bonjour” on a machine called "bael". Despite telling Adium that I want its presence to be known as "guybrush@bael" (since iChat is already "wjt@bael"), it seems to specify "wjt@bael (2)" in its from='' attributes.

Unfortunately, Salut crashes when faced with trying to normalize "wjt@bael (2)" as a handle. Debug log and extremely unhelpful backtrace:

(telepathy-salut:913): wocky-DEBUG: _new_connection: wocky-meta-porter.c:601: New connection from 172.22.64.170!
(telepathy-salut:913): wocky-DEBUG: Parsing chunk: <?xml version="1.0" encoding="UTF-8" ?><stream:stream to="wjt@queeg" from="wjt@bael (2)" xmlns="jabber:client" xmlns:stream="http://etherx.jabber.org/streams"><message from="wjt@bael (2)" type="chat" to="wjt@queeg"><body>hi.</body><html xmlns="http://www.w3.org/1999/xhtml"><body><div>hi.</div></body></html></message><message from="wjt@bael (2)" to="wjt@queeg"><body></body><html xmlns="http://www.w3.org/1999/xhtml"></html><x xmlns="jabber:x:event"><id></id></x></message>
(telepathy-salut:913): wocky-DEBUG: handle_stream_open: wocky-xmpp-reader.c:431: Received stream opening: stream, prefix: stream, uri: http://etherx.jabber.org/streams
(telepathy-salut:913): wocky-DEBUG: handle_stream_open: wocky-xmpp-reader.c:450: Stream opening attribute: to = 'wjt@queeg' (prefix: <no prefix>, uri: <no uri>)
(telepathy-salut:913): wocky-DEBUG: handle_stream_open: wocky-xmpp-reader.c:450: Stream opening attribute: from = 'wjt@bael (2)' (prefix: <no prefix>, uri: <no uri>)
(telepathy-salut:913): wocky-DEBUG: _end_element_ns: Received stanza
* message xmlns='jabber:client' from='wjt@bael (2)' type='chat' to='wjt@queeg'
    * body
        "hi."
    * html xmlns='http://www.w3.org/1999/xhtml'
        * body
            * div
                "hi."
(telepathy-salut:913): wocky-DEBUG: _end_element_ns: Received stanza
* message xmlns='jabber:client' from='wjt@bael (2)' to='wjt@queeg'
    * body
    * html xmlns='http://www.w3.org/1999/xhtml'
    * x xmlns='jabber:x:event'
        * id
(telepathy-salut:913): wocky-DEBUG: recv_open_cb: wocky-ll-connector.c:371: stream opened from wjt@bael (2), sending open back
(telepathy-salut:913): wocky-DEBUG: wocky_xmpp_writer_stream_open: wocky-xmpp-writer.c:298: Writing stream opening: <?xml version='1.0' encoding='UTF-8'?>
<stream:stream xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' to="wjt@bael (2)" from="" version="1.0">

(telepathy-salut:913): wocky-DEBUG: send_open_cb: wocky-ll-connector.c:418: connected, sending stream features but not expecting anything back
(telepathy-salut:913): wocky-DEBUG: _write_node_tree: Serializing tree:
* features xmlns='http://etherx.jabber.org/streams'
(telepathy-salut:913): wocky-DEBUG: Writing xml: <stream:features/>
(telepathy-salut:913): wocky-DEBUG: maybe_start_timeout: wocky-meta-porter.c:278: Started porter timeout...
(telepathy-salut:913): wocky-DEBUG: wocky_ll_connector_dispose: wocky-ll-connector.c:152: dispose called
(telepathy-salut:913): salut-DEBUG: salut_im_manager_new_channel: Requested channel for handle: 2 (wjt@bael (2))
(telepathy-salut:913): salut-DEBUG: salut_contact_manager_get_contact: Getting contact for: wjt@bael (2)
**
wocky:ERROR:wocky-c2s-porter.c:212:stanza_handler_new: assertion failed: (from_valid)

Program received signal SIGABRT, Aborted.
0x00007ffff4755475 in *__GI_raise (sig=<optimized out>)
    at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
64	../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0  0x00007ffff4755475 in *__GI_raise (sig=<optimized out>)
    at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1  0x00007ffff47586f0 in *__GI_abort () at abort.c:92
#2  0x00007ffff5150317 in g_assertion_message (
    domain=domain@entry=0x7ffff6d7b09b "wocky", 
    file=file@entry=0x7ffff6d7b90d "wocky-c2s-porter.c", line=line@entry=212, 
    func=func@entry=0x7ffff6d7c8f0 "stanza_handler_new", message=<optimized out>)
    at /tmp/buildd/glib2.0-2.32.3/./glib/gtestutils.c:1861
#3  0x00007ffff5150834 in g_assertion_message_expr (domain=0x7ffff6d7b09b "wocky", 
    file=0x7ffff6d7b90d "wocky-c2s-porter.c", line=212, 
    func=0x7ffff6d7c8f0 "stanza_handler_new", expr=<optimized out>)
    at /tmp/buildd/glib2.0-2.32.3/./glib/gtestutils.c:1872
#4  0x00007ffff6d483ae in ?? ()
   from /usr/lib/telepathy/salut-0/lib/libwocky-telepathy-salut-0.8.0.so
#5  0x00007ffff6d49a68 in ?? ()
   from /usr/lib/telepathy/salut-0/lib/libwocky-telepathy-salut-0.8.0.so
#6  0x00007ffff6d590a6 in ?? ()
   from /usr/lib/telepathy/salut-0/lib/libwocky-telepathy-salut-0.8.0.so
#7  0x00007ffff6d5a8ed in ?? ()
   from /usr/lib/telepathy/salut-0/lib/libwocky-telepathy-salut-0.8.0.so
#8  0x00007ffff6d628a7 in wocky_porter_register_handler_from_va ()
   from /usr/lib/telepathy/salut-0/lib/libwocky-telepathy-salut-0.8.0.so
#9  0x00007ffff6d62a68 in wocky_porter_register_handler_from ()
   from /usr/lib/telepathy/salut-0/lib/libwocky-telepathy-salut-0.8.0.so
#10 0x0000000000426e6a in ?? ()
#11 0x00007ffff53f42b3 in g_object_newv (object_type=1, object_type@entry=7382816, 
    n_parameters=n_parameters@entry=5, parameters=parameters@entry=0x7097e0)
    at /tmp/buildd/glib2.0-2.32.3/./gobject/gobject.c:1741
#12 0x00007ffff53f4630 in g_object_new_valist (object_type=object_type@entry=7382816, 
    first_property_name=first_property_name@entry=0x46ecdf "connection", 
    var_args=var_args@entry=0x7fffffffdf18)
    at /tmp/buildd/glib2.0-2.32.3/./gobject/gobject.c:1830
#13 0x00007ffff53f4964 in g_object_new (object_type=7382816, 
    first_property_name=0x46ecdf "connection")
    at /tmp/buildd/glib2.0-2.32.3/./gobject/gobject.c:1545
#14 0x0000000000425bdf in ?? ()
#15 0x000000000042664e in ?? ()
#16 0x00007ffff6d48a6d in ?? ()
   from /usr/lib/telepathy/salut-0/lib/libwocky-telepathy-salut-0.8.0.so
#17 0x00007ffff6d4a202 in ?? ()
   from /usr/lib/telepathy/salut-0/lib/libwocky-telepathy-salut-0.8.0.so
#18 0x00007ffff569c3f7 in g_simple_async_result_complete (simple=0x726070)
    at /tmp/buildd/glib2.0-2.32.3/./gio/gsimpleasyncresult.c:767
#19 0x00007ffff569c4f9 in complete_in_idle_cb (data=<optimized out>)
    at /tmp/buildd/glib2.0-2.32.3/./gio/gsimpleasyncresult.c:779
#20 0x00007ffff512f205 in g_main_dispatch (context=0x6a4860)
    at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:2539
#21 g_main_context_dispatch (context=context@entry=0x6a4860)
    at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:3075
#22 0x00007ffff512f538 in g_main_context_iterate (context=0x6a4860, block=block@entry=1, 
    dispatch=dispatch@entry=1, 
    self=<error reading variable: Unhandled dwarf expression opcode 0xfa>)
    at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:3146
#23 0x00007ffff512f932 in g_main_loop_run (loop=0x6a7650)
    at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:3340
#24 0x00007ffff4e1da7f in tp_run_connection_manager (prog_name=<optimized out>, 
    version=<optimized out>, construct_cm=<optimized out>, argc=<optimized out>, 
    argv=<optimized out>) at run.c:285
#25 0x000000000041be08 in main ()
Comment 1 Will Thompson 2012-06-28 10:21:48 UTC 
(It's notable that "wjt@bael (2)" shows up just fine on my roster. It's only when registering a handler for a particular JID on the porter (cf. bug 51527) that it crashes. Here's the Salut debug output and backtrace for requesting a channel to "wjt@bael (2)" in Empathy:

(telepathy-salut:1264): tp-glib/connection-DEBUG: channel_request_new: New channel request at 0x6c1010: ctype=org.freedesktop.Telepathy.Channel.Type.Text htype=1 handle=2 suppress=0
(telepathy-salut:1264): salut-DEBUG: salut_im_manager_new_channel: Requested channel for handle: 2 (wjt@bael (2))
(telepathy-salut:1264): salut-DEBUG: salut_contact_manager_get_contact: Getting contact for: wjt@bael (2)
(telepathy-salut:1264): wocky-DEBUG: wocky_meta_porter_hold: wocky-meta-porter.c:388: Porter to 'wjt@bael (2)' refcount 0 --> 1
(telepathy-salut:1264): tp-glib/connection-DEBUG: satisfy_request: completing queued request 0x6c1010 with success, channel_type=org.freedesktop.Telepathy.Channel.Type.Text, handle_type=1, handle=2, suppress_handler=0
(telepathy-salut:1264): tp-glib/connection-DEBUG: channel_request_free: Freeing channel request at 0x6c1010: ctype=org.freedesktop.Telepathy.Channel.Type.Text htype=1 handle=2 suppress=0
(telepathy-salut:1264): salut-DEBUG: salut_contact_manager_get_contact: Getting contact for: wjt@bael (2)
(telepathy-salut:1264): salut-DEBUG: salut_contact_manager_get_contact: Getting contact for: wjt@bael (2)
(telepathy-salut:1264): salut-DEBUG: salut_contact_manager_get_contact: Getting contact for: wjt@bael (2)
(telepathy-salut:1264): wocky-DEBUG: process_one_address: wocky-ll-connection-factory.c:190: connecting to 172.22.64.170 (port 5298)
(telepathy-salut:1264): tp-glib/misc-DEBUG: tp_message_to_text: Parsing part 1, type text/plain, alternative (null)
(telepathy-salut:1264): tp-glib/misc-DEBUG: tp_message_to_text: ... is text/plain
(telepathy-salut:1264): tp-glib/misc-DEBUG: tp_message_to_text: ... using its text
(telepathy-salut:1264): wocky-DEBUG: connect_to_host_cb: wocky-ll-connection-factory.c:151: made connection
(telepathy-salut:1264): wocky-DEBUG: wocky_xmpp_writer_stream_open: wocky-xmpp-writer.c:298: Writing stream opening: <?xml version='1.0' encoding='UTF-8'?>
<stream:stream xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' to="wjt@bael (2)" from="wjt@queeg" version="1.0">

(telepathy-salut:1264): wocky-DEBUG: send_open_cb: wocky-ll-connector.c:408: successfully sent stream open, now waiting for other side to too
(telepathy-salut:1264): wocky-DEBUG: Parsing chunk: <?xml version="1.0" encoding="UTF-8" ?>
(telepathy-salut:1264): wocky-DEBUG: Parsing chunk: <stream:stream to="wjt@queeg" from="wjt@bael (2)" xmlns="jabber:client" xmlns:stream="http://etherx.jabber.org/streams">
(telepathy-salut:1264): wocky-DEBUG: handle_stream_open: wocky-xmpp-reader.c:431: Received stream opening: stream, prefix: stream, uri: http://etherx.jabber.org/streams
(telepathy-salut:1264): wocky-DEBUG: handle_stream_open: wocky-xmpp-reader.c:450: Stream opening attribute: to = 'wjt@queeg' (prefix: <no prefix>, uri: <no uri>)
(telepathy-salut:1264): wocky-DEBUG: handle_stream_open: wocky-xmpp-reader.c:450: Stream opening attribute: from = 'wjt@bael (2)' (prefix: <no prefix>, uri: <no uri>)
(telepathy-salut:1264): wocky-DEBUG: recv_open_cb: wocky-ll-connector.c:361: connected, sending stream features but not expecting anything back
(telepathy-salut:1264): wocky-DEBUG: _write_node_tree: Serializing tree:
* features xmlns='http://etherx.jabber.org/streams'
(telepathy-salut:1264): wocky-DEBUG: Writing xml: <stream:features/>
(telepathy-salut:1264): wocky-DEBUG: made_connection_connect_cb: wocky-meta-porter.c:953: connected
**
wocky:ERROR:wocky-c2s-porter.c:212:stanza_handler_new: assertion failed: (from_valid)
[New Thread 0x7ffff1ef5700 (LWP 1285)]
[New Thread 0x7ffff16f4700 (LWP 1286)]

Program received signal SIGABRT, Aborted.

#0  0x00007ffff4755475 in *__GI_raise (sig=<optimized out>)
    at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1  0x00007ffff47586f0 in *__GI_abort () at abort.c:92
#2  0x00007ffff5150317 in g_assertion_message (
    domain=domain@entry=0x7ffff6d7b09b "wocky", 
    file=file@entry=0x7ffff6d7b90d "wocky-c2s-porter.c", line=line@entry=212, 
    func=func@entry=0x7ffff6d7c8f0 "stanza_handler_new", message=<optimized out>)
    at /tmp/buildd/glib2.0-2.32.3/./glib/gtestutils.c:1861
#3  0x00007ffff5150834 in g_assertion_message_expr (domain=0x7ffff6d7b09b "wocky", 
    file=0x7ffff6d7b90d "wocky-c2s-porter.c", line=212, 
    func=0x7ffff6d7c8f0 "stanza_handler_new", expr=<optimized out>)
    at /tmp/buildd/glib2.0-2.32.3/./glib/gtestutils.c:1872
#4  0x00007ffff6d483ae in ?? ()
   from /usr/lib/telepathy/salut-0/lib/libwocky-telepathy-salut-0.8.0.so
#5  0x00007ffff6d49a68 in ?? ()
   from /usr/lib/telepathy/salut-0/lib/libwocky-telepathy-salut-0.8.0.so
#6  0x00007ffff6d590a6 in ?? ()
   from /usr/lib/telepathy/salut-0/lib/libwocky-telepathy-salut-0.8.0.so
#7  0x00007ffff6d59e44 in ?? ()
   from /usr/lib/telepathy/salut-0/lib/libwocky-telepathy-salut-0.8.0.so
#8  0x00007ffff6d59f78 in ?? ()
   from /usr/lib/telepathy/salut-0/lib/libwocky-telepathy-salut-0.8.0.so
#9  0x00007ffff569c3f7 in g_simple_async_result_complete (simple=0x725e30)
    at /tmp/buildd/glib2.0-2.32.3/./gio/gsimpleasyncresult.c:767
#10 0x00007ffff6d57381 in ?? ()
   from /usr/lib/telepathy/salut-0/lib/libwocky-telepathy-salut-0.8.0.so
#11 0x00007ffff569c3f7 in g_simple_async_result_complete (simple=0x725ea0)
    at /tmp/buildd/glib2.0-2.32.3/./gio/gsimpleasyncresult.c:767
#12 0x00007ffff6d726ee in ?? ()
   from /usr/lib/telepathy/salut-0/lib/libwocky-telepathy-salut-0.8.0.so
#13 0x00007ffff5696089 in async_ready_callback_wrapper (source_object=0x725f10, 
    res=0x725ce0, user_data=0x734890)
    at /tmp/buildd/glib2.0-2.32.3/./gio/goutputstream.c:595
#14 0x00007ffff569c3f7 in g_simple_async_result_complete (simple=0x725ce0)
    at /tmp/buildd/glib2.0-2.32.3/./gio/gsimpleasyncresult.c:767
#15 0x00007ffff56a75ce in g_socket_output_stream_write_ready (socket=<optimized out>, 
    condition=<optimized out>, stream=0x725f10)
    at /tmp/buildd/glib2.0-2.32.3/./gio/gsocketoutputstream.c:170
#16 0x00007ffff569cda6 in socket_source_dispatch (source=source@entry=0x733d00, 
    callback=<optimized out>, user_data=<optimized out>)
    at /tmp/buildd/glib2.0-2.32.3/./gio/gsocket.c:3168
#17 0x00007ffff512f205 in g_main_dispatch (context=0x6a4860)
    at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:2539
#18 g_main_context_dispatch (context=context@entry=0x6a4860)
    at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:3075
#19 0x00007ffff512f538 in g_main_context_iterate (context=0x6a4860, block=block@entry=1, 
    dispatch=dispatch@entry=1, 
    self=<error reading variable: Unhandled dwarf expression opcode 0xfa>)
    at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:3146
#20 0x00007ffff512f932 in g_main_loop_run (loop=0x6a7650)
    at /tmp/buildd/glib2.0-2.32.3/./glib/gmain.c:3340
#21 0x00007ffff4e1da7f in tp_run_connection_manager (prog_name=<optimized out>, 
    version=<optimized out>, construct_cm=<optimized out>, argc=<optimized out>, 
    argv=<optimized out>) at run.c:285
#22 0x000000000041be08 in main ()
Comment 2 Will Thompson 2012-11-16 15:21:36 UTC 
This is actually fixed by the fix for 51527: the assertion is WockyC2SPorter asserting that the JID you've told it to match is valid. In this context, “you” are the WockyMetaPorter. The fix for bug 51527 stops WockyMetaPorter telling WockyC2SPorter from matching on JIDs, so makes this bug go away.

There's a smaller bug that WockyC2SPorter should g_return_val_if_fail() from a more obvious location rather than asserting from deep inside its guts, but hey.
Comment 3 Will Thompson 2012-11-16 17:03:36 UTC 
The bug is fixed in telepathy-salut 0.8.1.

http://cgit.collabora.com/git/user/wjt/wocky/commit/?h=porter-validate-jid-sooner moves the check to happen sooner.
Comment 4 Simon McVittie 2012-11-21 12:11:44 UTC 
(In reply to comment #3)
> http://cgit.collabora.com/git/user/wjt/wocky/commit/?h=porter-validate-jid-
> sooner moves the check to happen sooner.

Looks good to me, ship it.

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.