Skip to content

MUC messages duplicated as DMs #137

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
Fishbowler opened this issue Nov 27, 2020 · 12 comments
Closed

MUC messages duplicated as DMs #137

Fishbowler opened this issue Nov 27, 2020 · 12 comments

Comments

@Fishbowler
Copy link
Member

Fishbowler commented Nov 27, 2020

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?)

@Fishbowler
Copy link
Member Author

Fishbowler commented Nov 27, 2020

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="[email protected]/Spark 2.8.3.579" id="2ZjfZ-114" type="groupchat" from="[email protected]/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="[email protected]"/>
    <addresses xmlns="http://jabber.org/protocol/address">
        <address type="ofrom" jid="[email protected]"/>
    </addresses>
</message>

But instead gets one that looks like this:

<message from="[email protected]" to="[email protected]" 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).

@guusdk
Copy link
Member

guusdk commented Nov 30, 2020

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.

@guusdk
Copy link
Member

guusdk commented Nov 30, 2020

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 [email protected] converse.js-114026539 [email protected] 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 [email protected] converse.js-27557185 [email protected] user2 1606729430236 null this was sent by user2 that is connected to the junior cluster node!

@guusdk
Copy link
Member

guusdk commented Nov 30, 2020

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	[email protected]	converse.js-38025516	[email protected]	user1	1606751465422	<message from="[email protected]/user1" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3" to="[email protected]" 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="[email protected]"/><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="[email protected]"/></addresses></message>	This was sent by user 1 in mucOne on xmpp1, which is the senior cluster node.
2	1	[email protected]	converse.js-33213578	[email protected]	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='[email protected]'>
  <query xmlns='urn:xmpp:mam:2' queryid='f27' />
</iq>

Responses:

<message to="[email protected]/Spark 2.9.5-SNAPSHOT" from="[email protected]"><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="[email protected]"><subject/></message></forwarded></result></message>
<message to="[email protected]/Spark 2.9.5-SNAPSHOT" from="[email protected]"><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="[email protected]/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="[email protected]"></stanza-id><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="[email protected]"/></addresses></message></forwarded></result></message>
<message to="[email protected]/Spark 2.9.5-SNAPSHOT" from="[email protected]"><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="[email protected]/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="[email protected]"></stanza-id><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="[email protected]"/></addresses></message></forwarded></result></message>
<iq type="result" id="1" from="[email protected]" to="[email protected]/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="[email protected]/converse.js-38025516" to="[email protected]"><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="[email protected]/converse.js-33213578" to="[email protected]"><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='[email protected]'>
  <query xmlns='urn:xmpp:mam:2' queryid='f27' />
</iq>

Responses

<message to="[email protected]/Spark 2.9.5-SNAPSHOT" from="[email protected]"><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="[email protected]"><subject/></message></forwarded></result></message>
<message to="[email protected]/Spark 2.9.5-SNAPSHOT" from="[email protected]"><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="[email protected]/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="[email protected]"></stanza-id><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="[email protected]"/></addresses></message></forwarded></result></message>
<message to="[email protected]/Spark 2.9.5-SNAPSHOT" from="[email protected]"><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="[email protected]/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="[email protected]"></stanza-id><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="[email protected]"/></addresses></message></forwarded></result></message>
<iq type="result" id="a" from="[email protected]" to="[email protected]/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='[email protected]/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="[email protected]/user1" to="[email protected]/Spark 2.9.5-SNAPSHOT"><x xmlns="http://jabber.org/protocol/muc#user"><item jid="[email protected]/converse.js-38025516" affiliation="none" role="participant"/></x></presence>
<presence from="[email protected]/user2" to="[email protected]/Spark 2.9.5-SNAPSHOT"><x xmlns="http://jabber.org/protocol/muc#user"><item jid="[email protected]/converse.js-33213578" affiliation="none" role="participant"/></x></presence>
<presence to="[email protected]/Spark 2.9.5-SNAPSHOT" id="9YZWD-130" from="[email protected]/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="[email protected]/Spark 2.9.5-SNAPSHOT" affiliation="none" role="participant"/><status code="110"/><status code="100"/></x></presence>
<message from="[email protected]/user1" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3" to="[email protected]/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="[email protected]"/><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="[email protected]"/></addresses><delay xmlns="urn:xmpp:delay" stamp="2020-11-30T15:51:05.425Z" from="[email protected]/converse.js-38025516"/></message>
<message from="[email protected]/user2" id="ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76" to="[email protected]/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="[email protected]"/><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="[email protected]"/></addresses><delay xmlns="urn:xmpp:delay" stamp="2020-11-30T15:51:19.043Z" from="[email protected]/converse.js-33213578"/></message>
<message type="groupchat" from="[email protected]" to="[email protected]/Spark 2.9.5-SNAPSHOT"><subject></subject><delay xmlns="urn:xmpp:delay" stamp="2020-11-12T15:00:16.988Z" from="[email protected]"/></message>

Joining (through the UI) mucOne, using user3 connected to xmpp1 / senior cluster node:

