Outcoming chat messages are not always stored in archive

[gsohn]

Environment

• ejabberd version: 20.07

Configuration

  mod_mam:         
    db_type: sql
    assume_mam_usage: true
    default: always                                       
    user_mucsub_from_muc_archive: true                  
    request_activates_archiving: false   

Only incoming chat messages are stored in archive table when we send messages with ejabberd send_message command and/or send_message API endpoint.

The outcoming chat messages are only stored when the from user has an active session.

[badlop]

I am not able to reproduce that problem. I installed ejabberd from git master (there aren't changes in mod_mam.erl since long ago), configured mod_mam like you showed, registered two accounts user1 and user2, logged in both accounts with two clients, send a few messages, and their messages are stored in the "archive" table.

Then, with both clients still connected, I use this command, and both outgoing and incoming messages are stored: $ ejabberdctl send_message chat user1@localhost user2@localhost SSS BBBXXX

Finally I close both clients, and execute again that command. In the database, I see both outgoing and incoming messages are stored.

Do you see anything relevant in the ejabberd log files?

[gsohn]

Thanks for your test!

We also tested with two new registered users (created with the register command), and the incoming and outcoming are stored correctly, you're right.

It seems the problem only occurs with our user using JWT as authentication (who doesn't exist in the users table...).

[gsohn]

Here's the log output we have when only the incoming message is stored in mam :

There is an error when for incoming message:

sub_els = [#stanza_error{type = cancel,code = 503,by = undefined,
                                  reason = 'service-unavailable',text = [],
                                  sub_els = []}],

2020-09-02 19:33:15.051949+00:00 [debug] <0.453.0>@ejabberd_access_permissions:handle_call/3:108 Command 'send_message' execution allowed by rule 'console commands' (CallerInfo=#{caller_module =>
                                                                                      ejabberd_ctl})
2020-09-02 19:33:15.052207+00:00 [debug] <0.2979.0>@ejabberd_commands:do_execute_command/2:250 Executing command mod_admin_extra:send_message with Args=[<<"chat">>,
                                                          <<"btzfegzuncjy0r.1577630574592@im.XXXX.XX">>,
                                                          <<"dhzt2fohhghfr9.1577630219046@im.XXXX.XX">>,
                                                          <<>>,<<"21h33">>]
