mod_mam with multisession issue

[DarkSideF]

I have configured ejabberd 14.12 server with enabled multisession and working mod_mam (XEP-0313 v0.2, https://github.com/kongo2002/ejabberd-mod-mam, http://xmpp.org/extensions/attic/xep-0313-0.2.html)

mod_mam works great when i send message from user with one connected session to different user with one session

However if user-1@example has 2 online sessions with different resources and user-2@example sends to user-1@example (to bare JID) one message - mod_mam saves two messages

ejabberd log:

<0.708.0>@ejabberd_http_bind:http_put:792 Looking for session: <<"2a16b709927907352b5696d8c7fbb4bdc641c736">>
<0.606.0>@ejabberd_http_bind:handle_sync_event:440 New request: {http_put,152025,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"152025">>},{<<"sid">>,<<"2a16b709927907352b5696d8c7fbb4bdc641c736">>},{<<"key">>,<<"e9815d19f02d2ca9249209cdd82c818fae01b821">>}],[{xmlel,<<"message">>,[{<<"xmlns">>,<<"jabber:client">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"2-222">>}]}]}],251,1,<<>>,{{10,0,2,2},49075}}
<0.606.0>@ejabberd_http_bind:handle_http_put_event:575 New request: {http_put,152025,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"152025">>},{<<"sid">>,<<"2a16b709927907352b5696d8c7fbb4bdc641c736">>},{<<"key">>,<<"e9815d19f02d2ca9249209cdd82c818fae01b821">>}],[{xmlel,<<"message">>,[{<<"xmlns">>,<<"jabber:client">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"2-222">>}]}]}],251,1,<<>>,{{10,0,2,2},49075}}
<0.606.0>@ejabberd_http_bind:rid_allow:866 Previous rid / New rid: 152024/152025
<0.606.0>@ejabberd_http_bind:process_http_put:608 Actually processing request: {http_put,152025,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"152025">>},{<<"sid">>,<<"2a16b709927907352b5696d8c7fbb4bdc641c736">>},{<<"key">>,<<"e9815d19f02d2ca9249209cdd82c818fae01b821">>}],[{xmlel,<<"message">>,[{<<"xmlns">>,<<"jabber:client">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"2-222">>}]}]}],251,1,<<>>,{{10,0,2,2},49075}}
<0.606.0>@ejabberd_http_bind:process_http_put:619 Key/OldKey/NextKey: e9815d19f02d2ca9249209cdd82c818fae01b821/4b0850aed0c7d411c41f28c041f0e176db7cf4d7/4b0850aed0c7d411c41f28c041f0e176db7cf4d7
<0.606.0>@ejabberd_http_bind:process_http_put:659  -- SaveKey: e9815d19f02d2ca9249209cdd82c818fae01b821
<0.606.0>@ejabberd_http_bind:process_http_put:671 reqlist: [{hbr,152025,<<"4b0850aed0c7d411c41f28c041f0e176db7cf4d7">>,[]},{hbr,152024,<<"882220e875a29152d9b15510b8673137e8360e42">>,[]}]
<0.606.0>@ejabberd_http_bind:process_http_put:717 really sending now: [{xmlel,<<"message">>,[{<<"xmlns">>,<<"jabber:client">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"2-222">>}]}]}]
<0.607.0>@ejabberd_router:do_route:322 route
    from {jid,<<"user-2">>,<<"ch">>,<<"ch_jsjac">>,<<"user-2">>,<<"ch">>,<<"ch_jsjac">>}
    to {jid,<<"user-1">>,<<"ch">>,<<>>,<<"user-1">>,<<"ch">>,<<>>}
    packet {xmlel,<<"message">>,[{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"2-222">>}]}]}
<0.496.0>@mod_mam:handle_cast:313 Packet: {xmlel,<<"message">>,[{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"2-222">>}]}]}
<0.607.0>@ejabberd_local:do_route:296 local route
    from {jid,<<"user-2">>,<<"ch">>,<<"ch_jsjac">>,<<"user-2">>,<<"ch">>,<<"ch_jsjac">>}
    to {jid,<<"user-1">>,<<"ch">>,<<>>,<<"user-1">>,<<"ch">>,<<>>}
    packet {xmlel,<<"message">>,[{<<"to">>,<<"user"...>>},{<<"type">>,<<...>>}],[{xmlel,<<...>>,...}]}
