Duplicate messages when using stream management

[singpolyma]

I enabled mod_smacks on my prosody, and now users with Conversations sometimes get duplicate messages when they reconnect. I expect that these are stanzas that got delivered right before the network cut and so the ack never got sent up to the server. It seems like Conversations should be able to detect this case (won't the stanza ids be the same?) and filter them out.

[iNPUTmice]

this isn't how sm works. the server won't just resend all stanzas from the last ack but on resume the client tells the server the last sequence number.
maybe what you are seeing are the effects of MAM or muc history.
filtering messages by id isn't always possible because a) messages are not required to have ids b) those ids don't have to be uuids. (conversations tries to do that when ever possible and where necessary. (muc, mam)
I by the way have never seen this happening. except with mam and muc in some scenarios. I have also seen some weird behavior with spectrum. but in those cases the duplicate messages arrived at my desktop as well and thus could not have been a result of failing sm

[singpolyma]

Don't have MAM right now, and the conversation isn't a MUC. The only reason I thought of sm is that it just started happening and I enabled sm yesterday and haven't made any other changes. I do also have carbons, but those have been on for some time. I will try to investigate more when I get time.

[singpolyma]

Is there a good way to get an XML log file generated of stanzas in/out from Conversations for later analysis so I can debug this?

[SamWhited]

I see this behavior fairly frequently; I haven't had a chance to triage yet though. Mostly (maybe exclusively) with muc for me.

[singpolyma]

@SamWhited if yours is with MUC do you think it is sm related? This is definitely with a 1:1

[SamWhited]

If I notice it again I'll turn SM off and let you know.

[singpolyma]

@SamWhited I just disabled my SM because it was getting too much. We'll see if the dupes go away again. What is your server set up? Is it prosody? What version? What mod_smacks version? Any other community (non-core) modules? Would be interesting for me to compare to mine, if you're not seeing this issue as much. Same questions for @iNPUTmice

[SamWhited]

@singpolyma I'm on ejabberd 14.12, stream management on (the default).

[devurandom]

I experience the same. Sometimes I receive the same messages again and again, so I end up with a dozen or so copies. I have SM and MAM enabled on my Prosody 0.10_pre (6224:2f709bc35575) server.

The time shown in the UI seems to be the received-time, as I guess from messages that are duplicated with more distance in time, but Conversation sorts messages by sent-time? Because duplicate messages are often shown like this: 1,1,1,1,1,1,2,2,2,2,2,2

[singpolyma]

@devurandom do you have mod_carbons as well?

[devurandom]

Yes

[singpolyma]

I wonder if carbons is interacting with smacks in a stupid way... haven't had time yet to test this idea.

[the-solipsist]

I too have seen this issue fairly frequently (though, I must admit, I haven't experienced it in around a fortnight or more). I have Prosody 0.9.7, and mod_smacks and mod_carbons and mod_carbons_copies enabled, among others.

[devurandom]

More information:

• It never happens for sent messages, only for incoming
• It can happen hours after the original message was received, with good internet connectivity in the meantime
• It always affects the last messages received, never those in the middle of a conversation
• It can affect a group of messages (say 3 in a row)

This time it was like this:

• I was chatting on the computer, my phone received carbons – I heard the message sounds, but did not interact with the phone
• The conversation ended, I had a brief look at my phone and then did not interact with it any further
• Several hours later I looked at the phone again, having received some duplicate messages
• Several minutes or maybe an hour after that I again received duplicate messages of said conversation
• I was on wifi for the whole time, so the connection should have been stable

[devurandom]

Another instance of this issue:

• I had a conversation on my computer and ended it by shutting the machine down
• I received a last message from above conversation on the phone and read it there
• I kept receiving the message in the manner described above (2-3 times over the course of a few hours)
• When I started another computer, I received the message there, once
• I received no further copies on any of my machines

Thus I conclude this case seems to be linked to offline messages.

[vext01]

I enabled mod_smacks in prosody recently and have been receiving duplicate messages. Both parties are using conversations, and we are sending normal messages (not in a MUC or anything).

[ghost]

I'm facing the same problem with Prosody and mod_smacks. No MUC or carbons.

[teissler]

We have exactly the same issue. We have prosody 0.9.7 and 0.9.4 on another server.
Both servers have mod_smacks and mod_carbons enabled.

We never had such an issue with MUC only with "normal" chats.

I anyone of the devs need an account to verify this, you can create an account at jabber.ipfire.org.

We didn't have this issue with other xmpp clients like ChatSecure.

[vext01]

Hrm, this is becoming a problem. Can anyone suggest an alternative android client with a nice UI, carbons and smacks support?

[iNPUTmice]

I did some digging...

It seems like with recent prosody versions with every resume the stanza count of Conversations falls one behind prosodys stanza count. Meaning the first resume is fine. The second resume will give us one more stanza, the third resume two more, the forth three and so forth. Depending on the situation (whether we received only messages or other stanzas as well) that will result in duplicate messages.

those are the facts. now come the wild speculations.

at this point I'm fairly certain that my stanza count (I'm counting every iq, presence and message) is correct. I reread my code did some debugging here and there.

a wild guess could be that prosody counts the resumed element as stanza?

I'm not seeing the behavior with 'older' versions of prosody. (I don't know exactly how old) And I haven't anyone complain about ejabberd.

@Zash

@vext01 the only other client a know of that supports SM is yaxim. Feel free to check this out and report back if you experience similar problems. That could help us narrow don't whether this is a server or a client problem.

[iNPUTmice]

I just very quickly did some tests with yaxim myself. I managed to produce duplicate messages once but couldn't reliably reproduce the results. (Staging this is actually a bit difficult because first of you have to produce a number of resumes to let the count diverge enough and then make sure that $count last stanzas contain at least on real message (real meaning with body and not just some receipt stuff that won't show up in the UI)