2020-09-02 19:33:15.052458+00:00 [debug] <0.2979.0>@ejabberd_hooks:safe_apply/4:231 Running hook user_send_packet: mod_privacy:user_send_packet/1
2020-09-02 19:33:15.052593+00:00 [debug] <0.2979.0>@ejabberd_hooks:safe_apply/4:231 Running hook user_send_packet: mod_vcard_xupdate:user_send_packet/1
2020-09-02 19:33:15.052691+00:00 [debug] <0.2979.0>@ejabberd_hooks:safe_apply/4:231 Running hook user_send_packet: mod_caps:user_send_packet/1
2020-09-02 19:33:15.052815+00:00 [debug] <0.2979.0>@ejabberd_hooks:safe_apply/4:231 Running hook user_send_packet: mod_mam:user_send_packet/1
2020-09-02 19:33:15.058429+00:00 [debug] <0.2979.0>@ejabberd_hooks:safe_apply/4:231 Running hook store_mam_message: mod_push:mam_message/7
2020-09-02 19:33:15.063492+00:00 [debug] <0.2979.0>@ejabberd_hooks:safe_apply/4:231 Running hook store_mam_message: mod_mam:store_mam_message/7
2020-09-02 19:33:15.067665+00:00 [debug] <0.2979.0>@ejabberd_hooks:safe_apply/4:231 Running hook user_send_packet: mod_carboncopy:user_send_packet/1
2020-09-02 19:33:15.067831+00:00 [debug] <0.2979.0>@ejabberd_hooks:safe_apply/4:231 Running hook user_send_packet: mod_mam:user_send_packet_strip_tag/1
2020-09-02 19:33:15.068180+00:00 [debug] <0.2979.0>@ejabberd_router:do_route/1:384 Route:
#message{id = <<"4483496191783130789">>,type = chat,lang = <<>>,
         from = #jid{user = <<"btzfegzuncjy0r.1577630574592">>,
                     server = <<"im.XXXX.XX">>,resource = <<>>,
                     luser = <<"btzfegzuncjy0r.1577630574592">>,
                     lserver = <<"im.XXXX.XX">>,lresource = <<>>},
         to = #jid{user = <<"dhzt2fohhghfr9.1577630219046">>,
                   server = <<"im.XXXX.XX">>,resource = <<>>,
                   luser = <<"dhzt2fohhghfr9.1577630219046">>,
                   lserver = <<"im.XXXX.XX">>,lresource = <<>>},
         subject = [#text{lang = <<>>,data = <<>>}],
         body = [#text{lang = <<>>,data = <<"21h33">>}],
         thread = undefined,sub_els = [],meta = #{}}
2020-09-02 19:33:15.068587+00:00 [debug] <0.2979.0>@ejabberd_local:route/1:74 Local route:
#message{id = <<"4483496191783130789">>,type = chat,lang = <<>>,
         from = #jid{user = <<"btzfegzuncjy0r.1577630574592">>,
                     server = <<"im.XXXX.XX">>,resource = <<>>,
                     luser = <<"btzfegzuncjy0r.1577630574592">>,
                     lserver = <<"im.XXXX.XX">>,lresource = <<>>},
         to = #jid{user = <<"dhzt2fohhghfr9.1577630219046">>,
                   server = <<"im.XXXX.XX">>,resource = <<>>,
                   luser = <<"dhzt2fohhghfr9.1577630219046">>,
                   lserver = <<"im.XXXX.XX">>,lresource = <<>>},
         subject = [#text{lang = <<>>,data = <<>>}],
         body = [#text{lang = <<>>,data = <<"21h33">>}],
         thread = undefined,sub_els = [],meta = #{}}
2020-09-02 19:33:15.069088+00:00 [debug] <0.2979.0>@ejabberd_hooks:safe_apply/4:231 Running hook sm_receive_packet: mod_mam:sm_receive_packet/1
2020-09-02 19:33:15.069416+00:00 [debug] <0.2979.0>@ejabberd_sm:do_route/1:703 Processing message to bare JID:
#message{id = <<"4483496191783130789">>,type = chat,lang = <<>>,
         from = #jid{user = <<"btzfegzuncjy0r.1577630574592">>,
                     server = <<"im.XXXX.XX">>,resource = <<>>,
                     luser = <<"btzfegzuncjy0r.1577630574592">>,
                     lserver = <<"im.XXXX.XX">>,lresource = <<>>},
         to = #jid{user = <<"dhzt2fohhghfr9.1577630219046">>,
                   server = <<"im.XXXX.XX">>,resource = <<>>,
                   luser = <<"dhzt2fohhghfr9.1577630219046">>,
                   lserver = <<"im.XXXX.XX">>,lresource = <<>>},
         subject = [#text{lang = <<>>,data = <<>>}],
         body = [#text{lang = <<>>,data = <<"21h33">>}],
         thread = undefined,sub_els = [],
         meta = #{stanza_id => 1599075195069272}}
2020-09-02 19:33:15.076985+00:00 [debug] <0.2979.0>@ejabberd_router:do_route/1:384 Route:
#message{id = <<"4483496191783130789">>,type = error,lang = <<>>,
         from = #jid{user = <<"dhzt2fohhghfr9.1577630219046">>,
                     server = <<"im.XXXX.XX">>,resource = <<>>,
                     luser = <<"dhzt2fohhghfr9.1577630219046">>,
                     lserver = <<"im.XXXX.XX">>,lresource = <<>>},
         to = #jid{user = <<"btzfegzuncjy0r.1577630574592">>,
                   server = <<"im.XXXX.XX">>,resource = <<>>,
                   luser = <<"btzfegzuncjy0r.1577630574592">>,
                   lserver = <<"im.XXXX.XX">>,lresource = <<>>},
         subject = [#text{lang = <<>>,data = <<>>}],
         body = [#text{lang = <<>>,data = <<"21h33">>}],
         thread = undefined,
         sub_els = [#stanza_error{type = cancel,code = 503,by = undefined,
                                  reason = 'service-unavailable',text = [],
                                  sub_els = []}],
         meta = #{stanza_id => 1599075195069272}}
2020-09-02 19:33:15.077306+00:00 [debug] <0.2979.0>@ejabberd_local:route/1:74 Local route:
#message{id = <<"4483496191783130789">>,type = error,lang = <<>>,
         from = #jid{user = <<"dhzt2fohhghfr9.1577630219046">>,
                     server = <<"im.XXXX.XX">>,resource = <<>>,
                     luser = <<"dhzt2fohhghfr9.1577630219046">>,
                     lserver = <<"im.XXXX.XX">>,lresource = <<>>},
         to = #jid{user = <<"btzfegzuncjy0r.1577630574592">>,
                   server = <<"im.XXXX.XX">>,resource = <<>>,
                   luser = <<"btzfegzuncjy0r.1577630574592">>,
                   lserver = <<"im.XXXX.XX">>,lresource = <<>>},
         subject = [#text{lang = <<>>,data = <<>>}],
         body = [#text{lang = <<>>,data = <<"21h33">>}],
         thread = undefined,
         sub_els = [#stanza_error{type = cancel,code = 503,by = undefined,
                                  reason = 'service-unavailable',text = [],
                                  sub_els = []}],
         meta = #{stanza_id => 1599075195069272}}
2020-09-02 19:33:15.077491+00:00 [debug] <0.2979.0>@ejabberd_hooks:safe_apply/4:231 Running hook sm_receive_packet: mod_mam:sm_receive_packet/1
2020-09-02 19:33:15.077719+00:00 [debug] <0.2979.0>@ejabberd_sm:do_route/1:703 Processing message to bare JID:
#message{id = <<"4483496191783130789">>,type = error,lang = <<>>,
         from = #jid{user = <<"dhzt2fohhghfr9.1577630219046">>,
                     server = <<"im.XXXX.XX">>,resource = <<>>,
                     luser = <<"dhzt2fohhghfr9.1577630219046">>,
                     lserver = <<"im.XXXX.XX">>,lresource = <<>>},
         to = #jid{user = <<"btzfegzuncjy0r.1577630574592">>,
                   server = <<"im.XXXX.XX">>,resource = <<>>,
                   luser = <<"btzfegzuncjy0r.1577630574592">>,
                   lserver = <<"im.XXXX.XX">>,lresource = <<>>},
         subject = [#text{lang = <<>>,data = <<>>}],
         body = [#text{lang = <<>>,data = <<"21h33">>}],
         thread = undefined,
         sub_els = [#stanza_error{type = cancel,code = 503,by = undefined,
                                  reason = 'service-unavailable',text = [],
                                  sub_els = []}],
         meta = #{stanza_id => 1599075195069272}}
2020-09-02 19:33:15.077922+00:00 [debug] <0.2979.0>@ejabberd_hooks:safe_apply/4:231 Running hook bounce_sm_packet: ejabberd_sm:bounce_sm_packet/1
2020-09-02 19:33:20.984652+00:00 [debug] <0.2954.0>@ejabberd_shaper:update/2:75 Shaper update:
#state{maxrate = 100000,burst_size = 100000,acquired_credit = 100000,
       lasttime = 1599075140704982} =>
{#state{maxrate = 100000,burst_size = 100000,acquired_credit = 100000,
        lasttime = 1599075200984589},
 0}

