Outcoming chat messages are not always stored in archive #3377

gsohn · 2020-09-02T17:34:01Z

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.

The text was updated successfully, but these errors were encountered:

badlop · 2020-09-02T18:41:30Z

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 · 2020-09-02T19:22:35Z

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 · 2020-09-02T19:36:12Z

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">>,
                                                          <<"[email protected]">>,
                                                          <<"[email protected]">>,
                                                          <<>>,<<"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}

…3377)

badlop · 2020-09-03T18:38:46Z

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

weiss · 2020-09-04T07:54:44Z

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 · 2020-09-04T08:06:52Z

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 · 2020-09-04T08:22:56Z

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 · 2020-09-04T08:30:53Z

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 😄 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 · 2020-09-04T08:39:13Z

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 · 2020-09-04T09:04:09Z

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.

…coming (#3377)" This reverts commit 43f813d.

badlop · 2020-09-04T09:38:44Z

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 · 2020-09-04T09:40:33Z

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 · 2020-09-04T09:41:56Z

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 · 2020-09-04T09:45:20Z

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.

This makes `user_check` hook work better with authentication methods that don't have a way to determine if user exists (like is the case for jwt and cert based authentication), and as result will improve mod_offline and mod_mam handling of offline messages to those users. This reuses information stored by `mod_last` for this purpose. Should fix issue #3377.

prefiks · 2023-10-11T12:23:11Z

Commit 12d4745 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.

badlop added a commit that referenced this issue Sep 3, 2020

Run user_receive_packet in send_message so MAM stores also incoming (#…

43f813d

…3377)

badlop added this to the ejabberd 20.xx milestone Sep 3, 2020

badlop added a commit that referenced this issue Sep 4, 2020

Revert "Run user_receive_packet in send_message so MAM stores also in…

a75966f

…coming (#3377)" This reverts commit 43f813d.

mremond mentioned this issue Apr 15, 2021

Presence subscribe request fails when using JWT auth #3537

Closed

badlop modified the milestones: ejabberd 21.07, ejabberd 21.xx Jul 21, 2021

badlop removed this from the ejabberd 21.xx milestone Nov 5, 2021

dkliss mentioned this issue Feb 23, 2023

mod_mam with external authentication, unable to retrieve all chat messages #3999

Closed

mremond assigned jsautret Jul 11, 2023

mremond added this to the ejabberd 23.xx milestone Jul 11, 2023

badlop removed this from the ejabberd 23.xx milestone Oct 10, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Outcoming chat messages are not always stored in archive #3377

Outcoming chat messages are not always stored in archive #3377

gsohn commented Sep 2, 2020 •

edited by badlop

Loading

badlop commented Sep 2, 2020 •

edited

Loading

gsohn commented Sep 2, 2020

gsohn commented Sep 2, 2020 •

edited by badlop

Loading

badlop commented Sep 3, 2020

weiss commented Sep 4, 2020

weiss commented Sep 4, 2020

gsohn commented Sep 4, 2020

weiss commented Sep 4, 2020

gsohn commented Sep 4, 2020

weiss commented Sep 4, 2020

badlop commented Sep 4, 2020

prefiks commented Sep 4, 2020

mremond commented Sep 4, 2020

mremond commented Sep 4, 2020

prefiks commented Oct 11, 2023

Outcoming chat messages are not always stored in archive #3377

Outcoming chat messages are not always stored in archive #3377

Comments

gsohn commented Sep 2, 2020 • edited by badlop Loading

Environment

Configuration

badlop commented Sep 2, 2020 • edited Loading

gsohn commented Sep 2, 2020

gsohn commented Sep 2, 2020 • edited by badlop Loading

badlop commented Sep 3, 2020

weiss commented Sep 4, 2020

weiss commented Sep 4, 2020

gsohn commented Sep 4, 2020

weiss commented Sep 4, 2020

gsohn commented Sep 4, 2020

weiss commented Sep 4, 2020

badlop commented Sep 4, 2020

prefiks commented Sep 4, 2020

mremond commented Sep 4, 2020

mremond commented Sep 4, 2020

prefiks commented Oct 11, 2023

gsohn commented Sep 2, 2020 •

edited by badlop

Loading

badlop commented Sep 2, 2020 •

edited

Loading

gsohn commented Sep 2, 2020 •

edited by badlop

Loading