#996 MAM stores/ delivers only own messages, those of partner missing
Reporter
Trolli Schmittlauch
Owner
Zash
Created
Updated
Stars
★ (1)
Tags
Status-Fixed
Type-Defect
Priority-Medium
Trolli Schmittlauch
on
What steps will reproduce the problem?
1. Exchange chat messages with a contact (both directions) while the second client is offline.
2. Go online with another client.
3. Look which messages from the conversation at 1. appear in this 2nd client.
What is the expected output?
The 2nd client should get both the own sent messages and the received (from chatpartner) messages via MAM.
What do you see instead?
Only the own sent messages appear, the ones received from chat partner are missing.
What version of the product are you using? On what operating system?
prosod-0.9.12 on openSUSE 42.2, mod_mam (latest changeset in hg log: 2762:f2096c03428b)
Please provide any additional information below.
in the debuglog of prosody lines like
example.com:mam debug Archive query nil completed
appear.
I can reproduce this behaviour with dino (commit 54a25fd926070a977138cec94908c55806e22f4a) and gajim-0.16.16 in both roles.
From the dino logs:
```
XMPP OUT
<{jabber:client}:iq {jabber:client}:id='355fa298-6a95-4a86-b0f7-f25f4c10be87' {jabber:client}:type='set'>
<{urn:xmpp:mam:2}:query {http://www.w3.org/2000/xmlns/}:xmlns='urn:xmpp:mam:2'>
<{jabber:x:data}:x {http://www.w3.org/2000/xmlns/}:xmlns='jabber:x:data' {jabber:x:data}:type='submit'>
<{jabber:x:data}:field {jabber:x:data}:type='hidden' {jabber:x:data}:var='FORM_TYPE'>
<{jabber:x:data}:value>
urn:xmpp:mam:2
</{jabber:x:data}:value>
</{jabber:x:data}:field>
<{jabber:x:data}:field {jabber:x:data}:var='start'>
<{jabber:x:data}:value>
2017-09-20T12:16:46Z
</{jabber:x:data}:value>
</{jabber:x:data}:field>
</{jabber:x:data}:x>
</{urn:xmpp:mam:2}:query>
</{jabber:client}:iq>
--- snip ---
<{jabber:client}:message {jabber:client}:to='a@example.com/dino.4bd4e32'>
<{urn:xmpp:mam:2}:result {urn:xmpp:mam:2}:id='4b8f73da-b1ee-4aca-8e41-01a5594768de' {http://www.w3.org/2000/xmlns/}:xmlns='urn:xmpp:mam:2'>
<{urn:xmpp:forward:0}:forwarded {http://www.w3.org/2000/xmlns/}:xmlns='urn:xmpp:forward:0'>
<{urn:xmpp:delay}:delay {urn:xmpp:delay}:stamp='2017-09-21T12:39:32Z' {http://www.w3.org/2000/xmlns/}:xmlns='urn:xmpp:delay' />
<{jabber:client}:message {jabber:client}:type='chat' {jabber:client}:to='b@example.com/Gajim' {jabber:client}:from='a@example.com/Gajim' {jabber:client}:id='8e677984-ed33-47bf-b8b2-17f81f248392' {http://www.w3.org/2000/xmlns/}:xmlns='jabber:client'>
<{jabber:client}:body>
from A to B
</{jabber:client}:body>
<{http://jabber.org/protocol/chatstates}:active {http://www.w3.org/2000/xmlns/}:xmlns='http://jabber.org/protocol/chatstates' />
<{urn:xmpp:receipts}:request {http://www.w3.org/2000/xmlns/}:xmlns='urn:xmpp:receipts' />
<{jabber:client}:thread>
puHTTdpDvSuGcgTigoDRlDbfpITpwcOr
</{jabber:client}:thread>
</{jabber:client}:message>
</{urn:xmpp:forward:0}:forwarded>
</{urn:xmpp:mam:2}:result>
</{jabber:client}:message>
```
Zash
on
Thanks for the report. This issue was hard to reproduce and appeared randomly under certain conditions. It looks like it boils down to a priority conflict, with both mod_mam and mod_message hooking incoming messages at the same priority, so which one gets it first may be essentially random. If mod_message gets it first, it sends it out to the client and marks the event completed. For some reason I'm only able to reproduce while mod_privacy is also loaded.
What steps will reproduce the problem? 1. Exchange chat messages with a contact (both directions) while the second client is offline. 2. Go online with another client. 3. Look which messages from the conversation at 1. appear in this 2nd client. What is the expected output? The 2nd client should get both the own sent messages and the received (from chatpartner) messages via MAM. What do you see instead? Only the own sent messages appear, the ones received from chat partner are missing. What version of the product are you using? On what operating system? prosod-0.9.12 on openSUSE 42.2, mod_mam (latest changeset in hg log: 2762:f2096c03428b) Please provide any additional information below. in the debuglog of prosody lines like example.com:mam debug Archive query nil completed appear. I can reproduce this behaviour with dino (commit 54a25fd926070a977138cec94908c55806e22f4a) and gajim-0.16.16 in both roles. From the dino logs: ``` XMPP OUT <{jabber:client}:iq {jabber:client}:id='355fa298-6a95-4a86-b0f7-f25f4c10be87' {jabber:client}:type='set'> <{urn:xmpp:mam:2}:query {http://www.w3.org/2000/xmlns/}:xmlns='urn:xmpp:mam:2'> <{jabber:x:data}:x {http://www.w3.org/2000/xmlns/}:xmlns='jabber:x:data' {jabber:x:data}:type='submit'> <{jabber:x:data}:field {jabber:x:data}:type='hidden' {jabber:x:data}:var='FORM_TYPE'> <{jabber:x:data}:value> urn:xmpp:mam:2 </{jabber:x:data}:value> </{jabber:x:data}:field> <{jabber:x:data}:field {jabber:x:data}:var='start'> <{jabber:x:data}:value> 2017-09-20T12:16:46Z </{jabber:x:data}:value> </{jabber:x:data}:field> </{jabber:x:data}:x> </{urn:xmpp:mam:2}:query> </{jabber:client}:iq> --- snip --- <{jabber:client}:message {jabber:client}:to='a@example.com/dino.4bd4e32'> <{urn:xmpp:mam:2}:result {urn:xmpp:mam:2}:id='4b8f73da-b1ee-4aca-8e41-01a5594768de' {http://www.w3.org/2000/xmlns/}:xmlns='urn:xmpp:mam:2'> <{urn:xmpp:forward:0}:forwarded {http://www.w3.org/2000/xmlns/}:xmlns='urn:xmpp:forward:0'> <{urn:xmpp:delay}:delay {urn:xmpp:delay}:stamp='2017-09-21T12:39:32Z' {http://www.w3.org/2000/xmlns/}:xmlns='urn:xmpp:delay' /> <{jabber:client}:message {jabber:client}:type='chat' {jabber:client}:to='b@example.com/Gajim' {jabber:client}:from='a@example.com/Gajim' {jabber:client}:id='8e677984-ed33-47bf-b8b2-17f81f248392' {http://www.w3.org/2000/xmlns/}:xmlns='jabber:client'> <{jabber:client}:body> from A to B </{jabber:client}:body> <{http://jabber.org/protocol/chatstates}:active {http://www.w3.org/2000/xmlns/}:xmlns='http://jabber.org/protocol/chatstates' /> <{urn:xmpp:receipts}:request {http://www.w3.org/2000/xmlns/}:xmlns='urn:xmpp:receipts' /> <{jabber:client}:thread> puHTTdpDvSuGcgTigoDRlDbfpITpwcOr </{jabber:client}:thread> </{jabber:client}:message> </{urn:xmpp:forward:0}:forwarded> </{urn:xmpp:mam:2}:result> </{jabber:client}:message> ```
Thanks for the report. This issue was hard to reproduce and appeared randomly under certain conditions. It looks like it boils down to a priority conflict, with both mod_mam and mod_message hooking incoming messages at the same priority, so which one gets it first may be essentially random. If mod_message gets it first, it sends it out to the client and marks the event completed. For some reason I'm only able to reproduce while mod_privacy is also loaded.
ChangesShould be fixed in https://hg.prosody.im/prosody-modules/rev/2af42a3af131 but please verify.
Changes