I'd love to see someone try yaxim for real for a couple of hours / days to see if yaxim really suffers from the same problem.

[Zash]

@iNPUTmice Could you get us debug logs from when this happens?

[iNPUTmice]

@Zash unfortunately no. I haven't seen this with any of my servers... I just observed this with the jabber.ipfire.org @Morlix linked earlier.

[iNPUTmice]

Woke up and tried to analyze the problem with a clear mind. I tried to eliminate as many non-message-with-body stanzas as possible. Left all the conference to get rid of some presence. Turned of message confirmation.

I'm now sure that this doesn't happen with siacs.eu (I was previously afraid that I just never noticed the effects because of all the presence packets I receive) it does how ever happen with jabber.ipfire.org (both open for registration in case someone's interested)

My test setup: Logged in with one siacs.eu and one jabber.ipfire.org account in Conversations. Send messages from my computer with the siacs.eu account to the ipfire account. With carbons enabled Conversations now receives the same amount of messages to each account. (carbon copies for the siacs.eu account and real messages for the ipfire account.)
if both accounts would show the same symptoms they both would receive the same duplicate messages. But they didn't. Only the ipfire account received duplicate messages.

Unfortunately I'm no longer a 100% sure that the count diverges by one at every resume. Might have been a coincident and there are might be other reasons for the count to diverge. But I'm still about 80% sure. (This is all still very hard to measure because a) I have no access to the ipfire server logs b) there is no way I can know/request the servers count.)

[iNPUTmice]

One more thing. I noticed that ipfire.org - if the latest stanzas are not messages - it will just resend the same iq stanza result multiple times.

02-08 09:42:43.851 D/conversations( 2634): daniel@jabber.ipfire.org catchup: <iq xmlns="jabber:client" id="v1919dudec" to="daniel@jabber.ipfire.org/phone" type="result"><delay from="jabber.ipfire.org" xmlns="urn:xmpp:delay" stamp="2015-02-08T08:30:20Z"/></iq>
02-08 09:42:43.857 D/conversations( 2634): daniel@jabber.ipfire.org/phonestanza number 53 received
02-08 09:42:43.859 D/conversations( 2634): daniel@jabber.ipfire.org catchup: <iq xmlns="jabber:client" id="v1919dudec" to="daniel@jabber.ipfire.org/phone" type="result"><delay from="jabber.ipfire.org" xmlns="urn:xmpp:delay" stamp="2015-02-08T08:30:20Z"/></iq>
02-08 09:42:43.865 D/conversations( 2634): daniel@jabber.ipfire.org/phonestanza number 54 received
02-08 09:42:43.866 D/conversations( 2634): daniel@jabber.ipfire.org catchup: <iq xmlns="jabber:client" id="v1919dudec" to="daniel@jabber.ipfire.org/phone" type="result"><delay from="jabber.ipfire.org" xmlns="urn:xmpp:delay" stamp="2015-02-08T08:30:20Z"/></iq>
02-08 09:42:43.875 D/conversations( 2634): daniel@jabber.ipfire.org/phonestanza number 55 received
02-08 09:42:43.877 D/conversations( 2634): daniel@jabber.ipfire.org catchup: <iq xmlns="jabber:client" id="v1919dudec" to="daniel@jabber.ipfire.org/phone" type="result"><delay from="jabber.ipfire.org" xmlns="urn:xmpp:delay" stamp="2015-02-08T08:30:20Z"/></iq>

