Bug 22837

By looking at the MC log it seems tp-qt4 is sending org.freedesktop.Telepathy.Qt4.ErrorHandlingError as an error. This happens in 2 cases, one is when context is destroyed without being finished, other is when you call setFinishedWithError with no error code.

Could you please add a debug message on MethodInvocationContext destructor and check if it's being called with mFinished set to false.

Also please provide tp-qt4 logs :)

(In reply to comment #0)
> The scenario:
> =============
> 
> I have a Telepathy Channel Handler Client. Before I decide whether I want to
> handle some channels or not, I want to find out the aliases of the remote
> contacts of the channels. In order to do this, I have the following pseudocode:
> 
> MyChannelHandler::handleChannels(Channel channel, Context context)
> {
>   connect(channel->becomeReady(),
>           SIGNAL(finished()),
>           SLOT(onChannelReady()));
> 
>   m_context = context;
>   m_channel = channel;
> }
> 
> MyChannelHandler::onChannelReady()
> {  
>   if (m_channel->initiator()->alias() == "test@test.com") {
>     m_context->setFinished();
>   } else {
>     m_context->setFinishedWithError();
>   }
> }
> 
> The problem:
> ============
> 
> The finished() signal is never emitted, so onChannelReady() never gets called.
> MC Output reports an error from TpQt4.
> 
> MC Output:
> ==========
> 
> ** (process:17704): DEBUG: on_new_channels:
> /org/freedesktop/Telepathy/Connection/gabble/jabber/telepathy_2dtest2_40jabber_2eorg_2fTelepathy_2e52c9dcb6/ImChannel3
> ** (process:17704): DEBUG: on_new_channels:  
> "org.freedesktop.Telepathy.Channel.InitiatorID" => "grundleborg@googlemail.com"
> ** (process:17704): DEBUG: on_new_channels:  
> "org.freedesktop.Telepathy.Channel.TargetHandleType" => 1
> ** (process:17704): DEBUG: on_new_channels:  
> "org.freedesktop.Telepathy.Channel.TargetHandle" => 3
> ** (process:17704): DEBUG: on_new_channels:  
> "org.freedesktop.Telepathy.Channel.TargetID" => "grundleborg@googlemail.com"
> ** (process:17704): DEBUG: on_new_channels:  
> "org.freedesktop.Telepathy.Channel.Requested" => FALSE
> ** (process:17704): DEBUG: on_new_channels:  
> "org.freedesktop.Telepathy.Channel.ChannelType" =>
> "org.freedesktop.Telepathy.Channel.Type.Text"
> ** (process:17704): DEBUG: on_new_channels:  
> "org.freedesktop.Telepathy.Channel.InitiatorHandle" => 3
> ** (process:17704): DEBUG: on_new_channels:  
> "org.freedesktop.Telepathy.Channel.Interfaces" => ((GStrv*) 0x1f56110)
> ** (process:17704): DEBUG: _mcd_mission_set_parent: child = 0x1f57e30, parent =
> 0x1f3e8b0
> ** (process:17704): DEBUG: _mcd_channel_set_status: 0x1f57e30, 3
> ** (process:17704): DEBUG: _mcd_dispatcher_enter_state_machine: CTXREF11 on
> 0x1f5ed40
> ** (process:17704): DEBUG: _mcd_dispatcher_enter_state_machine: new dispatcher
> context 0x1f5ed40 for unrequested channel 0x1f57e30 (only):
> /org/freedesktop/Telepathy/Connection/gabble/jabber/telepathy_2dtest2_40jabber_2eorg_2fTelepathy_2e52c9dcb6/ImChannel3
> ** (process:17704): DEBUG: mcd_dispatch_operation_constructor: do10/0x1f45d90
> ** (process:17704): DEBUG: mcd_dispatch_operation_constructor: Channel:
> /org/freedesktop/Telepathy/Connection/gabble/jabber/telepathy_2dtest2_40jabber_2eorg_2fTelepathy_2e52c9dcb6/ImChannel3
> ** (process:17704): DEBUG: _mcd_dispatcher_enter_state_machine: No filters
> found for context 0x1f5ed40, starting the channel handler
> ** (process:17704): DEBUG: mcd_dispatcher_context_ref: CTXREF07 on 0x1f5ed40
> (ref = 1)
> ** (process:17704): DEBUG: mcd_dispatcher_context_ref: CTXREF13 on 0x1f5ed40
> (ref = 2)
> ** (process:17704): DEBUG: handlers_can_bypass_approval:
> org.freedesktop.Telepathy.Client.KopetePluginHandler has BypassApproval=T
> ** (process:17704): DEBUG: mcd_dispatcher_context_release_client_lock: called
> on 0x1f5ed40, locks = 1
> ** (process:17704): DEBUG: mcd_dispatcher_context_ref: CTXREF04 on 0x1f5ed40
> (ref = 3)
> ** (process:17704): DEBUG: mcd_dispatcher_run_handlers: Possible handler:
> org.freedesktop.Telepathy.Client.KopetePluginHandler (still exists: Y)
> ** (process:17704): DEBUG: _mcd_channel_set_status: 0x1f57e30, 4
> ** (process:17704): DEBUG: mcd_dispatcher_context_ref: CTXREF03 on 0x1f5ed40
> (ref = 4)
> ** (process:17704): DEBUG: mcd_dispatcher_handle_channels: calling
> HandleChannels on KopetePluginHandler for context 0x1f5ed40
> ** (process:17704): DEBUG: mcd_dispatcher_context_unref: CTXREF04 on 0x1f5ed40
> (ref = 5)
> ** (process:17704): DEBUG: mcd_dispatcher_context_unref: CTXREF13 on 0x1f5ed40
> (ref = 4)
> ** (process:17704): DEBUG: mcd_dispatcher_context_unref: CTXREF07 on 0x1f5ed40
> (ref = 3)
> ** (process:17704): DEBUG: mcd_dispatcher_context_unref: CTXREF11 on 0x1f5ed40
> (ref = 2)
> ** (process:17704): DEBUG: on_channel_ready: channel 0x1f57e30 is ready
> ** (process:17704): DEBUG: mcd_dispatcher_context_ref: CTXREF02 on 0x1f5ed40
> (ref = 1)
> ** (process:17704): WARNING **: handle_channels_cb got error:
> org.freedesktop.Telepathy.Qt4.ErrorHandlingError:
> org.freedesktop.Telepathy.Qt4.ErrorHandlingError
> ** (process:17704): DEBUG: _mcd_channel_set_status: 0x1f57e30, 6
> ** (process:17704): DEBUG: _mcd_channel_undispatchable: 0x1f57e30:
> /org/freedesktop/Telepathy/Connection/gabble/jabber/telepathy_2dtest2_40jabber_2eorg_2fTelepathy_2e52c9dcb6/ImChannel3
> ** (process:17704): DEBUG: _mcd_channel_undispatchable: calling Destroy()
> ** (process:17704): DEBUG: mcd_dispatcher_context_unref: CTXREF02 on 0x1f5ed40
> (ref = 2)
> ** (process:17704): DEBUG: mcd_handler_call_data_free: called
> ** (process:17704): DEBUG: mcd_dispatcher_context_unref: CTXREF03 on 0x1f5ed40
> (ref = 1)
> ** (process:17704): DEBUG: mcd_dispatcher_context_unref: freeing the context
> 0x1f5ed40
> ** (process:17704): DEBUG: _mcd_dispatch_operation_finish: do10/0x1f45d90 has
> finished
> ** (process:17704): DEBUG: proxy_destroyed: Channel proxy invalidated:
> tp_dbus_errors_quark 8: Channel was closed
> ** (process:17704): DEBUG: mcd_channel_abort: 0x1f57e30
> ** (process:17704): DEBUG: _mcd_mission_set_parent: child = 0x1f57e30, parent =
> (nil)
> ** (process:17704): DEBUG: _mcd_operation_remove_mission: removing mission:
> 0x1f57e30
> ** (process:17704): DEBUG: _mcd_channel_dispose: 0x1f57e30 (is disposed = 0)
> ** (process:17704): DEBUG: _mcd_mission_dispose: mission disposed 0x1f57e30
> ** (process:17704): DEBUG: _mcd_mission_finalize: mission finalized 0x1f57e30
> 

I added a debug to the MethodInvocationContext destructor and ran the app again. It is being called with mFinished set to false (see last line of following debug output).

TpQt4 Debug Output:
===================


telepathy-qt4 (version 0.1.7.1) DEBUG: HandleChannels: account: "/org/freedesktop/Telepathy/Account/gabble/jabber/telepathy_2dtest2_40jabber_2eorg0" , connection: "/org/freedesktop/Telepathy/Connection/gabble/jabber/telepathy_2dtest2_40jabber_2eorg_2fTelepathy_2efbc9cd80"
telepathy-qt4 (version 0.1.7.1) DEBUG: Creating new DBusProxy
telepathy-qt4 (version 0.1.7.1) DEBUG: ReadinessHelper: supportedStatuses = QSet()
telepathy-qt4 (version 0.1.7.1) DEBUG: ReadinessHelper: supportedFeatures = QSet()
telepathy-qt4 (version 0.1.7.1) DEBUG: ReadinessHelper: new supportedStatuses = QSet(0)
telepathy-qt4 (version 0.1.7.1) DEBUG: ReadinessHelper: new supportedFeatures = QSet(QPair("Tp::Account",0) ,  QPair("Tp::Account",1) ,  QPair("Tp::Account",2) )
telepathy-qt4 (version 0.1.7.1) DEBUG: Creating new DBusProxy
telepathy-qt4 (version 0.1.7.1) DEBUG: ReadinessHelper: supportedStatuses = QSet()
telepathy-qt4 (version 0.1.7.1) DEBUG: ReadinessHelper: supportedFeatures = QSet()
telepathy-qt4 (version 0.1.7.1) DEBUG: ReadinessHelper: new supportedStatuses = QSet(0, 2)
telepathy-qt4 (version 0.1.7.1) DEBUG: ReadinessHelper: new supportedFeatures = QSet(QPair("Tp::Connection",3) ,  QPair("Tp::Connection",2) ,  QPair("Tp::Connection",1) ,  QPair("Tp::Connection",0) )
telepathy-qt4 (version 0.1.7.1) DEBUG: Connecting to StatusChanged()
telepathy-qt4 (version 0.1.7.1) DEBUG: Calling GetStatus()
telepathy-qt4 (version 0.1.7.1) DEBUG: Reusing existing HandleContext
telepathy-qt4 (version 0.1.7.1) DEBUG: Creating new DBusProxy
telepathy-qt4 (version 0.1.7.1) DEBUG: ReadinessHelper: supportedStatuses = QSet()
telepathy-qt4 (version 0.1.7.1) DEBUG: ReadinessHelper: supportedFeatures = QSet()
telepathy-qt4 (version 0.1.7.1) DEBUG: Creating new Channel: ":1.79"
telepathy-qt4 (version 0.1.7.1) DEBUG:  Connecting to Channel::Closed() signal
telepathy-qt4 (version 0.1.7.1) DEBUG:  Connection to owning connection's lifetime signals
telepathy-qt4 (version 0.1.7.1) DEBUG: ReadinessHelper: new supportedStatuses = QSet(0)
telepathy-qt4 (version 0.1.7.1) DEBUG: ReadinessHelper: new supportedFeatures = QSet(QPair("Tp::Channel",0) )
telepathy-qt4 (version 0.1.7.1) DEBUG: ReadinessHelper: new supportedStatuses = QSet(0)
telepathy-qt4 (version 0.1.7.1) DEBUG: ReadinessHelper: new supportedFeatures = QSet(QPair("Tp::Channel",0) ,  QPair("Tp::TextChannel",0) ,  QPair("Tp::TextChannel",1) ,  QPair("Tp::TextChannel",2) )
kopete(7451)/kopete (Telepathy) TelepathyChannelManager::instance:
kopete(7451)/kopete (Telepathy) TelepathyChannelManager::handleChannels: Stored data member: 0x26db560
kopete(7451)/kopete (Telepathy) TelepathyChannelManager::handleChannels: Remote initiated channel.
kopete(7451)/kopete (Telepathy) TelepathyChannelManager::handleChannels: Check if the context is finished.
kopete(7451)/kopete (Telepathy) TelepathyChannelManager::handleChannels: handleCHannels finished.
~MethodInvocationContext(): Called with mFinished =  false

My fault. I fail at C++. Was storing a reference to context, not a copy of it, so it was going out of scope and getting deleted. fail++.