[badlop]

I think this commit fixed it. If you're able to try it, comment here your results.

[weiss]

It seems the problem only occurs with our user using JWT as authentication (who doesn't exist in the users table...).

I didn't look into this yet: Shouldn't the user be added to the table as soon as he logged in once?

I think this commit fixed it.

I'm confused. We now run both the user_send_packet and user_receive_packet hooks when sending messages from the API? So the user_receive_packet hook is called even if the recipient is on a remote server, and it's called twice for local users which don't have this JWT auth issue (which I didn't fully understand yet), no? Whereas the OP's issue will remain unfixed if a message is sent via c2s (or s2s_in) rather than the API, no?

[weiss]

I would've thought the problem description is misleading: The problem is not that a message was received but not archived. The problem is that the message wasn't received (but bounced), because from ejabberd's point of view, the recipient doesn't exist. It's obviously correct to not run the user_receive_packet hook in this case, and to not archive the message.

Or am I totally overlooking something?

[gsohn]

because from ejabberd's point of view, the recipient doesn't exist. As we used JWT authentication, the recipient will never exist for ejabberd.

The outcoming message has to be archived. If not, I'll never be able to send a message to a not connected user with the send_message command.

[weiss]

As we used JWT authentication, the recipient will never exist for ejabberd.

This conclusion is the part I don't understand, but that's mostly due to me not being familiar with our JWT implementation. (E.g., users authenticated via extauth exist just fine.) I'll have a look later.

The outcoming message has to be archived.

I understood your requirement :smile: I'm just saying that the correct way to solve this problem is making ejabberd aware of that user.

I'll never be able to send a message to a not connected user

So everything works fine while the user is connected?

[gsohn]

Sorry if I'm not clear enough.

• All users are using JWT auth mecanism.
• If the sender and receiver are both connected, everything works fine (but unfortunately, this will not happen in real world :)).

[weiss]

Ok, quick look at the code explains the issue.

I don't know whether there's a sane way to query a JWT service for user existence. If there isn't, the only solutions I see would be hacks such as checking some local tables or access rules.

[badlop]

Or am I totally overlooking something?

Au contraire, you're totally right! I got so concerned about the command code, that didn't consider it's an auth+mam behaviour. So, my workaround works for that particular case (JWT with only local accounts), but is unacceptable for broad use.

[prefiks]

Yes jwt doesn't really have users table, as those tokens are externally created, and there is no really mechanism that can be used to query which tokens were created. Probably we should make jwt return true to user_exists - or at least offer option to do that, both ways have it's drawbacks (for always false mam/offline and probably some other stuff wouldn't work properly, for true we can store data when user doesn't really exists). Will need to think about this.

[mremond]

Yes, the user existance cannot be checked with jwt, so indeed, the function should always return true, not false I think. The issue is that you need to monitor the offline store to make sure the offline messages store does not get field with messages sent to no existent users.

[mremond]

A more complex option (on the long run) is to add the user into a known user table, and provide a way to delete them. That table would be consulted by the jwt user exist query.

[prefiks]

Commit 12d47455bac10b57cff44d1af37744d4ffaf0feb should help with this (as long as you have mod_last enabled), i will be also adding a way to clear old mod_last data, which i think should be the full solution for this problem.