Project

General

Profile

Message goes to offline storage before being delivered

Daniele Ricci
Added about 2 years ago

Hello,

I occasionally bump into this strange issue while connecting with a client and getting stored messages from the OfflineMessages plugin:

2016-12-10 13:56:20.909 [in_0-sess-man]    SessionManager.walk()              FINEST:   XMPPProcessorIfc: Message (message)Request: from=sess-man@notebook.casaricci.it, to=sess-man@notebook.casaricci.it, DATA=<message id="KQsQ1zfYMmnj2O8na9J9cxXLepQxM3" xmlns="jabber:client" to="d96b6d3ba60e3714e98a094990bb6275e83ab46b@prime.kontalk.net" type="chat" from="4bdd4f929f3a1062253e4e496bafba0bdfb5db75@prime.kontalk.net/aa3bb802b8c777f6"><body>1</body><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay xmlns="urn:xmpp:delay" stamp="2016-12-10T12:56:11.038Z" from="prime.kontalk.net">Offline Storage - notebook.casaricci.it</delay></message>, SIZE=476, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat, conn: XMPPResourceConnection=[user_jid=d96b6d3ba60e3714e98a094990bb6275e83ab46b@prime.kontalk.net/6b8a44278cd80d72, packets=11, connectioId=c2s@notebook.casaricci.it/127.0.0.1_5222_127.0.0.1_41278, domain=prime.kontalk.net, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=164113115, parentSession liveTime=207]
2016-12-10 13:56:20.909 [in_0-sess-man]    OfflineMessages.savePacketForOffLineUser()  FINEST: Storing packet for offline user: from=sess-man@notebook.casaricci.it, to=sess-man@notebook.casaricci.it, DATA=<message id="KQsQ1zfYMmnj2O8na9J9cxXLepQxM3" xmlns="jabber:client" to="d96b6d3ba60e3714e98a094990bb6275e83ab46b@prime.kontalk.net" type="chat" from="4bdd4f929f3a1062253e4e496bafba0bdfb5db75@prime.kontalk.net/aa3bb802b8c777f6"><body>1</body><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay xmlns="urn:xmpp:delay" stamp="2016-12-10T12:56:11.038Z" from="prime.kontalk.net">Offline Storage - notebook.casaricci.it</delay></message>, SIZE=476, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat
2016-12-10 13:56:20.910 [message Queue Worker 0]  Message.process()           FINEST:   Processing packet: from=sess-man@notebook.casaricci.it, to=sess-man@notebook.casaricci.it, DATA=<message id="KQsQ1zfYMmnj2O8na9J9cxXLepQxM3" xmlns="jabber:client" to="d96b6d3ba60e3714e98a094990bb6275e83ab46b@prime.kontalk.net" type="chat" from="4bdd4f929f3a1062253e4e496bafba0bdfb5db75@prime.kontalk.net/aa3bb802b8c777f6"><body>1</body><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay xmlns="urn:xmpp:delay" stamp="2016-12-10T12:56:11.038Z" from="prime.kontalk.net">Offline Storage - notebook.casaricci.it</delay></message>, SIZE=476, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat, for session: XMPPResourceConnection=[user_jid=d96b6d3ba60e3714e98a094990bb6275e83ab46b@prime.kontalk.net/6b8a44278cd80d72, packets=11, connectioId=c2s@notebook.casaricci.it/127.0.0.1_5222_127.0.0.1_41278, domain=prime.kontalk.net, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=164113115, parentSession liveTime=208]
2016-12-10 13:56:20.910 [message Queue Worker 0]  Message.process()           FINEST:   Message to this user, packet: from=sess-man@notebook.casaricci.it, to=sess-man@notebook.casaricci.it, DATA=<message id="KQsQ1zfYMmnj2O8na9J9cxXLepQxM3" xmlns="jabber:client" to="d96b6d3ba60e3714e98a094990bb6275e83ab46b@prime.kontalk.net" type="chat" from="4bdd4f929f3a1062253e4e496bafba0bdfb5db75@prime.kontalk.net/aa3bb802b8c777f6"><body>1</body><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay xmlns="urn:xmpp:delay" stamp="2016-12-10T12:56:11.038Z" from="prime.kontalk.net">Offline Storage - notebook.casaricci.it</delay></message>, SIZE=476, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat, for session: XMPPResourceConnection=[user_jid=d96b6d3ba60e3714e98a094990bb6275e83ab46b@prime.kontalk.net/6b8a44278cd80d72, packets=11, connectioId=c2s@notebook.casaricci.it/127.0.0.1_5222_127.0.0.1_41278, domain=prime.kontalk.net, authState=AUTHORIZED, isAnon=false, isTmp=false, parentSession hash=164113115, parentSession liveTime=208]
2016-12-10 13:56:20.910 [message Queue Worker 0]  Message.getConnectionsForMessageDelivery()  FINEST: Out of: 1 total connections, only: 0 have non-negative priority

The message just "skips" this connection and goes to offline storage. It will be delivered on the next connection. This results in wrong delivery order (in a block of three messages, for example, only the second and the third initially went through).