There is something very weird going on... Either you haven't updated your prosody-modules in for ever or there is something wrong with the lua libraries?

[teissler]

Hi iNPUTmice,

if you could tell me from which timeframe you need the server logs, i can provide them to you.

Thanks in advance for your debugging.
I will provide tomorrow a list of all software version we currently use in our infrastructure, so maybe we could find something which might cause these issues.

Kind regards,

morlix

[iNPUTmice]

@Morlix at this point I'm fairly certain that this bug is not caused by Conversations. Please try to replicate the bug yourself under controlled circumstances. Feel free to do tests with yaxim as well. (Or any other client that supports SM.) and then send your log and findings to the prosody guys.

[teissler]

Hmm after a short test with yaxim i can definitely say, that i get messages only repeated once with yaxim instead of multiple times with Conversations.

I hope i find some more time to dig deeper into this. Meanwhile it would be great to know how you have tested this.

[iNPUTmice]

@Morlix have a look at processPacket at https://github.com/siacs/Conversations/blob/development/src/main/java/eu/siacs/conversations/xmpp/XmppConnection.java#L387

you can log the variable stanzasReceived and the variable element with with Log.d(Config.LOGTAG,"stanza #"+stanzasReceived+": "+element.toString()); or something similar. You can compare that with the debug log of prosody which logs their stanza count.

[vext01]

fwiw, I just received a duplicate on yaxim.
On 13 Feb 2015 16:50, "Daniel Gultsch" notifications@github.com wrote:

@Morlix https://github.com/morlix have a look at processPacket at
https://github.com/siacs/Conversations/blob/development/src/main/java/eu/siacs/conversations/xmpp/XmppConnection.java#L387

you can log the variable stanzasReceived and the variable element with
with Log.d(Config.LOGTAG,"stanza #"+stanzasReceived+":
"+element.toString()); or something similar. You can compare that with
the debug log of prosody which logs their stanza count.

—
Reply to this email directly or view it on GitHub
#879 (comment).

[Natureshadow]

That's a good question. I believe they are.

Are you thinking that maybe message receipts got lost and thus Conversatiosn resends them?

In any case, I see another issue. Quite often, mesages jsut say "Sending...", even long after they were delivered to the other party.

Maybe there really is an issue with message receipts rather than sm?

[iNPUTmice]

Conversations does not use message receipts to resend messages. The message state is being switched from sending to sent after the servers stream managment has acked the message. if you see sending even after the recepient has received your message that means the server doesn't ack your messages which indicates a problem in SM.

The prosody devs say, that this is an conversations issue.

@mase76 when/where did they say that?

[mase76]

@iNPUTmice I already reported this issue via email with the prosody dev.

gajim or pidgin cannot have this issue, as they don't support message streaming.

How can we help to get rid of this very annoying issue?
Maybe you could provide some debug builds.
It does not matter if this is a server or client issue. We must
solve this together instead.

[iNPUTmice]

I'm happy to help. and I did so already as this thread shows. however I'm not experiencing the bug myself despite the fact that I am using prosody myself so my options are limited.

[mase76]

I can create a test account for you on my server.

gpg-id: ccdbc2cf
https://www.setho.org/people

[iNPUTmice]

bcdfdb9 introduces a config option to log Conversations’ stanza counts. This should make it visable if prosody stops incrementing stanza counts as @BrianBlade noticed:

I noticed that mod_smacks on Prosody sometimes for (yet) unknown reasons stops increasing the incoming stanza count. This causes the last messages to be resend every time the sender resumes a stream-management session.

I think it will be important to differentiate between messages being send multiple times and messages being received multiple times.

with the debug option enabled Conversations should log something similiar to this after each message:

if you are missing the second line or that line gives you a different stanza number something is wrong.

D/conversations(11602): inputmice@siacs.eu: requesting ack for message stanza #16
D/conversations(11602): inputmice@siacs.eu: server acknowledged stanza #16

[iNPUTmice]

btw if you are unwilling to debug this yourself there is also the option of switching to ejabberd which doesn't seem to have those issues. I have no problem with prosody myself but the sm module in prosody is marked as unstable and so is the prosody version 0.10 which a lot of you seem to be using. stream managment in ejabberd on the other hand is available in the stable branch.

[deoren]

We started having this issue on our Prosody 0.10 installation as well recently. We were trying to troubleshoot lots of failed image deliveries, long wait times, etc by downgrading our Conversations version. We started at 1.2.0 and then went to 1.1.0 and then I think finally to 1.0.0. After not really seeing any change we did a direct upgrade back to 1.2.0.

Not sure if that is in any way helpful or not or just muddies the water so to speak. We are also using the smacks module with a default 5 minute timeout setting. I'm specifically using 0.10 in order to gain the MAM functionality.

• https://code.google.com/p/prosody-modules/wiki/mod_mam
• https://code.google.com/p/prosody-modules/wiki/mod_mam_archive

When I noticed the duplication today it was first from a Pidgin client. I then checked Conversations on my Nexus 4 (Android 4.4.4) and saw them there as well. I checked the prosodyarchive table in the database and found them listed there as well.

The sender did not see the duplicate messages in the list on their end. They initially reported send errors and then reported that those notices were gone when they glanced again.

[deoren]

I reverted mod_smacks to 1635:b877b75eb973 on our installation to see if that helps. So far I'm not seeing the same behavior, but because I had to reboot Prosody to load the downgraded module it's too soon to say for sure.

[mase76]

I tried a mod_smacks version from January. Somewhat better, but not solved.

[Natureshadow]

The issue goes away with ejabberd 15.03 with all the modules enabled.

[mwild1]

@iNPUTmice Thanks for the new debug option. If anyone who is experiencing the issue can enable this and provide some insight, it will be really useful. Thanks!

[deoren]

@mwild1 I assume that if we capture debug output you're only interested if we are running the latest version of mod_smacks?

[deoren]

@iNPUTmice Is the debug option included with bcdfdb9 part of the 1.3.0 version that was just released? I installed from Google Play and didn't see it listed anyway, but I am probably overlooking it. Is it turned on by default?

[iNPUTmice]

@deoren No you will have to compile Conversations yourself. There is no UI setting for this. Just the hard coded Config.java variable.

[Natureshadow]

I have to report that the issue still appears with ejabberd. It was just quiet for two days, but now we are back to the full storm of old messages.

[deoren]

@iNPUTmice thanks for clarifying. Any plans to add a toggle within the UI, perhaps under Settings > Expert options?

[mwild1]

Hi Prosody-using folks. We just pushed some updates to mod_smacks in the prosody-modules repository. To update, run: hg pull -u -R /path/to/prosody-modules and restart Prosody.

A reminder for future reports (even if you have already commented) please say what version of Conversations, Prosody and mod_smacks you are using (you can find the last one with the command: hg id /path/to/prosody-modules ).

I'm interested to know if the update changes the behaviour in any way for people experiencing the issue.

@iNPUTmice You don't experience the issue - what version of mod_smacks do you have? (see command above)

[mgansler]

I have updated my docker image:
docker pull mgansler/prosody:nightly
prosody nightly 132, community modules from right after the post above :)