<0.607.0>@ejabberd_sm:do_route:514 session manager
    from {jid,<<"user-2">>,<<"ch">>,<<"ch_jsjac">>,<<"user-2">>,<<"ch">>,<<"ch_jsjac">>}
    to {jid,<<"user-1">>,<<"ch">>,<<>>,<<"user-1">>,<<"ch">>,<<>>}
    packet {xmlel,<<"message">>,[{<<"to">>,<<"user"...>>},{<<"type">>,<<...>>}],[{xmlel,<<...>>,...}]}
<0.607.0>@ejabberd_sm:route_message:658 sending to process <0.586.0>
<0.607.0>@ejabberd_sm:route_message:658 sending to process <0.649.0>
<0.615.0>@ejabberd_http_bind:prepare_response:914 OutPacket: [{xmlstreamelement,{xmlel,<<"message">>,[{<<"from">>,<<"user-2@example/ch_jsjac">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"2-222">>}]}]}}]
<0.615.0>@ejabberd_http_bind:send_outpacket:1056  --- outgoing data --- 
<body xmlns='http://jabber.org/protocol/httpbind'><message xmlns='jabber:client' from='user-2@example/ch_jsjac' to='user-1@example' type='chat'><body>2-222</body></message></body>
 --- END --- 
<0.580.0>@ejabberd_http_bind:prepare_response:914 OutPacket: [{xmlstreamelement,{xmlel,<<"message">>,[{<<"from">>,<<"user-2@example/ch_jsjac">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"2-222">>}]}]}}]
<0.580.0>@ejabberd_http_bind:send_outpacket:1056  --- outgoing data --- 
<body xmlns='http://jabber.org/protocol/httpbind'><message xmlns='jabber:client' from='user-2@example/ch_jsjac' to='user-1@example' type='chat'><body>2-222</body></message></body>
 --- END --- 
<0.496.0>@mod_mam:handle_cast:313 Packet: {xmlel,<<"message">>,[{<<"from">>,<<"user-2@example/ch_jsjac">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"2-222">>}]}]}
<0.496.0>@mod_mam:handle_cast:313 Packet: {xmlel,<<"message">>,[{<<"from">>,<<"user-2@example/ch_jsjac">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"2-222">>}]}]}

We can see double 'handle_cast' from mod_mam.

When i querying messages from archive i got something like this:

<message xmlns='jabber:client' from='user-1@example' to='user-1@example/42114606331421936688301010'>
    <result xmlns='urn:xmpp:mam:tmp' id='54C104E31E374104E800009B'>
        <forwarded xmlns='urn:xmpp:forward:0'>
            <delay xmlns='urn:xmpp:delay' stamp='2015-01-22T14:10:43Z'/>
            <message from='user-2@example/8658298161421935653320719' to='user-1@example' type='chat'>
                <body>
                    2-222
                </body>
            </message>
        </forwarded>
    </result>
</message>
<message xmlns='jabber:client' from='user-1@example' to='user-1@example/42114606331421936688301010'>
    <result xmlns='urn:xmpp:mam:tmp' id='54C104E31E374104E800009C'>
        <forwarded xmlns='urn:xmpp:forward:0'>
        <delay xmlns='urn:xmpp:delay' stamp='2015-01-22T14:10:43Z'/>
            <message from='user-2@example/8658298161421935653320719' to='user-1@example' type='chat'>
                <body>
                    2-222
                </body>
            </message>
        </forwarded>
    </result>
</message>

But i want receive only one message without duplicate.

Similarly if user-1@example has 3 online sessions with different resources and user-2@example sends to user-1@example (to bare JID) one message - mod_mam saves two messages. ejabberd log:

<0.690.0>@ejabberd_http_bind:http_put:792 Looking for session: <<"2a16b709927907352b5696d8c7fbb4bdc641c736">>
<0.606.0>@ejabberd_http_bind:handle_sync_event:440 New request: {http_put,151909,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"151909">>},{<<"sid">>,<<"2a16b709927907352b5696d8c7fbb4bdc641c736">>},{<<"key">>,<<"97451cccc5e5f52563e625169fbc6fecc17ae950">>}],[{xmlel,<<"message">>,[{<<"xmlns">>,<<"jabber:client">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"3-333">>}]}]}],251,1,<<>>,{{10,0,2,2},47540}}
<0.606.0>@ejabberd_http_bind:handle_http_put_event:575 New request: {http_put,151909,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"151909">>},{<<"sid">>,<<"2a16b709927907352b5696d8c7fbb4bdc641c736">>},{<<"key">>,<<"97451cccc5e5f52563e625169fbc6fecc17ae950">>}],[{xmlel,<<"message">>,[{<<"xmlns">>,<<"jabber:client">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"3-333">>}]}]}],251,1,<<>>,{{10,0,2,2},47540}}
<0.606.0>@ejabberd_http_bind:rid_allow:866 Previous rid / New rid: 151908/151909
<0.606.0>@ejabberd_http_bind:process_http_put:608 Actually processing request: {http_put,151909,[{<<"xmlns">>,<<"http://jabber.org/protocol/httpbind">>},{<<"rid">>,<<"151909">>},{<<"sid">>,<<"2a16b709927907352b5696d8c7fbb4bdc641c736">>},{<<"key">>,<<"97451cccc5e5f52563e625169fbc6fecc17ae950">>}],[{xmlel,<<"message">>,[{<<"xmlns">>,<<"jabber:client">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"3-333">>}]}]}],251,1,<<>>,{{10,0,2,2},47540}}
<0.606.0>@ejabberd_http_bind:process_http_put:619 Key/OldKey/NextKey: 97451cccc5e5f52563e625169fbc6fecc17ae950/17ba9df4939c3fbd9c7f5021af54e4edb6d11496/17ba9df4939c3fbd9c7f5021af54e4edb6d11496
<0.606.0>@ejabberd_http_bind:process_http_put:659  -- SaveKey: 97451cccc5e5f52563e625169fbc6fecc17ae950
<0.606.0>@ejabberd_http_bind:process_http_put:671 reqlist: [{hbr,151909,<<"17ba9df4939c3fbd9c7f5021af54e4edb6d11496">>,[]},{hbr,151908,<<"7a3ebe3b5639ddcc6f73e004c58966e21364257d">>,[]}]
<0.606.0>@ejabberd_http_bind:process_http_put:717 really sending now: [{xmlel,<<"message">>,[{<<"xmlns">>,<<"jabber:client">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"3-333">>}]}]}]
<0.607.0>@ejabberd_router:do_route:322 route
    from {jid,<<"user-2">>,<<"ch">>,<<"ex_jsjac">>,<<"user-2">>,<<"ch">>,<<"ex_jsjac">>}
    to {jid,<<"user-1">>,<<"ch">>,<<>>,<<"user-1">>,<<"ch">>,<<>>}
    packet {xmlel,<<"message">>,[{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"3-333">>}]}]}
<0.496.0>@mod_mam:handle_cast:313 Packet: {xmlel,<<"message">>,[{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"3-333">>}]}]}
<0.607.0>@ejabberd_local:do_route:296 local route
    from {jid,<<"user-2">>,<<"ch">>,<<"ex_jsjac">>,<<"user-2">>,<<"ch">>,<<"ex_jsjac">>}
    to {jid,<<"user-1">>,<<"ch">>,<<>>,<<"user-1">>,<<"ch">>,<<>>}
    packet {xmlel,<<"message">>,[{<<"to">>,<<"user"...>>},{<<"type">>,<<...>>}],[{xmlel,<<...>>,...}]}
<0.607.0>@ejabberd_sm:do_route:514 session manager
    from {jid,<<"user-2">>,<<"ch">>,<<"ex_jsjac">>,<<"user-2">>,<<"ch">>,<<"ex_jsjac">>}
    to {jid,<<"user-1">>,<<"ch">>,<<>>,<<"user-1">>,<<"ch">>,<<>>}
    packet {xmlel,<<"message">>,[{<<"to">>,<<"user"...>>},{<<"type">>,<<...>>}],[{xmlel,<<...>>,...}]}
<0.607.0>@ejabberd_sm:route_message:658 sending to process <0.586.0>
<0.607.0>@ejabberd_sm:route_message:658 sending to process <0.649.0>
<0.607.0>@ejabberd_sm:route_message:658 sending to process <0.683.0>
<0.615.0>@ejabberd_http_bind:prepare_response:914 OutPacket: [{xmlstreamelement,{xmlel,<<"message">>,[{<<"from">>,<<"user-2@example/ex_jsjac">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"3-333">>}]}]}}]
<0.615.0>@ejabberd_http_bind:send_outpacket:1056  --- outgoing data --- 
<body xmlns='http://jabber.org/protocol/httpbind'><message xmlns='jabber:client' from='user-2@example/ex_jsjac' to='user-1@example' type='chat'><body>3-333</body></message></body>
 --- END --- 
<0.580.0>@ejabberd_http_bind:prepare_response:914 OutPacket: [{xmlstreamelement,{xmlel,<<"message">>,[{<<"from">>,<<"user-2@example/ex_jsjac">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"3-333">>}]}]}}]
<0.580.0>@ejabberd_http_bind:send_outpacket:1056  --- outgoing data --- 
<body xmlns='http://jabber.org/protocol/httpbind'><message xmlns='jabber:client' from='user-2@example/ex_jsjac' to='user-1@example' type='chat'><body>3-333</body></message></body>
 --- END --- 