<presence to='[email protected]/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="[email protected]/user1" to="[email protected]/Spark 2.9.5-SNAPSHOT"><x xmlns="http://jabber.org/protocol/muc#user"><item jid="[email protected]/converse.js-38025516" affiliation="none" role="participant"/></x></presence>
<presence from="[email protected]/user2" to="[email protected]/Spark 2.9.5-SNAPSHOT"><x xmlns="http://jabber.org/protocol/muc#user"><item jid="[email protected]/converse.js-33213578" affiliation="none" role="participant"/></x></presence>
<presence to="[email protected]/Spark 2.9.5-SNAPSHOT" id="xApsj-125" from="[email protected]/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="[email protected]/Spark 2.9.5-SNAPSHOT" affiliation="none" role="participant"/><status code="110"/><status code="100"/></x></presence>
<message from="[email protected]/user1" id="4db18e15-5eaf-4794-ad3d-ec247b9982b3" to="[email protected]/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="[email protected]"/><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="[email protected]"/></addresses><delay xmlns="urn:xmpp:delay" stamp="2020-11-30T15:51:05.423Z" from="[email protected]/converse.js-38025516"/></message>
<message from="[email protected]/user2" id="ef03fb1f-51c6-44c5-8bc0-29cb06c6bd76" to="[email protected]/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="[email protected]"/><addresses xmlns="http://jabber.org/protocol/address"><address type="ofrom" jid="[email protected]"/></addresses><delay xmlns="urn:xmpp:delay" stamp="2020-11-30T15:51:19.044Z" from="[email protected]/converse.js-33213578"/></message>
<message type="groupchat" from="[email protected]" to="[email protected]/Spark 2.9.5-SNAPSHOT"><subject></subject><delay xmlns="urn:xmpp:delay" stamp="2020-11-12T15:00:16.988Z" from="[email protected]"/></message>

@Fishbowler
Copy link
Member Author

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? 🤷‍♂️

@guusdk
Copy link
Member

guusdk commented Nov 30, 2020

I was using the same MUC both times

I did that too, but wrote it down incorrectly. I have now modified my comment above.

@guusdk
Copy link
Member

guusdk commented Dec 1, 2020

I wonder if I need some traffic interception?

Let's try that. The xmldebugger plugin should help us capture that traffic.

@Fishbowler
Copy link
Member Author

xmllog.txt

Here's a log using the xmldebugger.

@Fishbowler
Copy link
Member Author

oflog_withextras.txt

This is a snippet of log from an Openfire with the modified Monitoring plugin with additional logging.

@guusdk
Copy link
Member

guusdk commented Dec 1, 2020

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).

guusdk added a commit to guusdk/openfire-monitoring-plugin that referenced this issue Dec 1, 2020
As the senior node is responsible for processing cluster events related, that node needs to have all available data to operate on. By making available the original stanza, this stanza can be persisted in the database. This in turn prevents an inpresice reproduction from being used when the corresponding message archive is used at some point later in the future.
guusdk added a commit to guusdk/openfire-monitoring-plugin that referenced this issue Dec 1, 2020
As the senior node is responsible for processing cluster events related, that node needs to have all available data to operate on. By making available the original stanza, this stanza can be persisted in the database. This in turn prevents an inpresice reproduction from being used when the corresponding message archive is used at some point later in the future.
guusdk added a commit to guusdk/openfire-monitoring-plugin that referenced this issue Dec 1, 2020
As the senior node is responsible for processing cluster events related, that node needs to have all available data to operate on. By making available the original stanza, this stanza can be persisted in the database. This in turn prevents an inpresice reproduction from being used when the corresponding message archive is used at some point later in the future.
@Fishbowler
Copy link
Member Author

Tested on Guus' branch, and can no longer reproduce the issue

guusdk added a commit to guusdk/openfire-monitoring-plugin that referenced this issue Dec 4, 2020
…cluster

It is important to assign a message ID, which is used for ordering messages in a conversation, soon
after the message arrived, as opposed to just before the message gets written to the database. In the latter
scenario, the message ID values might no longer reflect the order of the messages in a conversation, as
database writes are batched up together for performance reasons. Using these batches won't affect the
database-insertion order (as compared to the order of messages in the conversation) on a single Openfire
server, but when running in a cluster, these batches do have a good chance to mess up the order of things.
@guusdk
Copy link
Member

guusdk commented Dec 4, 2020

Turns out that this issue is pretty much a duplicate of #19

guusdk added a commit to guusdk/openfire-monitoring-plugin that referenced this issue Dec 4, 2020
@guusdk guusdk closed this as completed in 0ccb74f Dec 8, 2020
guusdk added a commit that referenced this issue Dec 8, 2020
It is important to assign a message ID, which is used for ordering messages in a conversation, soon
after the message arrived, as opposed to just before the message gets written to the database. In the latter
scenario, the message ID values might no longer reflect the order of the messages in a conversation, as
database writes are batched up together for performance reasons. Using these batches won't affect the
database-insertion order (as compared to the order of messages in the conversation) on a single Openfire
server, but when running in a cluster, these batches do have a good chance to mess up the order of things.
guusdk added a commit that referenced this issue Dec 8, 2020
With issue #137 fixed, issue #19 can be closed.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants