Bug 22074

Summary: Any test using telepathy-gabble-debug fails
Product: Telepathy Reporter: Jonny Lamb <jonny.lamb>
Component: gabbleAssignee: Telepathy bugs list <telepathy-bugs>
Status: RESOLVED WONTFIX QA Contact: Telepathy bugs list <telepathy-bugs>
Severity: normal    
Priority: medium    
Version: unspecified   
Hardware: Other   
OS: All   
Whiteboard:
i915 platform: i915 features:

Description Jonny Lamb 2009-06-03 16:47:58 UTC
% make -C tests/twisted check-twisted TWISTED_TESTS=test-disco.py
make: Entering directory `/home/jonny/src/telepathy-gabble/tests/twisted'
make[1]: Entering directory `/home/jonny/src/telepathy-gabble/tests/twisted/tools'
make[1]: Leaving directory `/home/jonny/src/telepathy-gabble/tests/twisted/tools'
Temporary bus daemon is unix:abstract=/tmp/dbus-IFrHkPBIdd,guid=1d339410b3b0fe6601b6cb8d4a26da80
Temporary bus daemon PID is 24962
make[1]: Entering directory `/home/jonny/src/telepathy-gabble/tests/twisted'
Traceback (most recent call last):
  File "/home/jonny/src/telepathy-gabble/tests/twisted/gabbletest.py", line 381, in exec_test_deferred
    f(queue, bus, conn, stream)
  File "./test-disco.py", line 12, in test
    q.expect('dbus-signal', signal='StatusChanged', args=[0, 1])
  File "/home/jonny/src/telepathy-gabble/tests/twisted/servicetest.py", line 114, in expect
    event = self.wait()
  File "/home/jonny/src/telepathy-gabble/tests/twisted/servicetest.py", line 187, in wait
    raise TimeoutError
TimeoutError
FAIL: test-disco.py

And then looking at the backtrace from the core dumped:

Program terminated with signal 11, Segmentation fault.
[New process 10692]
#0  _lm_connection_async_connect_waiting (connection=0x95749c0) at lm-connection.c:947
947	lm-connection.c: No such file or directory.
	in lm-connection.c
(gdb) bt
#0  _lm_connection_async_connect_waiting (connection=0x95749c0) at lm-connection.c:947
#1  0x4025b4ad in g_io_unix_dispatch (source=0x955d8e8, callback=0x9559ba8, user_data=0x955d8e8) at /build/buildd-glib2.0_2.20.1-2-i386-hGzT8z/glib2.0-2.20.1/glib/giounix.c:162
#2  0x40224848 in IA__g_main_context_dispatch (context=0x955ae00) at /build/buildd-glib2.0_2.20.1-2-i386-hGzT8z/glib2.0-2.20.1/glib/gmain.c:1814
#3  0x40227dab in g_main_context_iterate (context=0x955ae00, block=1, dispatch=1, self=0x9561400) at /build/buildd-glib2.0_2.20.1-2-i386-hGzT8z/glib2.0-2.20.1/glib/gmain.c:2448
#4  0x4022827a in IA__g_main_loop_run (loop=0x955ad60) at /build/buildd-glib2.0_2.20.1-2-i386-hGzT8z/glib2.0-2.20.1/glib/gmain.c:2656
#5  0x40333fe0 in tp_run_connection_manager (prog_name=0x80d5c08 "telepathy-gabble", version=0x80d25a8 "0.7.28.1", construct_cm=0x80616e0 <construct_cm>, argc=1, argv=0xbfb24d34) at run.c:281
#6  0x080616b3 in gabble_main (argc=1, argv=0xbfb24d34) at gabble.c:112
#7  0x080566f9 in main (argc=5, argv=0x402a0600) at main-debug.c:42
Comment 1 Simon McVittie 2010-01-11 04:49:15 UTC
Do you still get this? I'm inclined to close it as WORKSFORME if not... the tests seem to work (modulo race conditions) for everyone else.
Comment 2 Jonny Lamb 2010-01-11 10:55:47 UTC
(In reply to comment #1)
> Do you still get this? I'm inclined to close it as WORKSFORME if not... the
> tests seem to work (modulo race conditions) for everyone else.

I do still get this, only on the 0.8 branch. It works fine on master.

I'm inclined to agree with your resolution as it does work for everyone else. Every time I've tried debugging it, it lead down a loudmouth well of doom.
Comment 3 Simon McVittie 2010-01-11 11:42:26 UTC
(In reply to comment #2)
> I'm inclined to agree with your resolution as it does work for everyone else.
> Every time I've tried debugging it, it lead down a loudmouth well of doom.

WORKSFORME it is, then.
Comment 4 Guillaume Desmottes 2010-03-17 09:19:01 UTC
If have a similar issue when running tests in the 0.8 branch with loudmouth 1.4.3-4.

#0  socket_connect_cb (source=0x890920, condition=G_IO_OUT, connect_data=0x89bd00) at lm-socket.c:543
#1  0x00002ada65cfdbce in g_main_dispatch (context=0x892d60) at /build/buildd/glib2.0-2.22.3/glib/gmain.c:1960
#2  IA__g_main_context_dispatch (context=0x892d60) at /build/buildd/glib2.0-2.22.3/glib/gmain.c:2513
#3  0x00002ada65d01598 in g_main_context_iterate (context=0x892d60, block=<value optimized out>, dispatch=<value optimized out>, 
    self=<value optimized out>) at /build/buildd/glib2.0-2.22.3/glib/gmain.c:2591
#4  0x00002ada65d019f5 in IA__g_main_loop_run (loop=0x892e40) at /build/buildd/glib2.0-2.22.3/glib/gmain.c:2799
#5  0x00002ada660361af in tp_run_connection_manager (prog_name=<value optimized out>, version=<value optimized out>, 
    construct_cm=<value optimized out>, argc=<value optimized out>, argv=<value optimized out>) at run.c:284
