Project

General

Profile

Preventing error "The user connection is no longer active"

Daniele Ricci
Added over 3 years ago

Hello,

I'm occasionally getting the above error for messages. While the error is legit (connections disappeared), I'd like to deliver those messages to offline storage instead of returning an error to the sender.

As far as I can see, the error is generated when ClientConnectionManager.writePacketToSocket returns false (some obscure socket error or the IOService gone :).

Is there a sane way to do this without patching Tigase code?

And even if it's the only way, is it sane/enough to just queue the message again with packetFrom and packetTo both set to null?

Thanks


Replies (9)

Added by Daniel Wisnewski IoT 1 Cloud over 3 years ago

Do you have any information on the recipient end of things? I assume this is caused by a user disconnecting from the sever, but not cleanly and in between the disconnect and when the server closes that connection.

If the client you are sending to loses connection, and it's before one of the watchdogs close the connection it can get stuck like that.

I'd give this option a go http://docs.tigase.org/tigase-server/snapshot/Administration_Guide/html/#watchdog and tighten up the tolerances from the defaults, once the receipient connection is closed, the server should store offline messages by default.

Added by Daniele Ricci over 3 years ago

Daniel Wisnewski wrote:

Do you have any information on the recipient end of things? I assume this is caused by a user disconnecting from the sever, but not cleanly and in between the disconnect and when the server closes that connection.

Exactly, although I don't have exact information except for the server log which states that the connection is being closed abruptly (which can happen in my client in certain situations).

If the client you are sending to loses connection, and it's before one of the watchdogs close the connection it can get stuck like that.

I'd give this option a go http://docs.tigase.org/tigase-server/snapshot/Administration_Guide/html/#watchdog and tighten up the tolerances from the defaults, once the receipient connection is closed, the server should store offline messages by default.

I don't know, it seems like a workaround. I mean it doesn't really solve the "sudden disconnection" case, don't you think?

Added by Wojciech Kapcia TigaseTeam over 3 years ago

Daniele Ricci wrote:

And even if it's the only way, is it sane/enough to just queue the message again with packetFrom and packetTo both set to null?

Are you sure those are message stanzas? Those shouldn't be process by that code (unless they don't have type, but if the message arrived without such it should be treated/stamped with normal type) and in such case it should be forwarded back to SM for processing (most likely storing to offline store).

Added by Daniele Ricci over 3 years ago

Wojciech Kapcia wrote:

Are you sure those are message stanzas?

Quite sure. I got messages with type=error myself a few days ago (several in sequence actually, like 4 messages in a row).

it should be forwarded back to SM for processing (most likely storing to offline store).

That's what I thought too. Is there any way I can help you debugging this? Besides patching Tigase in a very ugly way :)

Added by Wojciech Kapcia TigaseTeam over 3 years ago

Can you try enforcing either chat / normal type and check if the problem will happen again?

Added by Daniele Ricci over 3 years ago

Wojciech Kapcia wrote:

Can you try enforcing either chat / normal type and check if the problem will happen again?

Where should I do that? In the client (already done, no other type used outside of "chat") or in the server (and where exactly? In a plugin I should write?)

I've gathered an example log of those errors, maybe we can have a better view of this issue.

This is the original message being delivered to the recipient's connection:

2015-11-28 18:16:47.858 [in_0-c2s]         ClientConnectionManager.processPacket()  FINEST: Processing packet: from=sess-man@beta.kontalk.net, to=c2s@beta.kontalk.net/178.62.44.19_5222_185.44.151.48_9709, DATA=<message to="f2f7b231c576d88b0498f6c57a1fa89215e1cd6d@beta.kontalk.net" type="chat" id="N8B2PmTI13xS5TfgXZHFnl9da4gYen" from="73253a0c0d884b07d17a8db5a5066c9116ea29f8@beta.kontalk.net/a4772a4356c378d6" xmlns="jabber:client"><body>CData size: 11</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 1204</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/></message>, SIZE=1604, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat

A few milliseconds later:

2015-11-28 18:16:47.879 [in_0-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=c2s@beta.kontalk.net/178.62.44.19_5222_185.44.151.48_9709, to=sess-man@beta.kontalk.net, DATA=<message to="73253a0c0d884b07d17a8db5a5066c9116ea29f8@beta.kontalk.net/a4772a4356c378d6" type="error" id="N8B2PmTI13xS5TfgXZHFnl9da4gYen" from="f2f7b231c576d88b0498f6c57a1fa89215e1cd6d@beta.kontalk.net" xmlns="jabber:client"><body>(encrypted)</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e"> ... , SIZE=1817, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=error

That is writePacketToSocket() returning false and making ClientConnectionManager return an error packet (which is legal, but in this case harmful because the message is not delivered to offline storage, and that should be the correct behaviour IMHO).

But let's get back in the logs.

2015-11-28 18:16:47.858 [in_0-c2s]         ClientConnectionManager.processPacket()  FINE: Sending a command to close the remote session for non-existen c2s connection: from=c2s@beta.kontalk.net/178.62.44.19_5222_185.44.151.48_9709, to=sess-man@beta.kontalk.net, DATA=<iq to="sess-man@beta.kontalk.net" type="set" from="f2f7b231c576d88b0498f6c57a1fa89215e1cd6d@beta.kontalk.net" id="ca4fcd26-285e-4934-bbac-53b9f63dfcf2"><command node="STREAM_CLOSED_UPDATE" xmlns="http://jabber.org/protocol/commands"/></iq>, SIZE=240, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2015-11-28 18:16:47.860 [in_0-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=c2s@beta.kontalk.net/178.62.44.19_5222_185.44.151.48_9709, to=sess-man@beta.kontalk.net, DATA=<iq to="sess-man@beta.kontalk.net" type="set" from="f2f7b231c576d88b0498f6c57a1fa89215e1cd6d@beta.kontalk.net" id="ca4fcd26-285e-4934-bbac-53b9f63dfcf2"><command node="STREAM_CLOSED_UPDATE" xmlns="http://jabber.org/protocol/commands"/></iq>, SIZE=240, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2015-11-28 18:16:47.860 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@beta.kontalk.net
2015-11-28 18:16:47.860 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@beta.kontalk.net
2015-11-28 18:16:47.861 [in_0-message-router]  MessageRouter.processPacket()  FINEST:   1. Packet will be processed by: sess-man@beta.kontalk.net, from=c2s@beta.kontalk.net/178.62.44.19_5222_185.44.151.48_9709, to=sess-man@beta.kontalk.net, DATA=<iq to="sess-man@beta.kontalk.net" type="set" from="f2f7b231c576d88b0498f6c57a1fa89215e1cd6d@beta.kontalk.net" id="ca4fcd26-285e-4934-bbac-53b9f63dfcf2"><command node="STREAM_CLOSED_UPDATE" xmlns="http://jabber.org/protocol/commands"/></iq>, SIZE=240, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2015-11-28 18:16:47.863 [in_12-sess-man]   SessionManager.processPacket()     FINEST:   Received packet: from=c2s@beta.kontalk.net/178.62.44.19_5222_185.44.151.48_9709, to=sess-man@beta.kontalk.net, DATA=<iq to="sess-man@beta.kontalk.net" type="set" from="f2f7b231c576d88b0498f6c57a1fa89215e1cd6d@beta.kontalk.net" id="ca4fcd26-285e-4934-bbac-53b9f63dfcf2"><command node="STREAM_CLOSED_UPDATE" xmlns="http://jabber.org/protocol/commands"/></iq>, SIZE=240, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2015-11-28 18:16:47.863 [in_12-sess-man]   SessionManager.processCommand()    FINER:    STREAM_CLOSED_UPDATE command from: c2s@beta.kontalk.net/178.62.44.19_5222_185.44.151.48_9709
2015-11-28 18:16:47.863 [in_12-sess-man]   SessionManager.processCommand()    FINEST:   STREAM_CLOSED_UPDATE processing comment, connection:  is null
2015-11-28 18:16:47.863 [in_12-sess-man]   SessionManager.processCommand()    FINEST:   STREAM_CLOSED_UPDATE adding to the processor:  is null
2015-11-28 18:16:47.863 [in_12-sess-man]   SessionManager.processCommand()    INFO:     Stream close for the user session which does not exist: from=c2s@beta.kontalk.net/178.62.44.19_5222_185.44.151.48_9709, to=sess-man@beta.kontalk.net, DATA=<iq to="sess-man@beta.kontalk.net" type="set" from="f2f7b231c576d88b0498f6c57a1fa89215e1cd6d@beta.kontalk.net" id="ca4fcd26-285e-4934-bbac-53b9f63dfcf2"><command node="STREAM_CLOSED_UPDATE" xmlns="http://jabber.org/protocol/commands"/></iq>, SIZE=240, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set

Watch the timestamps. As you can see, the connection was lost (read: the server realized it was lost) right after trying to deliver the message, thus generating the error packet.

Added by Andrzej Wójcik IoT 1 CloudTigaseTeam over 3 years ago

I checked and found that this error may be generated as result of C2S not being able to find connection or connection being dropped at this moment. However in case of connection being dropped at this time message should be delivered to offline store.

I have few questions:

  • do you have StreamManagement enabled?

  • which version of Tigase XMPP Server do you use?

  • could you provided logs from time when this issue occurs for more detailed analysis?

I created new issue #3781 for investigation of this issue.

Added by Andrzej Wójcik IoT 1 CloudTigaseTeam over 3 years ago

It looks that my fix is working fine, please check with new version from release branch.

I'm still waiting on answer on my questions I asked in previous post.

Added by Daniele Ricci over 3 years ago

Andrzej Wójcik wrote:

I have few questions:

  • do you have StreamManagement enabled?

Yes, clients use it with resume disabled.

  • which version of Tigase XMPP Server do you use?

Directly from release branch at commit e1082df8febdfb7b95dae73f1c9cce1b378ec18a (2015-12-02).

  • could you provided logs from time when this issue occurs for more detailed analysis?

I still have the logs of that episode, I can prepare an archive for you but since there might be sensitive information I want to use another channel.

What about email?

I created new issue #3781 for investigation of this issue.

I will merge and test it as soon as I can.

    (1-9/9)