<0.686.0>@ejabberd_http_bind:prepare_response:914 OutPacket: [{xmlstreamelement,{xmlel,<<"message">>,[{<<"from">>,<<"user-2@example/ex_jsjac">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"3-333">>}]}]}}]
<0.686.0>@ejabberd_http_bind:send_outpacket:1056  --- outgoing data --- 
<body xmlns='http://jabber.org/protocol/httpbind'><message xmlns='jabber:client' from='user-2@example/ex_jsjac' to='user-1@example' type='chat'><body>3-333</body></message></body>
 --- END --- 
<0.496.0>@mod_mam:handle_cast:313 Packet: {xmlel,<<"message">>,[{<<"from">>,<<"user-2@example/ex_jsjac">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"3-333">>}]}]}
<0.496.0>@mod_mam:handle_cast:313 Packet: {xmlel,<<"message">>,[{<<"from">>,<<"user-2@example/ex_jsjac">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"3-333">>}]}]}
<0.496.0>@mod_mam:handle_cast:313 Packet: {xmlel,<<"message">>,[{<<"from">>,<<"user-2@example/ex_jsjac">>},{<<"to">>,<<"user-1@example">>},{<<"type">>,<<"chat">>}],[{xmlel,<<"body">>,[],[{xmlcdata,<<"3-333">>}]}]}
<0.580.0>@ejabberd_http:process_header:283 (#Port<0.5639>) http query: 'POST' /http-bind/
<0.580.0>@ejabberd_http:process_request:448 client data: <<"<body rid='568139' sid='fd0a27af99432dc8b6a252ce6dc87e35da715cc1' xmlns='http://jabber.org/protocol/httpbind' key='f4967d3d77af57b2c35847986de0720b8ad6215c' > </body>">>
<0.580.0>@ejabberd_http:process:359 [<<"http-bind">>] matches [<<"http-bind">>]
<0.580.0>@ejabberd_http:process:363 [{'Accept-Language',<<"ru-RU,ru;q=0.8,en-US;q=0.6,en;q=0.4">>},{'Accept-Encoding',<<"gzip, deflate">>},{'Referer',<<"http://localhost:3000/profile">>},{'Accept',<<"*/*">>},{'Content-Type',<<"text/xml; charset=UTF-8">>},{'User-Agent',<<"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.99 Safari/537.36">>},{<<"Origin">>,<<"http://localhost:3000">>},{'Content-Length',<<"166">>},{'Connection',<<"keep-alive">>},{'Host',<<"localhost:5280">>}]
<0.580.0>@mod_http_bind:process:68 Incoming data: <body rid='568139' sid='fd0a27af99432dc8b6a252ce6dc87e35da715cc1' xmlns='http://jabber.org/protocol/httpbind' key='f4967d3d77af57b2c35847986de0720b8ad6215c' > </body>
<0.580.0>@ejabberd_http_bind:parse_request:1128 --- incoming data --- 
<body rid='568139' sid='fd0a27af99432dc8b6a252ce6dc87e35da715cc1' xmlns='http://jabber.org/protocol/httpbind' key='f4967d3d77af57b2c35847986de0720b8ad6215c' > </body>

Questions:

1. It is normal behaviour for mod_mam(XEP-0313) or bug of module?
2. How i may fix it?

[kongo2002]

Hi, it does not sound too right although I am not sure what you mean with multisession exactly? What configuration is that? Then I will have to look into this issue further. As long as only one message get 'delivered' I would say that the module should store only one message too.

Cheers, Gregor

[DarkSideF]

Speaking of multisession I mean user who logged from different devices or browsers with one jabber account. i.e. same bare JID with different resources

That make this possible in my ejabberd config i set resource_conflict: setresource (http://www.process-one.net/docs/ejabberd/guide_en.html, 3.1.5 Authentication)

I also asked this question on StackOverflow: http://stackoverflow.com/questions/28093418/ejabberd-14-12-mod-mam-multisession-issue

[DarkSideF]

I think this problem is resolved in fork for your module: https://github.com/sdcr/ejabberd-mod-mam/commit/d7be032bf8153d093bbd02dc2812c2e51a9a3cc2

As I understand it you should not use user_receive_packet ejabberd hook because that save message after server route it to all user resources

Example: I send message to bare JID, who have 3 online resources. Server router send it to each JID resource and we have triple user_receive_packet And module saves 3 messages, but i send only one

[alexpetroaica]

Was this ever solved? I am running ejabberd 15.07 and it behaves the same way.