#6  0x00002ada662aaabd in __libc_start_main (main=<value optimized out>, argc=<value optimized out>, ubp_av=<value optimized out>, 
    init=<value optimized out>, fini=<value optimized out>, rtld_fini=<value optimized out>, stack_end=0x7fffa1b288e8)
    at libc-start.c:220
#7  0x0000000000413d99 in _start () at ../sysdeps/x86_64/elf/start.S:113
Comment 5 Guillaume Desmottes 2010-03-17 09:20:33 UTC
Valgrind log:

==28370== Invalid read of size 8
==28370==    at 0x6AB34F3: socket_connect_cb (lm-socket.c:518)
==28370==    by 0x6F2DBCD: g_main_context_dispatch (gmain.c:1960)
==28370==    by 0x6F31597: g_main_context_iterate (gmain.c:2591)
==28370==    by 0x6F319F4: g_main_loop_run (gmain.c:2799)
==28370==    by 0x72661AE: tp_run_connection_manager (run.c:284)
==28370==    by 0x74DAABC: (below main) (libc-start.c:220)
==28370==  Address 0x92628b8 is 8 bytes inside a block of size 48 free'd
==28370==    at 0x4C24D68: free (vg_replace_malloc.c:325)
==28370==    by 0x6AB3409: _lm_socket_succeeded (lm-socket.c:415)
==28370==    by 0x6AB36A4: socket_connect_cb (lm-socket.c:552)
==28370==    by 0x6F2DBCD: g_main_context_dispatch (gmain.c:1960)
==28370==    by 0x6F31597: g_main_context_iterate (gmain.c:2591)
==28370==    by 0x6F319F4: g_main_loop_run (gmain.c:2799)
==28370==    by 0x72661AE: tp_run_connection_manager (run.c:284)
==28370==    by 0x74DAABC: (below main) (libc-start.c:220)
==28370== 
Comment 6 Guillaume Desmottes 2010-03-18 02:19:19 UTC
Interesting, here is the log with LM_DEBUG=all

(telepathy-gabble:1925): gabble-DEBUG: do_connect: calling lm_connection_open
*** Connecting to: localhost:4242
*** SRV lookup disabled for localhost
Going to connect to localhost:4242
(telepathy-gabble:1925): tp-glib/connection-DEBUG: tp_base_connection_change_status: was 4294967295, now 1, for reason 1
(telepathy-gabble:1925): tp-glib/connection-DEBUG: tp_base_connection_change_status: emitting status-changed to 1, for reason 1
(telepathy-gabble:1925): gabble-DEBUG: connection_status_changed_cb: adding callbacks
(telepathy-gabble:1925): gabble-DEBUG: connection_status_changed_cb: adding callbacks
(telepathy-gabble:1925): gabble-DEBUG: connection_status_changed_cb: adding callbacks
Trying ::1 port 4242...
Connection failed.
Connection failed: Connection refused (error 111)
Freeing up IOChannel and file descriptor
Trying ::1 port 4242...
Connection failed.
Connection failed: Connection refused (error 111)
Freeing up IOChannel and file descriptor
Trying 127.0.0.1 port 4242...
Connection success (1).

SEND:
-----------------------------------
<?xml version='1.0' encoding='UTF-8'?>
-----------------------------------
*** Sending stream header

SEND:
-----------------------------------
<stream:stream version="1.0" xmlns="jabber:client" xmlns:stream="http://etherx.jabber.org/streams" to="localhost" id="18948281158">
-----------------------------------


So Gabble tries to connect using IPv6 first. So I tried to change the account param in gabbletest.py from 'localhost' to '127.0.0.1' and it works!

So I guess something goes wrong in lm when trying to connect to the IP6 address and a callback is called after resource have been destroyed.
Comment 7 Jonny Lamb 2010-03-18 03:48:10 UTC
(In reply to comment #6)
> So Gabble tries to connect using IPv6 first. So I tried to change the account
> param in gabbletest.py from 'localhost' to '127.0.0.1' and it works!
> 
> So I guess something goes wrong in lm when trying to connect to the IP6 address
> and a callback is called after resource have been destroyed.

I tried the same here, and it makes the tests work fine again!
Comment 8 Simon McVittie 2010-11-25 08:56:28 UTC
At this point I think Gabble 0.8/Loudmouth bugs are WONTFIX.

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.