Salut does not connect

Submitted by Alban Crequy

Assigned to Sjoerd Simons @sjoerd

Link to original bug (#16408)

Description

Sometimes, Salut does not connect.

I have D-Bus logs with SALUT_DEBUG enabled: $ grep salut /tmp/dbus-telepathy-alban.log Name "salut0" Profile "salut" Manager "salut" ** (process:3381): DEBUG: _mcd_manager_create_connection: Manager salut created ** (process:3381): DEBUG: Emitting account status changed for salut0: status = 1, reason = 1 ** (process:3381): DEBUG: mcd_connection_get_params_and_connect: Trying connect account: salut0 ** (process:3381): DEBUG: _mcd_connection_connect: Trying connect account: salut0 ** (process:3381): DEBUG: _mcd_manager_create_connection: Created a connection 0x9264c0 for account: salut0 (telepathy-salut:3398): tp-glib-DEBUG: started version 0.3.3.1 (telepathy-glib version 0.7.10.1) nu(telepathy-salut:3398): tp-glib-DEBUG: tp_cm_param_setter_offset: nickname = "alban" nua::keepalive: 12(telepathy-salut:3398): tp-glib-DEBUG: tp_cm_param_setter_offset: first-name = "Alban" (telepathy-salut:3398): tp-glib-DEBUG: tp_cm_param_setter_offset: last-name = "Crequy" (telepathy-salut:3398): tp-glib-DEBUG: parse_parameters: jid not given, using default behaviour (telepathy-salut:3398): tp-glib-DEBUG: parse_parameters: email not given, using default behaviour (telepathy-salut:3398): tp-glib-DEBUG: tp_cm_param_setter_offset: published-name = "alban" (telepathy-salut:3398): tp-glib-DEBUG: tp_base_connection_class_init: Initializing (TpBaseConnectionClass *)0x7cf580 (telepathy-salut:3398): tp-glib-DEBUG: tp_presence_mixin_class_init: called. (telepathy-salut:3398): tp-glib-DEBUG: tp_base_connection_init: Initializing (TpBaseConnection *)0x7d3000 (telepathy-salut:3398): tp-glib-DEBUG: tp_presence_mixin_init: called. (telepathy-salut:3398): tp-glib-DEBUG: tp_base_connection_constructor: Post-construction: (TpBaseConnection *)0x7d3000 (telepathy-salut:3398): tp-glib-DEBUG: tp_proxy_borrow_interface_by_id: 0x7cc6a0: org.freedesktop.DBus DBusGProxy is 0x7cc710 (telepathy-salut:3398): tp-glib-DEBUG: tp_base_connection_constructor: Handle repo for type #0 at (nil) (telepathy-salut:3398): tp-glib-DEBUG: tp_base_connection_constructor: Handle repo for type #1 at 0x7d58c0 (telepathy-salut:3398): tp-glib-DEBUG: tp_base_connection_constructor: Handle repo for type #2 at 0x7d5920 (telepathy-salut:3398): tp-glib-DEBUG: tp_base_connection_constructor: Handle repo for type #3 at 0x7c9520 (telepathy-salut:3398): tp-glib-DEBUG: tp_base_connection_constructor: Handle repo for type #4 at (nil) (telepathy-salut:3398): tp-glib-DEBUG: tp_base_connection_constructor: Channel factory #0 at 0x7d5980 (telepathy-salut:3398): tp-glib-DEBUG: tp_base_connection_constructor: Channel factory #1 at 0x7da000 (telepathy-salut:3398): tp-glib-DEBUG: tp_base_connection_constructor: Channel factory #2 at 0x7d7630 (telepathy-salut:3398): tp-glib-DEBUG: tp_base_connection_register: bus name org.freedesktop.Telepathy.Connection.salut.local_xmpp.alban (telepathy-salut:3398): tp-glib-DEBUG: tp_base_connection_register: object path /org/freedesktop/Telepathy/Connection/salut/local_xmpp/alban (telepathy-salut:3398): tp-glib-DEBUG: tp_base_connection_change_status: was 4294967295, now 1, for reason 1 (telepathy-salut:3398): tp-glib-DEBUG: tp_base_connection_change_status: emitting status-changed to 1, for reason 1

Avahi is running: $ ps aux |grep avahi avahi 3080 0.0 0.1 28764 1676 ? Ss 10:54 0:00 avahi-daemon: registering [alban-hp-2.local] avahi 3082 0.0 0.0 28512 432 ? Ss 10:54 0:00 avahi-daemon: chroot helper 105 4053 0.0 0.0 14300 836 ? S<s 10:55 0:00 avahi-autoipd: [eth0] bound 169.254.5.84 root 4054 0.0 0.0 5888 384 ? S<s 10:55 0:00 avahi-autoipd: [eth0] callout dispatcher

Salut is doing nothing useful:

(gdb) bt
#0  0x00007fbea5b99cef in poll () from /lib/libc.so.6
#1  0x00007fbea610d1e6 in g_main_context_iterate (context=0x7c62c0, block=1, 
    dispatch=1, self=<value optimized out>)
    at /tmp/buildd/glib2.0-2.16.3/glib/gmain.c:2951
#2  0x00007fbea610d657 in IA__g_main_loop_run (loop=0x7c29d0)
    at /tmp/buildd/glib2.0-2.16.3/glib/gmain.c:2850
#3  0x00007fbea5e9dfa3 in tp_run_connection_manager (
    prog_name=0x44b971 "telepathy-salut", version=0x44b98f "0.3.3.1", 
    construct_cm=0x40af5c <salut_create_connection_manager>, argc=1, 
    argv=0x7fffaf5af4f8) at run.c:263
#4  0x000000000040b006 in main (argc=1, argv=0x7fffaf5af4f8) at salut.c:33

strace on salut shows some D-Bus activity sometimes:

poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN, revents=POLLIN}], 2, -1) = 1 read(5, "l\4\1\1 \0\0\0q\1\0\0\211\0\0\0\1\1o\0\25\0\0\0/org/fr"..., 2048) = 381 read(5, 0x7df980, 2048) = -1 EAGAIN (Resource temporarily unavailable) poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0