I can't reproduce it constantly, it happens once in a while, so I couldn't find the cause. I noticed this:

2016-12-10 13:56:20.910 [message Queue Worker 0]  Message.getConnectionsForMessageDelivery()  FINEST: Out of: 1 total connections, only: 0 have non-negative priority

So I asked myself: has the client already sent its initial presence? Yes it did, a few milliseconds before:

2016-12-10 13:56:20.891 [in_21-sess-man]   SessionManager.processPacket()     FINEST:   Received packet: from=c2s@notebook.casaricci.it/127.0.0.1_5222_127.0.0.1_41278, to=sess-man@notebook.casaricci.it, DATA=<presence id="0I70q-73" xmlns="jabber:client"><c xmlns="http://jabber.org/protocol/caps" hash="sha-1" ver="none" node="http://www.kontalk.org/"/></presence>, SIZE=156, XMLNS=jabber:client, PRIORITY=PRESENCE, PERMISSION=NONE, TYPE=null

Is it possible that 19 ms aren't enough for Message.getConnectionsForMessageDelivery() to rely on the latest presence information? Isn't it strange that Message.process comes after OfflineMessages.postProcess anyway?

Just out of clarity, a few more milliseconds later, after processing some more requests from the client (mainly service discovery and roster presence) the other two messages from storage are delivered:

2016-12-10 13:56:20.931 [in_0-sess-man]    SessionManager.processPacket()     FINEST:   Received packet: from=sess-man@notebook.casaricci.it, to=null, DATA=<message id="8Z0lZWy15aC732vryKPPsoS38ROQ1f" xmlns="jabber:client" to="d96b6d3ba60e3714e98a094990bb6275e83ab46b@prime.kontalk.net" type="chat" from="4bdd4f929f3a1062253e4e496bafba0bdfb5db75@prime.kontalk.net/aa3bb802b8c777f6"><body>2</body><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay xmlns="urn:xmpp:delay" stamp="2016-12-10T12:56:12.238Z" from="prime.kontalk.net">CData size: 39</delay></message>, SIZE=476, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat
...
2016-12-10 13:56:20.933 [in_0-sess-man]    SessionManager.processPacket()     FINEST:   Received packet: from=sess-man@notebook.casaricci.it, to=null, DATA=<message id="VXZ0mcZKUtlIA55khlSQo79rH5u7NU" xmlns="jabber:client" to="d96b6d3ba60e3714e98a094990bb6275e83ab46b@prime.kontalk.net" type="chat" from="4bdd4f929f3a1062253e4e496bafba0bdfb5db75@prime.kontalk.net/aa3bb802b8c777f6"><body>3</body><active xmlns="http://jabber.org/protocol/chatstates"/><request xmlns="urn:xmpp:receipts"/><delay xmlns="urn:xmpp:delay" stamp="2016-12-10T12:56:13.582Z" from="prime.kontalk.net">CData size: 39</delay></message>, SIZE=476, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat

I'm using the latest release branch (but it's been happening for months now).

Thanks for your help


Replies (7)

Added by Daniele Ricci about 2 years ago

Sorry, got the wrong logs. I've edited my post with the correct findings.

Added by Daniele Ricci about 2 years ago

I'm doing some hacks on Tigase code... if I add a piece of code like this just before queueing messages from storage:

        if (session.getPresence() == null || session.getPriority() <= 0) {
            try {
                Thread.sleep(500);
            }
            catch (InterruptedException ignored) {
            }
        }

I made the recipient client ignore SM ack and disconnect abruptly so those messages would always fail and go back to storage.

With my patch, messages are always delivered, but sometimes the first one (the one that previously "skipped" the connection) is delivered last in the sequence. However, when that happens, the first message will remain the last, because message timestamps have changed and reset to that delivery time. And this ends up in storage, so at next connection order will be 2, 3, 1.

A few more tries and message 2 disappears.

More tries will show messages 1 and 3 being delivered at apparently random order each time.

I'm going to analyze this more thoroghly, but if you have any hint or pointers please share them.

Added by Daniele Ricci about 2 years ago

I found the source of the wrong delivery issue. It's caused by OfflineMessages.StampComparator. It's ignoring urn:xmpp:delay element. I'll send a patch to you via issue tracking later.

In the meanwhile I'm doing some more tests with that code fixed to see if messages disappear again. But I doubt it is related to the wrong order issue per se. I'll keep you posted.

Added by Daniele Ricci about 2 years ago

The sleep I put into OfflineMessages.process right before results.addAll seems to be avoiding message loss. I'll keep you posted if it happens again. In the meanwhile I'll send you the patch for the StampComparator.

Added by Andrzej Wójcik IoT 1 CloudTigaseTeam about 2 years ago

I've just fixed StampComparator in task #4818. Now it properly compares timestamps in XEP-0203 and XEP-0091.

Added by Daniele Ricci about 2 years ago

Sorry I forgot to send the patch to you! Thank you for the fix.

    (1-7/7)