Message sender is changed to the recipient (#598)

Daniele Ricci opened 10 years ago

Due Date
2015-12-02

I have a strange issue reported by a few users and I'm trying to find proof on the server logs.

I wrote a custom OfflineMessages module which is quite similar to the Tigase one [1] which does not alter the from attribute ever. Code is 90% copied from yours and it adds message expiration + a custom database repository.

Message IDs are unique (generated by clients), I'll examine a message with ID 50HeViNirO5Cp57PqRC47Eld7z7AG4 for this bug report.

That message has been apparently delivered with the sender being the recipient of the message. I can see the original (right) message reported by the OfflineMessages module after a storage loop (that is, failed to deliver because of broken connection client, then stored and then failed again: the delay element is detected by the OfflineMessages module and it doesn't add another one):

2015-11-11 08:39:14.717 [in_8-sess-man]    OfflineMessages.savePacketForOffLineUser()  WARNING: Restoring packet, possible offline storage loop? from=sess-man@beta.kontalk.net, to=sess-man@beta.kontalk.net, DATA=<message xmlns="jabber:client" from="e77aa2d04b00be2002badacf9a176d31373c42e4@beta.kontalk.net/91c86d2c35575f42" type="chat" to="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net" id="50HeViNirO5Cp57PqRC47Eld7z7AG4"><body>(verschlüsselt)</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">hH4D3iUI3jK+OqcSAgME6kb5y8OuMaof7krPgHjC2Mw9YYizsYF/5J51ud1x6SZB3u3RyHHHfUDhOfmalfVTz8cx+Hk+I0whS54xcy5mtzAqgPP2ve9cQcZHFXpuLv2dThUNc5xDpQ3lm6hr4bPAatu92vKVxzrGj5b+N7zGWozS6AGxgl1edAJNja81BmZgmS2ezvq3Nz+ToietHEhvRHBcW61bClOV3ltf5hUQgK4nLMZ8yviZuf/G+YXi5RLta91Ak0yVvJsyKgn2rvPVhWmx+el/aazA2NWFdZfAiapiQ58WSrybkv7mAZUP0doXQ87QIW9JTZ9yiNDK2cITyq2RhE6OD/MPsFntxVys4C4dURx/KgDF5BywYuE3/tKx2l+jx5E/2gKuTwAgwDyI+7o3r0SMwNCHPbC56+hIowmUpeUW7OV61ss7ZSIvZsq1LlY4GJWsmbx4knGy7hsv+005SlDnU0LVZNFDPSbAKLVB1471qsKy6VlghWQj00BYXki2OaUFFqDrOpRlVx2qFtqRJfILMMAOg353SiGKZOmQTxV09vJhJ1R9P9vIH6LMEyvQucSbO1HQT8cS154V+sESG1iJp0G9ygcum+twbrQDDFi0OrJ+iFTjaqG+FAW4voDcW4jTd0HYVcuk7BHzEyqayMXBGAilPCxxc0u8zwX6wE6McQPUFNEOrU7m80/+IAaJPKtOTbrkqTywz3Wg/MG ... , SIZE=1164, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat

As you can see, sender is e77aa2d04b00be2002badacf9a176d31373c42e4@beta.kontalk.net/91c86d2c35575f42,

recipient is 2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net.

20 minutes later, another log appears:

2015-11-11 08:59:29.221 [in_8-sess-man]    SessionManager.processPacket()     FINEST:   Received packet: from=sess-man@beta.kontalk.net, to=null, DATA=<message from="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net/70476da0cb463300" id="50HeViNirO5Cp57PqRC47Eld7z7AG4" type="chat" xmlns="jabber:client" to="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net"><body>CData size: 15</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 760</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay from="beta.kontalk.net" xmlns="urn:xmpp:delay" stamp="2015-11-11T08:39:14.717Z">CData size: 34</delay></message>, SIZE=1293, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat
2015-11-11 08:59:29.221 [in_8-sess-man]    SessionManager.processPacket()     FINEST:   processing packet: from=sess-man@beta.kontalk.net, to=sess-man@beta.kontalk.net, DATA=<message from="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net/70476da0cb463300" id="50HeViNirO5Cp57PqRC47Eld7z7AG4" type="chat" xmlns="jabber:client" to="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net"><body>CData size: 15</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 760</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay from="beta.kontalk.net" xmlns="urn:xmpp:delay" stamp="2015-11-11T08:39:14.717Z">CData size: 34</delay></message>, SIZE=1293, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat, connection: null
2015-11-11 08:59:31.709 [in_8-sess-man]    SessionManager.processPacket()     FINEST:   Received packet: from=sess-man@beta.kontalk.net, to=null, DATA=<message from="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net/70476da0cb463300" to="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net" type="chat" id="50HeViNirO5Cp57PqRC47Eld7z7AG4" xmlns="jabber:client"><body>CData size: 15</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 760</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay from="beta.kontalk.net" xmlns="urn:xmpp:delay" stamp="2015-11-11T08:39:14.717Z">CData size: 34</delay></message>, SIZE=1293, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat
2015-11-11 08:59:31.710 [in_8-sess-man]    SessionManager.processPacket()     FINEST:   processing packet: from=sess-man@beta.kontalk.net, to=sess-man@beta.kontalk.net, DATA=<message from="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net/70476da0cb463300" to="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net" type="chat" id="50HeViNirO5Cp57PqRC47Eld7z7AG4" xmlns="jabber:client"><body>CData size: 15</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 760</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay from="beta.kontalk.net" xmlns="urn:xmpp:delay" stamp="2015-11-11T08:39:14.717Z">CData size: 34</delay></message>, SIZE=1293, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat, connection: XMPPResourceConnection=[user_jid=2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net/70476da0cb463300, packets=8, connectioId=c2s@beta.kontalk.net/178.62.44.19_5222_37.201.230.55_40508, domain=beta.kontalk.net, authState=AUTHORIZED, isAnon=false, isTmp=false]
2015-11-11 08:59:31.716 [in_8-sess-man]    SessionManager.processPacket()     FINEST:   Received packet: from=sess-man@beta.kontalk.net, to=null, DATA=<message from="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net/70476da0cb463300" to="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net" type="chat" id="50HeViNirO5Cp57PqRC47Eld7z7AG4" xmlns="jabber:client"><body>CData size: 15</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 760</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay from="beta.kontalk.net" xmlns="urn:xmpp:delay" stamp="2015-11-11T08:39:14.717Z">CData size: 34</delay></message>, SIZE=1293, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat
2015-11-11 08:59:31.717 [in_8-sess-man]    SessionManager.processPacket()     FINEST:   processing packet: from=sess-man@beta.kontalk.net, to=sess-man@beta.kontalk.net, DATA=<message from="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net/70476da0cb463300" to="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net" type="chat" id="50HeViNirO5Cp57PqRC47Eld7z7AG4" xmlns="jabber:client"><body>CData size: 15</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 760</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay from="beta.kontalk.net" xmlns="urn:xmpp:delay" stamp="2015-11-11T08:39:14.717Z">CData size: 34</delay></message>, SIZE=1293, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat, connection: XMPPResourceConnection=[user_jid=2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net/70476da0cb463300, packets=9, connectioId=c2s@beta.kontalk.net/178.62.44.19_5222_37.201.230.55_40508, domain=beta.kontalk.net, authState=AUTHORIZED, isAnon=false, isTmp=false]
2015-11-11 08:59:31.719 [in_1-c2s]         ClientConnectionManager.processPacket()  FINEST: Processing packet: from=sess-man@beta.kontalk.net, to=c2s@beta.kontalk.net/178.62.44.19_5222_37.201.230.55_40508, DATA=<message from="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net/70476da0cb463300" to="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net" type="chat" id="50HeViNirO5Cp57PqRC47Eld7z7AG4" xmlns="jabber:client"><body>CData size: 15</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 760</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay from="beta.kontalk.net" xmlns="urn:xmpp:delay" stamp="2015-11-11T08:39:14.717Z">CData size: 34</delay></message>, SIZE=1293, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat
2015-11-11 08:59:31.753 [in_1-c2s]         ClientConnectionManager.processPacket()  FINEST: Processing packet: from=sess-man@beta.kontalk.net, to=c2s@beta.kontalk.net/178.62.44.19_5222_37.201.230.55_40508, DATA=<message from="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net/70476da0cb463300" to="2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net" type="chat" id="50HeViNirO5Cp57PqRC47Eld7z7AG4" xmlns="jabber:client"><body>CData size: 15</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 760</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay from="beta.kontalk.net" xmlns="urn:xmpp:delay" stamp="2015-11-11T08:39:14.717Z">CData size: 34</delay></message>, SIZE=1293, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat

The message comes from 20 minutes before (as of the delay element), but the sender has changed.

Inspecting Tigase's Message module, I can see only one point where the from might be changed [2] (release branch).

I've recently removed my custom message delivery code because you've done some modifications to improve that so I didn't need my custom code anymore. The only custom thing concerning messages is the OfflineMessages module.

Thanks for the help. If you need anything to debug this just ask. I will continue my log analysis in the meantime and keep you updated on my latest findings.

[1] https://github.com/kontalk/tigase-extension/blob/master/src/main/java/org/kontalk/xmppserver/messages/OfflineMessages.java

[2] https://projects.tigase.org/projects/tigase-server/repository/revisions/release/entry/src/main/java/tigase/xmpp/impl/Message.java#L187

Activities

Andrzej Wójcik (Tigase) commented 10 years ago
From provided logs I cannot tell what caused this issue, however I'm sure that [2] is not responsible for this issue as there is a call to setPacketFrom which only sets internal address of packet without setting or changing from attribute of stanza. So this is not responsible for this issue.

However I see a few things which look a little weird:

same packet is processed 3 times by sess-man and always packetFrom is null which looks like this packet was loaded from repository 3 times - this may not be causing issue but looks suspicious.

first processing of packet "after 20 min" is with packetFrom set to null and there is no session@, see: @TYPE=chat, connection: null - when packet is loaded from offline store it should be already a XMPPResourceConnection (session) which loaded this packet

One more thing - this "new" from attribute of element is not copied from to attribute of original message stanza but is set from JID of new connection as this is full JID with resource part - 2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net/70476da0cb463300
Daniele Ricci commented 10 years ago
Andrzej Wójcik wrote:

same packet is processed 3 times by sess-man and always packetFrom is null which looks like this packet was loaded from repository 3 times - this may not be causing issue but looks suspicious.

That's because the delivery failed 3 times (it can happen very often with mobile connections) and the message got back into offline storage.

first processing of packet "after 20 min" is with packetFrom set to null and there is no session@, see: @TYPE=chat, connection: null - when packet is loaded from offline store it should be already a XMPPResourceConnection (session) which loaded this packet

I'm sorry I didn't explain: although it says "Restoring packet", that log is from the savePacketForOfflineUser method [1], so it is going to offline storage again (I know it's going again because of the presence of the delay element which was injected the first time the message was stored, see from #L361).

One more thing - this "new" from attribute of element is not copied from to attribute of original message stanza but is set from JID of new connection as this is full JID with resource part - 2aa60150c7cacc53568e5923b1f365d6661acc65@beta.kontalk.net/70476da0cb463300

Indeed. You gave me some hints to do some more research on this. I'll get back to you. If anything pops into your mind in the meantime please share.

[1] https://github.com/kontalk/tigase-extension/blob/master/src/main/java/org/kontalk/xmppserver/messages/OfflineMessages.java#L363

Daniele Ricci commented 10 years ago

I think I got it.

2015-11-12 09:54:18.044 [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_83.43.19.100_42823, to=sess-man@beta.kontalk.net, DATA=<message xmlns="jabber:client" type="chat" to="476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net" id="b3V73UXC8H8i1VoupC67KlPMpI624p"><body>(cifrado)</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">hH4D3gAqhpvIqQISAgMEBBOyV4TtW9A+6QC6M/c/sR6UXGaao1fK+bjAndHt6WgZjNmMMMirKtSRy0a4Z64gQ9SuLHRllNvIm/OdExdP6jBwCiUpVLLXF8Kh3+R3wiYkL9LSsXG1TB+k45tdJwgkfdKG7s/0rMcrXRpLafC0fOzS6AEm/imYX017Zohc+75Z4ziHHhGpEcXQM0o/Z2OpmO6Ce7gg0FsvGDvcTglGD0k1lS4K9lS+SPuRF9JFXZa6qv5AGltD25zP1azf+Gq6oZDMyEUb7IZzoekwMke6U7C0mQz+WynfHLvOf9QRiuD5pMxm9m5KqhipVkP3v43Stmreoeg7+O/SEUSnIuh3ZekIx99d+D8Ql4If0JZUI5P/nT7582SgIpem2IW/GHhdxrg4k6AoNqnjSmZ9QQHQpKinApQNB8uP/3CeQx0WQoJMgTEyncP84HAy9bsv7/kAAessK6n/CWcruRx+okGLCh7LCQ4U1H37ek4OwNvTsj926OFb2tyFq9NXd+ldkQ3h5aGczr8n2GRQxXnUbxwJItPxwfUMFX8whjxB9fIXfRN/g4AeQaHE+RnDnCdFL554nWCSoFhy6xNhWg/EXikfTl8RWabTIidPed0qqG130Q==</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/></message>, SIZE=956, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat
2015-11-12 09:54:18.044 [in_4-sess-man]    SessionManager.processPacket()     FINEST:   Received packet: from=c2s@beta.kontalk.net/178.62.44.19_5222_83.43.19.100_42823, to=sess-man@beta.kontalk.net, DATA=<message xmlns="jabber:client" type="chat" to="476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net" id="b3V73UXC8H8i1VoupC67KlPMpI624p"><body>CData size: 9</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 640</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/></message>, SIZE=956, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat
2015-11-12 09:54:18.044 [in_4-sess-man]    SessionManager.processPacket()     FINEST:   processing packet: from=c2s@beta.kontalk.net/178.62.44.19_5222_83.43.19.100_42823, to=sess-man@beta.kontalk.net, DATA=<message xmlns="jabber:client" type="chat" to="476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net" id="b3V73UXC8H8i1VoupC67KlPMpI624p"><body>CData size: 9</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 640</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/></message>, SIZE=956, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat, connection: XMPPResourceConnection=[user_jid=476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net/4e397f25420672da, packets=20, connectioId=c2s@beta.kontalk.net/178.62.44.19_5222_83.43.19.100_42823, domain=beta.kontalk.net, authState=AUTHORIZED, isAnon=false, isTmp=false]
2015-11-12 09:54:18.044 [in_4-sess-man]    StartTLS.preProcess()              FINEST:   VHost: Domain: beta.kontalk.net, enabled: true, anonym: false, register: true, maxusers: 0, tls: false, s2sSecret: e8349573-6a2d-4484-b33d-bf573c77fe59, domainFilter: ALL, domainFilterDomains: null, c2sPortsAllowed: null, saslAllowedMechanisms: null
2015-11-12 09:54:18.045 [in_4-sess-man]    BindResource.preProcess()          FINEST:   Setting correct from attribute: 476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net/4e397f25420672da
2015-11-12 09:54:18.045 [in_4-sess-man]    DomainFilter.preProcess()          FINEST:   Processing: from=c2s@beta.kontalk.net/178.62.44.19_5222_83.43.19.100_42823, to=sess-man@beta.kontalk.net, DATA=<message xmlns="jabber:client" from="476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net/4e397f25420672da" type="chat" to="476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net" id="b3V73UXC8H8i1VoupC67KlPMpI624p"><body>(cifrado)</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">hH4D3gAqhpvIqQISAgMEBBOyV4TtW9A+6QC6M/c/sR6UXGaao1fK+bjAndHt6WgZjNmMMMirKtSRy0a4Z64gQ9SuLHRllNvIm/OdExdP6jBwCiUpVLLXF8Kh3+R3wiYkL9LSsXG1TB+k45tdJwgkfdKG7s/0rMcrXRpLafC0fOzS6AEm/imYX017Zohc+75Z4ziHHhGpEcXQM0o/Z2OpmO6Ce7gg0FsvGDvcTglGD0k1lS4K9lS+SPuRF9JFXZa6qv5AGltD25zP1azf+Gq6oZDMyEUb7IZzoekwMke6U7C0mQz+WynfHLvOf9QRiuD5pMxm9m5KqhipVkP3v43Stmreoeg7+O/SEUSnIuh3ZekIx99d+D8Ql4If0JZUI5P/nT7582SgIpem2IW/GHhdxrg4k6AoNqnjSmZ9QQHQpKinApQNB8uP/3CeQx0WQoJMgTEyncP84HAy9bsv7/kAAessK6n/CWcruRx+okGLCh7LCQ4U1H37ek4OwNvTsj926OFb2tyFq9NXd+ldkQ3h5aGczr8n2GRQxXnUbxwJItPxwfUMFX8whjxB9fIXfRN/g4AeQaHE+RnDnCdFL554nWCSoFhy6xNhWg/EXikfTl8RWabTIidPed0qqG130Q==</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipt ... , SIZE=1038, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat

The first line in the log shows the message stanza as coming from the sender, so without a from attribute.

But then there is this line:

2015-11-12 09:54:18.045 [in_4-sess-man]    BindResource.preProcess()          FINEST:   Setting correct from attribute: 476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net/4e397f25420672da

The line after that shows the message having the from attribute just that value. I don't think it's a coincidence.

I guess something weird happens if the recipient is still logging in while delivering the message.

Am I getting this right?

Wojciech Kapcia (Tigase) commented 10 years ago

This code should be run only on the established, authorised sessions, for packets that were send by the user of that session (i.e. incoming packets) in order to be in line with specification witch enforces that all packets should have correct from set.

From that excerpt it looks like the user sent the packet to it's on BareJID.

Daniele Ricci commented 10 years ago

Ok, just to give you a wider view:

2015-11-12 09:54:18.042 [pool-11-thread-1]  ClientConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<message type="chat" to="476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net" id="b3V73UXC8H8i1VoupC67KlPMpI624p"><body>CData size: 9</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 640</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/></message>, SIZE=934, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat from connection: c2s@beta.kontalk.net/178.62.44.19_5222_83.43.19.100_42823
2015-11-12 09:54:18.043 [pool-11-thread-1]  ClientConnectionManager.processSocketData()  FINEST: XMLNS set for packet: from=null, to=null, DATA=<message xmlns="jabber:client" type="chat" to="476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net" id="b3V73UXC8H8i1VoupC67KlPMpI624p"><body>CData size: 9</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 640</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/></message>, SIZE=956, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat from connection: c2s@beta.kontalk.net/178.62.44.19_5222_83.43.19.100_42823
2015-11-12 09:54:18.043 [in_0-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=c2s@beta.kontalk.net/178.62.44.19_5222_83.43.19.100_42823, to=sess-man@beta.kontalk.net, DATA=<message xmlns="jabber:client" type="chat" to="476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net" id="b3V73UXC8H8i1VoupC67KlPMpI624p"><body>(cifrado)</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">hH4D3gAqhpvIqQISAgMEBBOyV4TtW9A+6QC6M/c/sR6UXGaao1fK+bjAndHt6WgZjNmMMMirKtSRy0a4Z64gQ9SuLHRllNvIm/OdExdP6jBwCiUpVLLXF8Kh3+R3wiYkL9LSsXG1TB+k45tdJwgkfdKG7s/0rMcrXRpLafC0fOzS6AEm/imYX017Zohc+75Z4ziHHhGpEcXQM0o/Z2OpmO6Ce7gg0FsvGDvcTglGD0k1lS4K9lS+SPuRF9JFXZa6qv5AGltD25zP1azf+Gq6oZDMyEUb7IZzoekwMke6U7C0mQz+WynfHLvOf9QRiuD5pMxm9m5KqhipVkP3v43Stmreoeg7+O/SEUSnIuh3ZekIx99d+D8Ql4If0JZUI5P/nT7582SgIpem2IW/GHhdxrg4k6AoNqnjSmZ9QQHQpKinApQNB8uP/3CeQx0WQoJMgTEyncP84HAy9bsv7/kAAessK6n/CWcruRx+okGLCh7LCQ4U1H37ek4OwNvTsj926OFb2tyFq9NXd+ldkQ3h5aGczr8n2GRQxXnUbxwJItPxwfUMFX8whjxB9fIXfRN/g4AeQaHE+RnDnCdFL554nWCSoFhy6xNhWg/EXikfTl8RWabTIidPed0qqG130Q==</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/></message>, SIZE=956, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat
2015-11-12 09:54:18.043 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : 476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net
2015-11-12 09:54:18.043 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: No componentID matches (fast lookup against exact address): 476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net, for map: [network@beta.kontalk.net, probe@beta.kontalk.net, push@beta.kontalk.net, s2s@beta.kontalk.net, c2s@beta.kontalk.net, stats@beta.kontalk.net, upload@beta.kontalk.net, vhost-man@beta.kontalk.net, sess-man@beta.kontalk.net, monitor@beta.kontalk.net, basic-conf@beta.kontalk.net]; trying VHost lookup
2015-11-12 09:54:18.043 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: No component name matches (VHost lookup against component name): 476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net, for map: [vhost-man, c2s, upload, monitor, push, network, probe, s2s, stats, basic-conf, sess-man, message-router], for all VHosts: [beta.kontalk.net]; trying other forms of addressing
2015-11-12 09:54:18.044 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Component match failed: 476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net, for comp: [vhost-man, c2s, upload, monitor, push, network, probe, s2s, stats, basic-conf, sess-man, message-router], basename: kontalk.net
2015-11-12 09:54:18.044 [in_0-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@beta.kontalk.net
2015-11-12 09:54:18.044 [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_83.43.19.100_42823, to=sess-man@beta.kontalk.net, DATA=<message xmlns="jabber:client" type="chat" to="476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net" id="b3V73UXC8H8i1VoupC67KlPMpI624p"><body>(cifrado)</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">hH4D3gAqhpvIqQISAgMEBBOyV4TtW9A+6QC6M/c/sR6UXGaao1fK+bjAndHt6WgZjNmMMMirKtSRy0a4Z64gQ9SuLHRllNvIm/OdExdP6jBwCiUpVLLXF8Kh3+R3wiYkL9LSsXG1TB+k45tdJwgkfdKG7s/0rMcrXRpLafC0fOzS6AEm/imYX017Zohc+75Z4ziHHhGpEcXQM0o/Z2OpmO6Ce7gg0FsvGDvcTglGD0k1lS4K9lS+SPuRF9JFXZa6qv5AGltD25zP1azf+Gq6oZDMyEUb7IZzoekwMke6U7C0mQz+WynfHLvOf9QRiuD5pMxm9m5KqhipVkP3v43Stmreoeg7+O/SEUSnIuh3ZekIx99d+D8Ql4If0JZUI5P/nT7582SgIpem2IW/GHhdxrg4k6AoNqnjSmZ9QQHQpKinApQNB8uP/3CeQx0WQoJMgTEyncP84HAy9bsv7/kAAessK6n/CWcruRx+okGLCh7LCQ4U1H37ek4OwNvTsj926OFb2tyFq9NXd+ldkQ3h5aGczr8n2GRQxXnUbxwJItPxwfUMFX8whjxB9fIXfRN/g4AeQaHE+RnDnCdFL554nWCSoFhy6xNhWg/EXikfTl8RWabTIidPed0qqG130Q==</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/></message>, SIZE=956, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat
2015-11-12 09:54:18.044 [in_4-sess-man]    SessionManager.processPacket()     FINEST:   Received packet: from=c2s@beta.kontalk.net/178.62.44.19_5222_83.43.19.100_42823, to=sess-man@beta.kontalk.net, DATA=<message xmlns="jabber:client" type="chat" to="476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net" id="b3V73UXC8H8i1VoupC67KlPMpI624p"><body>CData size: 9</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 640</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/></message>, SIZE=956, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat
2015-11-12 09:54:18.044 [in_4-sess-man]    SessionManager.processPacket()     FINEST:   processing packet: from=c2s@beta.kontalk.net/178.62.44.19_5222_83.43.19.100_42823, to=sess-man@beta.kontalk.net, DATA=<message xmlns="jabber:client" type="chat" to="476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net" id="b3V73UXC8H8i1VoupC67KlPMpI624p"><body>CData size: 9</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 640</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/></message>, SIZE=956, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat, connection: XMPPResourceConnection=[user_jid=476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net/4e397f25420672da, packets=20, connectioId=c2s@beta.kontalk.net/178.62.44.19_5222_83.43.19.100_42823, domain=beta.kontalk.net, authState=AUTHORIZED, isAnon=false, isTmp=false]
2015-11-12 09:54:18.044 [in_4-sess-man]    StartTLS.preProcess()              FINEST:   VHost: Domain: beta.kontalk.net, enabled: true, anonym: false, register: true, maxusers: 0, tls: false, s2sSecret: e8349573-6a2d-4484-b33d-bf573c77fe59, domainFilter: ALL, domainFilterDomains: null, c2sPortsAllowed: null, saslAllowedMechanisms: null
2015-11-12 09:54:18.045 [in_4-sess-man]    BindResource.preProcess()          FINEST:   Setting correct from attribute: 476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net/4e397f25420672da
2015-11-12 09:54:18.045 [in_4-sess-man]    DomainFilter.preProcess()          FINEST:   Processing: from=c2s@beta.kontalk.net/178.62.44.19_5222_83.43.19.100_42823, to=sess-man@beta.kontalk.net, DATA=<message xmlns="jabber:client" from="476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net/4e397f25420672da" type="chat" to="476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net" id="b3V73UXC8H8i1VoupC67KlPMpI624p"><body>(cifrado)</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">hH4D3gAqhpvIqQISAgMEBBOyV4TtW9A+6QC6M/c/sR6UXGaao1fK+bjAndHt6WgZjNmMMMirKtSRy0a4Z64gQ9SuLHRllNvIm/OdExdP6jBwCiUpVLLXF8Kh3+R3wiYkL9LSsXG1TB+k45tdJwgkfdKG7s/0rMcrXRpLafC0fOzS6AEm/imYX017Zohc+75Z4ziHHhGpEcXQM0o/Z2OpmO6Ce7gg0FsvGDvcTglGD0k1lS4K9lS+SPuRF9JFXZa6qv5AGltD25zP1azf+Gq6oZDMyEUb7IZzoekwMke6U7C0mQz+WynfHLvOf9QRiuD5pMxm9m5KqhipVkP3v43Stmreoeg7+O/SEUSnIuh3ZekIx99d+D8Ql4If0JZUI5P/nT7582SgIpem2IW/GHhdxrg4k6AoNqnjSmZ9QQHQpKinApQNB8uP/3CeQx0WQoJMgTEyncP84HAy9bsv7/kAAessK6n/CWcruRx+okGLCh7LCQ4U1H37ek4OwNvTsj926OFb2tyFq9NXd+ldkQ3h5aGczr8n2GRQxXnUbxwJItPxwfUMFX8whjxB9fIXfRN/g4AeQaHE+RnDnCdFL554nWCSoFhy6xNhWg/EXikfTl8RWabTIidPed0qqG130Q==</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipt ... , SIZE=1038, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat

Let's analyze it together (correct me if I'm wrong)

At line 1 the packet comes in from the sender client socket
Line 2 sets the correct XMLNS to jabber:client
At line 3 packetFrom is set with the connection ID of the sender and packetTo is set to sess-man (stanza from is still not set)
At lines 9, 10 and 11 the SessionManager begins to process the packet (still no sign of the stanza from attribute - shouldn't it had been set at this point?)
At line 12 StartTLS module comes in and logs a call to preProcess
At line 13 BindResource sets the stanza from to the current session JID (which is still the sender session right? packetFrom hasn't changed yet)
What happened here?

Wojciech Kapcia (Tigase) commented 10 years ago
Daniele Ricci wrote:

Ok, just to give you a wider view:

Let's analyze it together (correct me if I'm wrong)

Ok :-)

At line 1 the packet comes in from the sender client socket

Correct

Line 2 sets the correct XMLNS to jabber:client

Correct

At line 3 packetFrom is set with the connection ID of the sender and packetTo is set to sess-man (stanza from is still not set)

Correct

At lines 9, 10 and 11 the SessionManager begins to process the packet (still no sign of the stanza from attribute - shouldn't it had been set at this point?)

No, those are entries from the SessionManager component itself - it performs some processing before calling the plugins. And after that plugins are executed in the documented way (all preProcessors, then processors for registered types, then postProcessors if there wasn't any processor for the given stanza, then filters)

At line 12 StartTLS module comes in and logs a call to preProces

Correct, all preProcessors are executed.

At line 13 BindResource sets the stanza from to the current session JID (which is still the sender session right? packetFrom hasn't changed yet)

This is correct; The packet came from the user 476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net which established connection under 4e397f25420672da resource. If you could check rest of the logs for the entries with fullJID 476e700b78af828bdd53df8c2497c73ec80f473c@beta.kontalk.net/4e397f25420672da and the CID c2s@beta.kontalk.net/178.62.44.19_5222_83.43.19.100_42823 you should see the association.

What happened here?

Well, everything seems in order. Main question is - are you sure you are logging in with the different JID for this account??
Daniele Ricci commented 10 years ago

Wojciech Kapcia wrote:

Well, everything seems in order. Main question is - are you sure you are logging in with the different JID for this account??

I'm quite sure yes :)

It just happened again with a friend, I'm analyzing the logs. I might know what is happening.
Wojciech Kapcia (Tigase) commented 10 years ago

If you find the root-cause please share, especially if it's a bug in Tigase.
Daniele Ricci commented 10 years ago

I thought the issue was fixed by this:

https://github.com/kontalk/tigase-extension/commit/68a378062b89947cb7ddb903a03b77a3a7822afe

and it actually made sense, but I've received a report just yesterday of this issue happening again.

Unfortunately, the user reported the issue too late for the logs to be still there (they rotated - I've activated almost maximum verbosity to debug this so they grow very quickly).

I'll keep you posted.

Daniele Ricci commented 10 years ago

I got another case (among many, I'll take one as example as I've already inspected two more, they happen in the same situation).

Sender: e893c4e88ccd497d019cf0391b12065f65a6bc1c@beta.kontalk.net

Recipient: 301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net

This is the case story.

The recipient got his message, but it can't ack it (Session Mngt) because he loses his connection. At this time, probably the connection was already broken, but the server still doesn't realize that.

2015-11-26 13:06:13.566 [in_3-c2s]         ConnectionManager.writePacketToSocket()  FINEST: c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, type: accept, Socket: ZLIB: TLS: c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788 Socket[addr=/176.83.204.136,port=56788,localport=5222], jid: 301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net/1e6565933f887add, Writing packet: from=sess-man@beta.kontalk.net, to=c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, DATA=<message to="301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net" type="chat" id="Nxfighae8M83SgmHsFtkYFwPCKsU6B" from="e893c4e88ccd497d019cf0391b12065f65a6bc1c@beta.kontalk.net/237877240a4e1575" xmlns="jabber:client"><body>(cifrado)</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">hQEMA1ZSzqhr9kXbAQgAiVC/I09yJwYElxQbr0UOrfHIEpypiWa0bQlODH60B5NzHeYH92t7WzrjfNTNze7XHvaa6tNdH2sJJrA2k/4rxlgg/LTDmVs6/hNMPS6fT8J5WAr78CF+6zyjRTGQTc0nmECIHuy5sciMyYp/WDQhhRmOpU8TPEaY0TjPILe336Ay3m75wnRy4/s+ykp4FyZVAxETZlSBQIYOQBEa5q+qEkjTEcUDme0S30SoY5Z/dFeF/g34Y/7caEuFVPSyxR3GxeGWvlcLnMOHoRdOaWGnXYRTrE55Vpw4gffVknFlUOEcgCH6Z0MX3htcLTcXo1988IsC/AV6yHhUHZXnw6VpQdLoATO04dKrIZaAG9S1752VmmZPjycAJZElT2PadpRpZOvJfrv3JslDaGsxCJh/27+QQcwROE2Dm4CdEkf3eoXHwwDKjMJc6uFe+cqauE7nt87bmgjgZmTv/tAIw+NUdzwYMLU5NtLQ0h3iylsiFvOBkkFex3f8Qc442WxT7OUJCpE+uR/0Vz0wAo+tZ0ITbUC9kv5BNr6Y+VtjNrRm1lc9CHlj1Af0haqw3Y8s41Sgq45kGQ6bwdYG1sXOw+iofPhCf8ANRbrNd0w3VAqRttKBx10F0YjpYPXxZhPAnqUwHfvT+9ipnYw2Mo7gEXwQ3gPtT92SsozBNZ3Mk4kxTWlS7+jfPN4KeA/xkpqo5xjQ4z1R6KSEC ... , SIZE=1586, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat

And here is the server finally realizing the connection is broken:

2015-11-26 13:06:13.777 [pool-11-thread-1]  StreamManagementIOProcessor.serviceStopped()  FINEST: c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, type: accept, Socket: ZLIB: TLS: c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788 Socket[addr=/176.83.204.136,port=56788,localport=5222], jid: 301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net/1e6565933f887add, service stopped - resumption disabled, sending unacked packets
2015-11-26 13:06:13.777 [pool-11-thread-1]  ConnectionManager.serviceStopped()  FINER:  [[c2s]] Connection stopped: c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, type: accept, Socket: ZLIB: TLS: c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788 Socket[addr=/176.83.204.136,port=56788,localport=5222], jid: 301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net/1e6565933f887add
2015-11-26 13:06:13.777 [pool-11-thread-1]  ClientConnectionManager.xmppStreamClosed()  FINER: Stream closed: c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788
2015-11-26 13:06:13.777 [pool-11-thread-1]  ClientConnectionManager.xmppStreamClosed()  FINE: Service stopped, sending packet: from=c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, to=sess-man@beta.kontalk.net, DATA=<iq to="sess-man@beta.kontalk.net" type="set" from="c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788" id="9675c04a-55e1-4c0b-ba71-128f4459ae9f"><command node="STREAM_CLOSED" xmlns="http://jabber.org/protocol/commands"><x type="submit" xmlns="jabber:x:data"><field var="user-jid"><value>301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net/1e6565933f887add</value></field></x></command></iq>, SIZE=406, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2015-11-26 13:06:13.777 [pool-11-thread-1]  StreamManagementIOProcessor.serviceStopped()  FINEST: c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, type: accept, Socket: ZLIB: TLS: c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788 Socket[addr=/176.83.204.136,port=56788,localport=5222], jid: 301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net/1e6565933f887add, service stopped - resumption disabled, sending unacked packets
2015-11-26 13:06:13.777 [pool-11-thread-1]  ConnectionManager.serviceStopped()  FINER:  [[c2s]] Connection stopped: c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, type: accept, Socket: ZLIB: TLS: c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788 Socket[addr=/176.83.204.136,port=56788,localport=5222], jid: 301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net/1e6565933f887add
2015-11-26 13:06:13.777 [pool-11-thread-1]  ConnectionManager.serviceStopped()  FINER:  [[c2s]] Attempt to stop incorrect service: c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, type: accept, Socket: ZLIB: TLS: c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788 Socket[addr=/176.83.204.136,port=56788,localport=5222], jid: 301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net/1e6565933f887add
2015-11-26 13:06:13.777 [pool-11-thread-1]  ClientConnectionManager.xmppStreamClosed()  FINER: Stream closed: c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788
2015-11-26 13:06:13.778 [in_3-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, to=sess-man@beta.kontalk.net, DATA=<iq to="sess-man@beta.kontalk.net" type="set" from="c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788" id="9675c04a-55e1-4c0b-ba71-128f4459ae9f"><command node="STREAM_CLOSED" xmlns="http://jabber.org/protocol/commands"><x type="submit" xmlns="jabber:x:data"><field var="user-jid"><value>301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net/1e6565933f887add</value></field></x></command></iq>, SIZE=406, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set

At this step I don't understand why this log is printed twice: "service stopped - resumption disabled, sending unacked packets". But let's continue for now.

The message is routed again (this time by StreamManagementIOProcessor handling the unacked packets). I can't see the whole stanza, but a few log lines later I will see this packet has the delivery-error tag (injected by ClientConnectionManager).

2015-11-26 13:06:13.778 [in_3-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, to=null, DATA=<message to="301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net" type="chat" id="Nxfighae8M83SgmHsFtkYFwPCKsU6B" from="e893c4e88ccd497d019cf0391b12065f65a6bc1c@beta.kontalk.net/237877240a4e1575" xmlns="jabber:client"><body>(cifrado)</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">hQEMA1ZSzqhr9kXbAQgAiVC/I09yJwYElxQbr0UOrfHIEpypiWa0bQlODH60B5NzHeYH92t7WzrjfNTNze7XHvaa6tNdH2sJJrA2k/4rxlgg/LTDmVs6/hNMPS6fT8J5WAr78CF+6zyjRTGQTc0nmECIHuy5sciMyYp/WDQhhRmOpU8TPEaY0TjPILe336Ay3m75wnRy4/s+ykp4FyZVAxETZlSBQIYOQBEa5q+qEkjTEcUDme0S30SoY5Z/dFeF/g34Y/7caEuFVPSyxR3GxeGWvlcLnMOHoRdOaWGnXYRTrE55Vpw4gffVknFlUOEcgCH6Z0MX3htcLTcXo1988IsC/AV6yHhUHZXnw6VpQdLoATO04dKrIZaAG9S1752VmmZPjycAJZElT2PadpRpZOvJfrv3JslDaGsxCJh/27+QQcwROE2Dm4CdEkf3eoXHwwDKjMJc6uFe+cqauE7nt87bmgjgZmTv/tAIw+NUdzwYMLU5NtLQ0h3iylsiFvOBkkFex3f8Qc442WxT7OUJCpE+uR/0Vz0wAo+tZ0ITbUC9kv5BNr6Y+VtjNrRm1lc9CHlj1Af0haqw3Y8s41Sgq45kGQ6bwdYG1sXOw+iofPhCf8ANRbrNd0w3VAqRttKBx10F0YjpYPXxZhPAnqUwHfvT+9ipnYw2Mo7gEXwQ3gPtT92SsozBNZ3Mk4kxTWlS7+jfPN4KeA/xkpqo5xjQ4z1R6KSEC ... , SIZE=1754, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat

Here is what raises a doubt: the packet "from" is the recipient's connectionId. I guess it's the only way to do it, but it could bring problems later for what I can see. I know I'm just speculating for now, but let's go ahead in our log.

2015-11-26 13:06:13.779 [in_3-message-router]  MessageRouter.processPacket()  FINEST:   2. Packet will be processed by: sess-man@beta.kontalk.net, from=c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, to=null, DATA=<message to="301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net" type="chat" id="Nxfighae8M83SgmHsFtkYFwPCKsU6B" from="e893c4e88ccd497d019cf0391b12065f65a6bc1c@beta.kontalk.net/237877240a4e1575" xmlns="jabber:client"><body>(cifrado)</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">hQEMA1ZSzqhr9kXbAQgAiVC/I09yJwYElxQbr0UOrfHIEpypiWa0bQlODH60B5NzHeYH92t7WzrjfNTNze7XHvaa6tNdH2sJJrA2k/4rxlgg/LTDmVs6/hNMPS6fT8J5WAr78CF+6zyjRTGQTc0nmECIHuy5sciMyYp/WDQhhRmOpU8TPEaY0TjPILe336Ay3m75wnRy4/s+ykp4FyZVAxETZlSBQIYOQBEa5q+qEkjTEcUDme0S30SoY5Z/dFeF/g34Y/7caEuFVPSyxR3GxeGWvlcLnMOHoRdOaWGnXYRTrE55Vpw4gffVknFlUOEcgCH6Z0MX3htcLTcXo1988IsC/AV6yHhUHZXnw6VpQdLoATO04dKrIZaAG9S1752VmmZPjycAJZElT2PadpRpZOvJfrv3JslDaGsxCJh/27+QQcwROE2Dm4CdEkf3eoXHwwDKjMJc6uFe+cqauE7nt87bmgjgZmTv/tAIw+NUdzwYMLU5NtLQ0h3iylsiFvOBkkFex3f8Qc442WxT7OUJCpE+uR/0Vz0wAo+tZ0ITbUC9kv5BNr6Y+VtjNrRm1lc9CHlj1Af0haqw3Y8s41Sgq45kGQ6bwdYG1sXOw+iofPhCf8ANRbrNd0w3VAqRttKBx10F0YjpYPXxZhPAnqUwHfvT+9ipnYw2Mo7gEXwQ3gPtT92SsozBNZ3Mk4kxTWlS7+jfPN4KeA/xkpqo5xjQ4z1R6KSEC ... , SIZE=1754, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat
2015-11-26 13:06:13.779 [in_3-message-router]  MessageRouter.processPacket()  FINEST:   Processing packet: from=c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, to=sess-man@beta.kontalk.net, DATA=<iq to="sess-man@beta.kontalk.net" type="set" from="c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788" id="e8b35e61-b09b-46c0-8380-256596bb4fd4"><command node="STREAM_FINISHED" xmlns="http://jabber.org/protocol/commands"/></iq>, SIZE=237, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=set
2015-11-26 13:06:13.779 [in_3-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@beta.kontalk.net
2015-11-26 13:06:13.779 [in_3-message-router]  MessageRouter.getLocalComponent()  FINEST: Called for : sess-man@beta.kontalk.net
2015-11-26 13:06:13.779 [in_3-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_176.83.204.136_56788, to=sess-man@beta.kontalk.net, DATA=<iq to="sess-man@beta.kontalk.net" type="set" from="c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788" id="e8b35e61-b09b-46c0-8380-256596bb4fd4"><command node="STREAM_FINISHED" xmlns="http://jabber.org/protocol/commands"/></iq>, SIZE=237, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=set
2015-11-26 13:06:13.779 [in_15-sess-man]   SessionManager.processPacket()     FINEST:   Received packet: from=c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, to=sess-man@beta.kontalk.net, DATA=<iq to="sess-man@beta.kontalk.net" type="set" from="c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788" id="9675c04a-55e1-4c0b-ba71-128f4459ae9f"><command node="STREAM_CLOSED" xmlns="http://jabber.org/protocol/commands"><x type="submit" xmlns="jabber:x:data"><field var="user-jid"><value>CData size: 74</value></field></x></command></iq>, SIZE=406, XMLNS=null, PRIORITY=SYSTEM, PERMISSION=NONE, TYPE=set
2015-11-26 13:06:13.779 [in_15-sess-man]   SessionManager.processCommand()    FINER:    STREAM_CLOSED command from: c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788
2015-11-26 13:06:13.779 [in_15-sess-man]   SessionManager.processPacket()     FINEST:   Received packet: from=c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, to=null, DATA=<message to="301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net" type="chat" id="Nxfighae8M83SgmHsFtkYFwPCKsU6B" from="e893c4e88ccd497d019cf0391b12065f65a6bc1c@beta.kontalk.net/237877240a4e1575" xmlns="jabber:client"><body>CData size: 9</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 1188</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay from="beta.kontalk.net" stamp="2015-11-26T13:06:13.777Z" xmlns="urn:xmpp:delay"/><delivery-error stamp="1448543173566" xmlns="http://tigase.org/delivery-error"/></message>, SIZE=1754, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat
2015-11-26 13:06:13.779 [in_15-sess-man]   SessionManager.processPacket()     FINEST:   processing packet: from=c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, to=sess-man@beta.kontalk.net, DATA=<message to="301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net" type="chat" id="Nxfighae8M83SgmHsFtkYFwPCKsU6B" from="e893c4e88ccd497d019cf0391b12065f65a6bc1c@beta.kontalk.net/237877240a4e1575" xmlns="jabber:client"><body>CData size: 9</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">CData size: 1188</e2e><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay from="beta.kontalk.net" stamp="2015-11-26T13:06:13.777Z" xmlns="urn:xmpp:delay"/><delivery-error stamp="1448543173566" xmlns="http://tigase.org/delivery-error"/></message>, SIZE=1754, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat, connection: XMPPResourceConnection=[user_jid=301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net/1e6565933f887add, packets=70, connectioId=c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, domain=beta.kontalk.net, authState=AUTHORIZED, isAnon=false, isTmp=false]
2015-11-26 13:06:13.779 [in_15-sess-man]   StartTLS.preProcess()              FINEST:   VHost: Domain: beta.kontalk.net, enabled: true, anonym: false, register: true, maxusers: 0, tls: false, s2sSecret: ac388384-19ae-4efd-867b-aa98afdaa3b2, domainFilter: ALL, domainFilterDomains: null, c2sPortsAllowed: null, saslAllowedMechanisms: null
2015-11-26 13:06:13.780 [in_15-sess-man]   BindResource.preProcess()          FINEST:   Setting correct from attribute: 301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net/1e6565933f887add
2015-11-26 13:06:13.780 [in_15-sess-man]   DomainFilter.preProcess()          FINEST:   Processing: from=c2s@beta.kontalk.net/178.62.44.19_5222_176.83.204.136_56788, to=sess-man@beta.kontalk.net, DATA=<message to="301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net" type="chat" id="Nxfighae8M83SgmHsFtkYFwPCKsU6B" from="301ec9a675d58bb2a9fa22f900ead23c443e0c21@beta.kontalk.net/1e6565933f887add" xmlns="jabber:client"><body>(cifrado)</body><e2e xmlns="urn:ietf:params:xml:ns:xmpp-e2e">hQEMA1ZSzqhr9kXbAQgAiVC/I09yJwYElxQbr0UOrfHIEpypiWa0bQlODH60B5NzHeYH92t7WzrjfNTNze7XHvaa6tNdH2sJJrA2k/4rxlgg/LTDmVs6/hNMPS6fT8J5WAr78CF+6zyjRTGQTc0nmECIHuy5sciMyYp/WDQhhRmOpU8TPEaY0TjPILe336Ay3m75wnRy4/s+ykp4FyZVAxETZlSBQIYOQBEa5q+qEkjTEcUDme0S30SoY5Z/dFeF/g34Y/7caEuFVPSyxR3GxeGWvlcLnMOHoRdOaWGnXYRTrE55Vpw4gffVknFlUOEcgCH6Z0MX3htcLTcXo1988IsC/AV6yHhUHZXnw6VpQdLoATO04dKrIZaAG9S1752VmmZPjycAJZElT2PadpRpZOvJfrv3JslDaGsxCJh/27+QQcwROE2Dm4CdEkf3eoXHwwDKjMJc6uFe+cqauE7nt87bmgjgZmTv/tAIw+NUdzwYMLU5NtLQ0h3iylsiFvOBkkFex3f8Qc442WxT7OUJCpE+uR/0Vz0wAo+tZ0ITbUC9kv5BNr6Y+VtjNrRm1lc9CHlj1Af0haqw3Y8s41Sgq45kGQ6bwdYG1sXOw+iofPhCf8ANRbrNd0w3VAqRttKBx10F0YjpYPXxZhPAnqUwHfvT+9ipnYw2Mo7gEXwQ3gPtT92SsozBNZ3Mk4kxTWlS7+jfPN4KeA/xkpqo5xjQ4z1R6KSEC ... , SIZE=1754, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat

The message continues its journey through the handling chain (a STREAM_CLOSED command is coming through too, that's from ClientConnectionManager IIRC) until it reaches BindResource.preProcess, which tries to handle the message because:

if (session.getConnectionId().equals(packet.getPacketFrom())) {

And the packet is indeed from the this session, so the if block goes through. The rest is self-explainatory in the code of BindResource.preProcess, until it finally reaches these lines:

if ( log.isLoggable( Level.FINEST ) ){
    log.log( Level.FINEST, "Setting correct from attribute: {0}", from_jid );
}
packet.initVars( from_jid, packet.getStanzaTo() );

Am I making any sense here?

Daniele Ricci commented 10 years ago

If you need anything else to debug this issue, please don't hesitate to ask. Several users have been reporting this behaviour by now and I want to fix this as soon as possible (it began happening since I've updated to latest release branch).
Wojciech Kapcia (Tigase) commented 10 years ago

I've included additional check in BindResource preProcessor to avoid handling such error packets.
Daniele Ricci commented 10 years ago

Thanks! I will pull the release branch tonight.
Andrzej Wójcik (Tigase) commented 10 years ago

I just checked if processing if other case will work correctly and all looks ok.
Daniele Ricci commented 9 years ago

I think this can be closed, thank you.
Login to comment

Type	Bug
Priority	Major
Assignee	Daniele Ricci
RedmineID	3689
Spent time	0

Issue Votes (0)

Watchers (0)

Reference

tigase/_server/server-core#598