MUC messages duplicated as DMs
Closed this issue · 12 comments
Environment:
- Docker
- 2 Openfire servers
- Hazelcast plugin to cluster
- Monitoring plugin on both
- Spark client (Mac)
- Conversations client (Android)
With users in the roster and in the MUC, the Conversations user sometimes sees MUC messages duplicated and appearing as one-on-one messages from the message author.
Launch cluster using https://github.com/surevine/openfire-docker-compose/tree/deleteme_all-the-branches
Log in to Spark1 as user1
Log in to Spark2 as user2
Open MUC1 as user1 and send a message
Open MUC1 as user2 and send a message
Log in to Conversations as user3
Open MUC1 as user3. See messages.
Open one-on-one messages with user1. See message.
Open one-on-one messages with user2. See no message.
(Sometimes user1/user2 are switched. Maybe it's the user on the node that user3 isn't on?)
Using additional logging (https://github.com/Fishbowler/openfire-monitoring-plugin/tree/137_more-logs) and some database snooping, the extra message has no stanza stored in ofMessageArchive, and so one gets recreated (although seemingly before it reaches the line of code that should do this here and so this isn't used).
The user3 should get a stanza about a message from user1 that looks like this:
<message to="user1@xmpp.localhost.example/Spark 2.8.3.579" id="2ZjfZ-114" type="groupchat" from="muc1@conference.xmpp.localhost.example/user1">
<body>This is the message</body>
<x xmlns="jabber:x:event">
<offline/>
<delivered/>
<displayed/>
<composing/>
</x>
<stanza-id xmlns="urn:xmpp:sid:0" id="83b84db1-f5f0-4240-ac6e-77d22dabba30" by="muc1@conference.xmpp.localhost.example"/>
<addresses xmlns="http://jabber.org/protocol/address">
<address type="ofrom" jid="user2@xmpp.localhost.example"/>
</addresses>
</message>
But instead gets one that looks like this:
<message from="user1@xmpp.localhost.example" to="muc1@conference.xmpp.localhost.example" type="normal">
<body>This is the message</body>
</message>
The stanza should be more properly reconstructed, and that would prevent this issue.
There are 2 separate issues to be logged:
- The stanza should have been stored correctly in the first place
- Conversations should ignore this message. This isn't from user1 to user3, so shouldn't be displayed in the one-on-one messages (although we give em a break since this is nonsense from the server).
I've replaced the usage of 'DM' with 'one-on-one messages' in the above comments, as in XMPP context, 'DM' can cause some confusion.
DM is typically reserved in scenarios where private messages are sent 'through' a MUC room (https://xmpp.org/extensions/xep-0045.html#privatemessage).
I've also briefly discussed this with the author of Conversations, to see if they're interested in changing behavior on their end. Conversations currently ignores the 'to' address, which is why these messages show.
I'm assuming that messages sent to a MUC room by users that are connected to a cluster node other than the senior node do not get logged in the stanza column of the ofMessageArchive database table.
The content of the table is shown below (which probably renders badly, apologies) seems to collaborate that, at least for the first time I tried the scenario. The message content describes on what cluster node the sender was connected.
| messageid | conversationid | fromjid | fromjidresource | tojid | tojidresource | sentdate | stanza | body |
|---|---|---|---|---|---|---|---|---|
| 1 | 1 | user1@xmpp.localhost.example | converse.js-114026539 | muc1@conference.xmpp.localhost.example | user1 | 1606729420602 | This was sent by user1 that is connected to the senior cluster node! | This was sent by user1 that is connected to the senior cluster node! |
| 2 | 1 | user2@xmpp.localhost.example | converse.js-27557185 | muc1@conference.xmpp.localhost.example | user2 | 1606729430236 | null | this was sent by user2 that is connected to the junior cluster node! |
DeI'm not having luck reproducing this. In a completely new environment, I've created a scenario in which I'm connecting user1, on server xmpp1 (which happens to be the senior cluster member), and share one message in room mucOne. I'm also connecting user2, on server xmpp2 (junior cluster member), and share another message in room mucOne.
Next, I'm using the Smack debugger that's part of Spark to send off a MAM query, using user3 (I've done that twice, connecting to each cluster node). The responses seemed valid to me. Next, I joined the room (using user3 again), also twice: once on each cluster node. The chat history that gets sent seems fine.
Database content prior to starting to interact with the message archive:
Your query: select * from ofMessageArchive
Your response:
messageid conversationid fromjid fromjidresource tojid tojidresource sentdate stanza body
1 1 user1@xmpp.localhost.example converse.js-38025516 muc1@conference.xmpp.localhost.example user1 1606751465422 <message from="muc1@conference.xmpp.localhost.example/user1" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3" to="muc1@conference.xmpp.localhost.example" type="groupchat"><body>This was sent by user 1 in mucOne on xmpp1, which is the senior cluster node.</body><active xmlns="http://jabber.org/protocol/chatstates"></active><origin-id xmlns="urn:xmpp:sid:0" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3"></origin-id><stanza-id xmlns="urn:xmpp:sid:0" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3" by="muc1@conference.xmpp.localhost.example"/><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="user1@xmpp.localhost.example"/></addresses></message> This was sent by user 1 in mucOne on xmpp1, which is the senior cluster node.
2 1 user2@xmpp.localhost.example converse.js-33213578 muc1@conference.xmpp.localhost.example user2 1606751479042 null This was sent by user 2 in mucOne on xmpp2, which is a junior cluster node.
Query, using user3 connected to xmpp1 / senior cluster node:
<iq type='set' id='1' to='muc1@conference.xmpp.localhost.example'>
<query xmlns='urn:xmpp:mam:2' queryid='f27' />
</iq>
Responses:
<message to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT" from="muc1@conference.xmpp.localhost.example"><result xmlns="urn:xmpp:mam:2" queryid="f27" id="1"><forwarded xmlns="urn:xmpp:forward:0"><delay xmlns="urn:xmpp:delay" stamp="2020-11-12T15:00:16.988Z"/><message xmlns="jabber:client" type="groupchat" from="muc1@conference.xmpp.localhost.example"><subject/></message></forwarded></result></message>
<message to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT" from="muc1@conference.xmpp.localhost.example"><result xmlns="urn:xmpp:mam:2" queryid="f27" id="51"><forwarded xmlns="urn:xmpp:forward:0"><delay xmlns="urn:xmpp:delay" stamp="2020-11-30T15:51:05.424Z"/><message xmlns="jabber:client" from="muc1@conference.xmpp.localhost.example/user1" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3" type="groupchat"><body>This was sent by user 1 in mucOne on xmpp1, which is the senior cluster node.</body><active xmlns="http://jabber.org/protocol/chatstates"></active><origin-id xmlns="urn:xmpp:sid:0" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3"></origin-id><stanza-id xmlns="urn:xmpp:sid:0" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3" by="muc1@conference.xmpp.localhost.example"></stanza-id><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="user1@xmpp.localhost.example"/></addresses></message></forwarded></result></message>
<message to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT" from="muc1@conference.xmpp.localhost.example"><result xmlns="urn:xmpp:mam:2" queryid="f27" id="101"><forwarded xmlns="urn:xmpp:forward:0"><delay xmlns="urn:xmpp:delay" stamp="2020-11-30T15:51:19.043Z"/><message xmlns="jabber:client" from="muc1@conference.xmpp.localhost.example/user2" id="ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76" type="groupchat"><body>This was sent by user 2 in mucOne on xmpp2, which is a junior cluster node.</body><active xmlns="http://jabber.org/protocol/chatstates"></active><origin-id xmlns="urn:xmpp:sid:0" id="ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76"></origin-id><stanza-id xmlns="urn:xmpp:sid:0" id="ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76" by="muc1@conference.xmpp.localhost.example"></stanza-id><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="user2@xmpp.localhost.example"/></addresses></message></forwarded></result></message>
<iq type="result" id="1" from="muc1@conference.xmpp.localhost.example" to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT"><fin xmlns="urn:xmpp:mam:2" queryid="f27" complete="true"><set xmlns="http://jabber.org/protocol/rsm"><first>1</first><last>ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76</last><count>3</count></set></fin></iq>
<presence from="user1@xmpp.localhost.example/converse.js-38025516" to="user3@xmpp.localhost.example"><priority>0</priority><idle xmlns="urn:xmpp:idle:1" since="2020-11-30T15:51:20.592Z"></idle><c xmlns="http://jabber.org/protocol/caps" hash="sha-1" node="https://conversejs.org" ver="++rpqEg4AFeEh+9zI4doy8ZTgyM="></c></presence>
<presence from="user2@xmpp.localhost.example/converse.js-33213578" to="user3@xmpp.localhost.example"><priority>0</priority><idle xmlns="urn:xmpp:idle:1" since="2020-11-30T15:51:25.592Z"></idle><c xmlns="http://jabber.org/protocol/caps" hash="sha-1" node="https://conversejs.org" ver="++rpqEg4AFeEh+9zI4doy8ZTgyM="></c></presence>
Query, using user3 connected to xmpp2 / junior cluster node:
<iq type='set' id='a' to='muc1@conference.xmpp.localhost.example'>
<query xmlns='urn:xmpp:mam:2' queryid='f27' />
</iq>
Responses
<message to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT" from="muc1@conference.xmpp.localhost.example"><result xmlns="urn:xmpp:mam:2" queryid="f27" id="1"><forwarded xmlns="urn:xmpp:forward:0"><delay xmlns="urn:xmpp:delay" stamp="2020-11-12T15:00:16.988Z"/><message xmlns="jabber:client" type="groupchat" from="muc1@conference.xmpp.localhost.example"><subject/></message></forwarded></result></message>
<message to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT" from="muc1@conference.xmpp.localhost.example"><result xmlns="urn:xmpp:mam:2" queryid="f27" id="51"><forwarded xmlns="urn:xmpp:forward:0"><delay xmlns="urn:xmpp:delay" stamp="2020-11-30T15:51:05.424Z"/><message xmlns="jabber:client" from="muc1@conference.xmpp.localhost.example/user1" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3" type="groupchat"><body>This was sent by user 1 in mucOne on xmpp1, which is the senior cluster node.</body><active xmlns="http://jabber.org/protocol/chatstates"></active><origin-id xmlns="urn:xmpp:sid:0" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3"></origin-id><stanza-id xmlns="urn:xmpp:sid:0" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3" by="muc1@conference.xmpp.localhost.example"></stanza-id><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="user1@xmpp.localhost.example"/></addresses></message></forwarded></result></message>
<message to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT" from="muc1@conference.xmpp.localhost.example"><result xmlns="urn:xmpp:mam:2" queryid="f27" id="101"><forwarded xmlns="urn:xmpp:forward:0"><delay xmlns="urn:xmpp:delay" stamp="2020-11-30T15:51:19.043Z"/><message xmlns="jabber:client" from="muc1@conference.xmpp.localhost.example/user2" id="ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76" type="groupchat"><body>This was sent by user 2 in mucOne on xmpp2, which is a junior cluster node.</body><active xmlns="http://jabber.org/protocol/chatstates"></active><origin-id xmlns="urn:xmpp:sid:0" id="ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76"></origin-id><stanza-id xmlns="urn:xmpp:sid:0" id="ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76" by="muc1@conference.xmpp.localhost.example"></stanza-id><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="user2@xmpp.localhost.example"/></addresses></message></forwarded></result></message>
<iq type="result" id="a" from="muc1@conference.xmpp.localhost.example" to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT"><fin xmlns="urn:xmpp:mam:2" queryid="f27" complete="true"><set xmlns="http://jabber.org/protocol/rsm"><first>1</first><last>ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76</last><count>3</count></set></fin></iq>
Joining (through the UI) mucOne, using user3 connected to xmpp2 / junior cluster node:
<presence to='muc1@conference.xmpp.localhost.example/user3' id='9YZWD-130'><x xmlns='http://jabber.org/protocol/muc'></x><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://www.igniterealtime.org/projects/smack' ver='9LJego/jm+LdNGOFm5gPTMPapl0='/></presence>
Responses:
<presence from="muc1@conference.xmpp.localhost.example/user1" to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT"><x xmlns="http://jabber.org/protocol/muc#user"><item jid="user1@xmpp.localhost.example/converse.js-38025516" affiliation="none" role="participant"/></x></presence>
<presence from="muc1@conference.xmpp.localhost.example/user2" to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT"><x xmlns="http://jabber.org/protocol/muc#user"><item jid="user2@xmpp.localhost.example/converse.js-33213578" affiliation="none" role="participant"/></x></presence>
<presence to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT" id="9YZWD-130" from="muc1@conference.xmpp.localhost.example/user3"><c xmlns="http://jabber.org/protocol/caps" hash="sha-1" node="http://www.igniterealtime.org/projects/smack" ver="9LJego/jm+LdNGOFm5gPTMPapl0="></c><x xmlns="http://jabber.org/protocol/muc#user"><item jid="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT" affiliation="none" role="participant"/><status code="110"/><status code="100"/></x></presence>
<message from="muc1@conference.xmpp.localhost.example/user1" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3" to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT" type="groupchat"><body>This was sent by user 1 in mucOne on xmpp1, which is the senior cluster node.</body><active xmlns="http://jabber.org/protocol/chatstates"></active><origin-id xmlns="urn:xmpp:sid:0" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3"></origin-id><stanza-id xmlns="urn:xmpp:sid:0" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3" by="muc1@conference.xmpp.localhost.example"/><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="user1@xmpp.localhost.example"/></addresses><delay xmlns="urn:xmpp:delay" stamp="2020-11-30T15:51:05.425Z" from="user1@xmpp.localhost.example/converse.js-38025516"/></message>
<message from="muc1@conference.xmpp.localhost.example/user2" id="ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76" to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT" type="groupchat"><body>This was sent by user 2 in mucOne on xmpp2, which is a junior cluster node.</body><active xmlns="http://jabber.org/protocol/chatstates"></active><origin-id xmlns="urn:xmpp:sid:0" id="ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76"></origin-id><stanza-id xmlns="urn:xmpp:sid:0" id="ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76" by="muc1@conference.xmpp.localhost.example"/><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="user2@xmpp.localhost.example"/></addresses><delay xmlns="urn:xmpp:delay" stamp="2020-11-30T15:51:19.043Z" from="user2@xmpp.localhost.example/converse.js-33213578"/></message>
<message type="groupchat" from="muc1@conference.xmpp.localhost.example" to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT"><subject></subject><delay xmlns="urn:xmpp:delay" stamp="2020-11-12T15:00:16.988Z" from="muc1@conference.xmpp.localhost.example"/></message>
Joining (through the UI) mucOne, using user3 connected to xmpp1 / senior cluster node:
<presence to='muc1@conference.xmpp.localhost.example/user3' id='xApsj-125'><x xmlns='http://jabber.org/protocol/muc'></x><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://www.igniterealtime.org/projects/smack' ver='9LJego/jm+LdNGOFm5gPTMPapl0='/></presence>
Responses:
<presence from="muc1@conference.xmpp.localhost.example/user1" to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT"><x xmlns="http://jabber.org/protocol/muc#user"><item jid="user1@xmpp.localhost.example/converse.js-38025516" affiliation="none" role="participant"/></x></presence>
<presence from="muc1@conference.xmpp.localhost.example/user2" to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT"><x xmlns="http://jabber.org/protocol/muc#user"><item jid="user2@xmpp.localhost.example/converse.js-33213578" affiliation="none" role="participant"/></x></presence>
<presence to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT" id="xApsj-125" from="muc1@conference.xmpp.localhost.example/user3"><c xmlns="http://jabber.org/protocol/caps" hash="sha-1" node="http://www.igniterealtime.org/projects/smack" ver="9LJego/jm+LdNGOFm5gPTMPapl0="></c><x xmlns="http://jabber.org/protocol/muc#user"><item jid="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT" affiliation="none" role="participant"/><status code="110"/><status code="100"/></x></presence>
<message from="muc1@conference.xmpp.localhost.example/user1" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3" to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT" type="groupchat"><body>This was sent by user 1 in mucOne on xmpp1, which is the senior cluster node.</body><active xmlns="http://jabber.org/protocol/chatstates"></active><origin-id xmlns="urn:xmpp:sid:0" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3"></origin-id><stanza-id xmlns="urn:xmpp:sid:0" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3" by="muc1@conference.xmpp.localhost.example"/><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="user1@xmpp.localhost.example"/></addresses><delay xmlns="urn:xmpp:delay" stamp="2020-11-30T15:51:05.423Z" from="user1@xmpp.localhost.example/converse.js-38025516"/></message>
<message from="muc1@conference.xmpp.localhost.example/user2" id="ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76" to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT" type="groupchat"><body>This was sent by user 2 in mucOne on xmpp2, which is a junior cluster node.</body><active xmlns="http://jabber.org/protocol/chatstates"></active><origin-id xmlns="urn:xmpp:sid:0" id="ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76"></origin-id><stanza-id xmlns="urn:xmpp:sid:0" id="ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76" by="muc1@conference.xmpp.localhost.example"/><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="user2@xmpp.localhost.example"/></addresses><delay xmlns="urn:xmpp:delay" stamp="2020-11-30T15:51:19.044Z" from="user2@xmpp.localhost.example/converse.js-33213578"/></message>
<message type="groupchat" from="muc1@conference.xmpp.localhost.example" to="user3@xmpp.localhost.example/Spark 2.9.5-SNAPSHOT"><subject></subject><delay xmlns="urn:xmpp:delay" stamp="2020-11-12T15:00:16.988Z" from="muc1@conference.xmpp.localhost.example"/></message>
I'm connecting user1, on server xmpp1 (which happens to be the senior cluster member), and share one message in room mucOne. I'm also connecting user2, on server xmpp2 (junior cluster member), and share another message in room mucTwo.
I was using the same MUC both times, but doubt that's the deciding factor.
I wonder if I need some traffic interception? Perhaps the request sent by the Conversations client differs slightly from yours? 🤷♂️
I was using the same MUC both times
I did that too, but wrote it down incorrectly. I have now modified my comment above.
I wonder if I need some traffic interception?
Let's try that. The xmldebugger plugin should help us capture that traffic.
Here's a log using the xmldebugger.
This is a snippet of log from an Openfire with the modified Monitoring plugin with additional logging.
We have found various factors contributing to this. The primary cause seems to be that the stanza that is triggering a MUC event on a junior cluster member does not get transferred to the senior cluster member (that takes responsibility for processing the event).
Tested on Guus' branch, and can no longer reproduce the issue