Bug 19762

Summary: assertion failure when disabling a gimpnet irc account while server is waiting for ident response
Product: Telepathy Reporter: Jonathon Jongsma <jonathon>
Component: idleAssignee: Telepathy bugs list <telepathy-bugs>
Status: RESOLVED FIXED QA Contact: Telepathy bugs list <telepathy-bugs>
Severity: normal    
Priority: medium    
Version: unspecified   
Hardware: Other   
OS: All   
Whiteboard:
i915 platform: i915 features:

Description Jonathon Jongsma 2009-01-27 09:08:06 UTC
From what I can tell, the gimpnet IRC server is particularly sluggish and if you enable that account and wait a few seconds until after idle has sent the NICK and USER accounts, and then disable the account, we will hit an assert.  

What seems to be happening is: when the account is disabled, idle will send a QUIT command to the server, but the server seems to be blocking waiting for an ident response, so it doesn't see the QUIT command.  telepathy-idle seems to be waiting for a response to the QUIT command before it actually terminates its connection to the server.  At some point (perhaps up to 30 seconds later), the server will decide to stop waiting for an ident response and will send the following messages:
 NOTICE AUTH :*** No Ident response
 :irc.acc.umu.se 001 idletest :Welcome to the Internet Relay Network

telepathy-idle will see this welcome message (001) and attempt to change our status to CONNECTED.  However, the act of sending the QUIT command apparently had already changed our internal status from CONNECTING to DISCONNECTED, so when we try to change our status to CONNECTED, we violate an assertion that we can only transition to CONNECTED if we're currently in CONNECTING state.

===========================================

Here is the debugger stack trace:

#0  g_logv (log_domain=0xb7d92007 \"tp-glib\", log_level=G_LOG_LEVEL_CRITICAL, format=0xb7c05171 \"%s: assertion `%s' failed\", args1=0xbfc7619c \"`4\?\?H5\?\?\?\?\?\?\?a\?\?\?\?\?\?\\a \?\?`4\?\?H5\?\?\\") at gmessages.c:493
#1  g_log (log_domain=0xb7d92007 \"tp-glib\", log_level=G_LOG_LEVEL_CRITICAL, format=0xb7c05171 \"%s: assertion `%s' failed\") at gmessages.c:517
#2  g_return_if_fail_warning (log_domain=0xb7d92007 \"tp-glib\", pretty_function=0xb7d93460 \"tp_base_connection_change_status\", expression=0xb7d93548 \"prev_status == TP_CONNECTION_STATUS_CONNECTING\") at gmessages.c:532
#3  tp_base_connection_change_status (self=0x95bd230, status=TP_CONNECTION_STATUS_CONNECTED, reason=TP_CONNECTION_STATUS_REASON_REQUESTED) at base-connection.c:2632
#4  connection_connect_cb (conn=0x95bd230, success=1, fail_reason=TP_CONNECTION_STATUS_REASON_NONE_SPECIFIED) at idle-connection.c:887
#5  _welcome_handler (parser=0x95c07f8, code=IDLE_PARSER_NUMERIC_WELCOME, args=0x95c41d0, user_data=0x95bd230) at idle-connection.c:848
#6  _parse_and_forward_one (parser=0x95c07f8, tokens=0x95c6950, code=IDLE_PARSER_NUMERIC_WELCOME, format=0x806423a \"\") at idle-parser.c:399
#7  _parse_message (parser=0x95c07f8, split_msg=0x95b47c0 \":irc.acc.umu.se 001 idletest :Welcome to the Internet Relay Network idletest\") at idle-parser.c:321
#8  idle_parser_receive (parser=0x95c07f8, msg=0x95c2e08 \":irc.acc.umu.se 001 idletest :Welcome to the Internet Relay Network idletest\\r\\n:irc.acc.umu.se 002 idletest :Your host is irc.acc.umu.se[130.239.18.157/6667], running version 2.8/gimpnet-0.1beta3\\r\\nNOTI\"...) at idle-parser.c:214
#9  sconn_received_cb (sconn=0x95c33b0, raw_msg=0x95bf970 \":irc.acc.umu.se 001 idletest :Welcome to the Internet Relay Network idletest\\r\\n:irc.acc.umu.se 002 idletest :Your host is irc.acc.umu.se[130.239.18.157/6667], running version 2.8/gimpnet-0.1beta3\\r\\nNOTI\"..., conn=0x95bd230) at idle-connection.c:661
#10  g_cclosure_marshal_VOID__STRING (closure=0x95b6aa8, return_value=0x0, n_param_values=2, param_values=0x95b8590, invocation_hint=0xbfc76968, marshal_data=0x0) at gmarshal.c:496
#11  g_closure_invoke (closure=0x95b6aa8, return_value=0x0, n_param_values=2, param_values=0x95b8590, invocation_hint=0xbfc76968) at gclosure.c:767
#12  signal_emit_unlocked_R (node=0x95bd800, detail=0, instance=0x95c33b0, emission_return=0x0, instance_and_params=0x95b8590) at gsignal.c:3244
#13  g_signal_emit_valist (instance=0x95c33b0, signal_id=22, detail=0, var_args=0xbfc76bfc \"0l\?\?,l\?\?\?5\\\b\?5\\\b\?u[\\t\\") at gsignal.c:2977
#14  g_signal_emit_by_name (instance=0x95c33b0, detailed_signal=0x80647b0 \"received\") at gsignal.c:3071
#15  io_func (src=0x95c8530, cond=G_IO_IN, data=0x95c33b0) at idle-server-connection.c:301
#16  g_io_unix_dispatch (source=0x95c6268, callback=0x8056ecc <io_func>, user_data=0x95c33b0) at giounix.c:162
#17  g_main_dispatch (context=0x95b37e8) at gmain.c:1814
#18  g_main_context_dispatch (context=0x95b37e8) at gmain.c:2367
#19  g_main_context_iterate (context=0x95b37e8, block=1, dispatch=1, self=0x95b8ca0) at gmain.c:2448
#20  g_main_loop_run (loop=0x95b2840) at gmain.c:2656
#21  tp_run_connection_manager (prog_name=0x8062df0 \"telepathy-idle\", version=0x8062de8 \"0.1.2.1\", construct_cm=0x804d3f4 <_construct_cm>, argc=1, argv=0xbfc77144) at run.c:264
#22  main (argc=1, argv=0xbfc77144) at idle.c:38