so far no duplicated messages

[devurandom]

@mgansler Maybe you can embed the version information into the Docker image tag or make it otherwise available?

[mgansler]

mgansler/prosody:0.10-132_e4867211cddb

or if you want to build yourself:
https://github.com/mgansler/docker-prosody/tree/latest

[mgansler]

I worked on my docker images a bit:
mgansler/prosody:nightly-0.10-131 has only prosody installed
mgansler/prosody-modules:e4867211cddb contains the current modules
This way, modules and prosody itself can be updated individually.
See docker-prosody-modules for hints on how to combine the two containers.
I will continue to tag all kinds of different versions of prosody and/or the modules, i hope it helps debugging.

[deoren]

@mwild1 It may be too soon to tell, but I've not noticed any duplicate messages since upgrading to 1706:e4867211cdd of the prosody modules repo and restarting Prosody about 9 hours ago. Thanks!

[kriztan]

@mwild1 I'm using mod_smacks e4867211cddb with prosody-trunk 561 and Conversations 1.4.0 alpha for 2 days. Now I've noticed that there were still some duplicates, but less than before and in the logfiles are still lines like that The client says it handled 130 new stanzas, but we only sent 122 :).

And I've also noticed that the session is automatically killed after a time without changing network state or restarting the server.

Please tell me, how to help with that.

[mwild1]

@kriztan Any chance you could email some debug logs to matthew@prosody.im?

[arty-name]

Using Conversations 1.4.3, Prosody 0.10 1nightly139-1~trusty, mod_smacks 1733:9abd3dce619a I do not seem to get duplicates

[mwild1]

Anyone else still experiencing this issue on the updated versions?

[mase76]

I did not get any duplicate messages within the last weeks. Prosody and mod_smacks was kept up to date all the time.

[iNPUTmice]

Ok I'm closing here since this probably resolved and didn't seem to be a Conversations problem anyway.