===========================================

Here is the relevant portion of the telepathy-idle log:

(telepathy-idle:5928): tp-glib-DEBUG: tp_cm_param_setter_offset: account = "idletest"
(telepathy-idle:5928): tp-glib-DEBUG: tp_cm_param_setter_offset: server = "irc.gimp.org"
(telepathy-idle:5928): tp-glib-DEBUG: tp_cm_param_setter_offset: port = 6667 = 0x1a0b
(telepathy-idle:5928): tp-glib-DEBUG: parse_parameters: password not given, using default behaviour
(telepathy-idle:5928): tp-glib-DEBUG: tp_cm_param_setter_offset: fullname = "test user"
(telepathy-idle:5928): tp-glib-DEBUG: tp_cm_param_setter_offset: charset = "UTF-8"
(telepathy-idle:5928): tp-glib-DEBUG: tp_cm_param_setter_offset: quit-message = "So long and thanks for all the IRC - telepathy-idle IRC Connection Manager for Telepathy - http://telepathy.freedesktop.org"
(telepathy-idle:5928): tp-glib-DEBUG: tp_cm_param_setter_offset: use-ssl = FALSE
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_init: Initializing (TpBaseConnection *)0x95bd230
(telepathy-idle:5928): tp-glib-DEBUG: tp_presence_mixin_init: called.
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_constructor: Post-construction: (TpBaseConnection *)0x95bd230
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_constructor: Handle repo for type #0 at (nil)
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_constructor: Handle repo for type #1 at 0x95c3230
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_constructor: Handle repo for type #2 at 0x95c3460
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_constructor: Handle repo for type #3 at (nil)
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_constructor: Handle repo for type #4 at (nil)
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_constructor: Channel factory #0 at 0x95b5c60
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_constructor: Channel factory #1 at 0x95b5c40
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_register: bus name org.freedesktop.Telepathy.Connection.idle.irc.idletest_40irc_2egimp_2eorg
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_register: object path /org/freedesktop/Telepathy/Connection/idle/irc/idletest_40irc_2egimp_2eorg
** (telepathy-idle:5928): DEBUG: change_state: emitting status-changed, state 1, reason 1
** (telepathy-idle:5928): DEBUG: sconn_status_changed_cb: called with state 1
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_change_status: was 4294967295, now 1, for reason 1
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_change_status: emitting status-changed to 1, for reason 1
** (telepathy-idle:5928): DEBUG: connect_io_func: connected!
** (telepathy-idle:5928): DEBUG: change_state: emitting status-changed, state 2, reason 1
** (telepathy-idle:5928): DEBUG: sconn_status_changed_cb: called with state 2
** (telepathy-idle:5928): DEBUG: _parse_message: parsing "NOTICE AUTH :*** Looking up your hostname..."
** (telepathy-idle:5928): DEBUG: _parse_message: parsing "NOTICE AUTH :*** Checking Ident"
** (telepathy-idle:5928): DEBUG: _parse_message: parsing "NOTICE AUTH :*** Found your hostname"
** (telepathy-idle:5928): DEBUG: msg_queue_timeout_cb: called
** (telepathy-idle:5928): DEBUG: iface_send_impl: sent "NICK idletest
"
** (telepathy-idle:5928): DEBUG: msg_queue_timeout_cb: called
** (telepathy-idle:5928): DEBUG: iface_send_impl: sent "USER idletest 8 * :test user
"
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_change_status: was 1, now 2, for reason 1
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_change_status: emitting status-changed to 2, for reason 1
** (telepathy-idle:5928): DEBUG: iface_send_impl: sent "QUIT :So long and thanks for all the IRC - telepathy-idle IRC Connection Manager for Telepathy - http://telepathy.freedesktop.org
"
** (telepathy-idle:5928): DEBUG: msg_queue_timeout_cb: called
** (telepathy-idle:5928): DEBUG: _parse_message: parsing "NOTICE AUTH :*** No Ident response"
** (telepathy-idle:5928): DEBUG: _parse_message: parsing ":irc.acc.umu.se 001 idletest :Welcome to the Internet Relay Network idletest"
** (telepathy-idle:5928): DEBUG: _parse_and_forward_one: message code 31
** (telepathy-idle:5928): DEBUG: _parse_atom: parsing atom "irc.acc.umu.se" as I
** (telepathy-idle:5928): DEBUG: _parse_atom: ignored token
** (telepathy-idle:5928): DEBUG: _parse_atom: parsing atom "001" as I
** (telepathy-idle:5928): DEBUG: _parse_atom: ignored token
** (telepathy-idle:5928): DEBUG: _parse_atom: parsing atom "idletest" as c
** (telepathy-idle:5928): DEBUG: _parse_atom: set handle 1
** (telepathy-idle:5928): DEBUG: _parse_and_forward_one: succesfully parsed
(telepathy-idle:5928): tp-glib-DEBUG: tp_base_connection_change_status: was 2, now 0, for reason 1

tp-glib-CRITICAL **: tp_base_connection_change_status: assertion `prev_status == TP_CONNECTION_STATUS_CONNECTING' failed
aborting...
Comment 1 Jonathon Jongsma 2009-01-27 13:04:34 UTC
I have a git branch that fixes this in my git repo.  The first commit adds tests for the bug, the second fixes the bug:

http://git.collabora.co.uk/?p=user/jonathon/telepathy-idle;a=shortlog;h=refs/heads/gimpnet-quit

review appreciated.
Comment 2 Jonathon Jongsma 2009-02-17 15:11:32 UTC
This has been reviewed and pushed to the main repository as well.  ad2a004f8aa490f756708c42b0d8b1f1759584c1

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.