Update mod_privacy.erl

[cisiqo]

Fix no match the socket. The error log:

[error] <0.15925.262>@ejabberd_hooks:safe_apply/4:240 Hook privacy_check_packet crashed when running mod_privacy:check_packet/4:
** exception error: no match of right hand side value
                  #{socket =>
                        {socket_state,gen_tcp,#Port<0.3717811>,262144,
                            #Ref<0.1588370629.2594570242.230885>,
                            {state,30000,20000,20000,1658990806695179},
                            none},
                    xmlns => <<"jabber:client">>,stream_encrypted => false,
                    stream_authenticated => true,shaper => c2s_shaper,
                    tls_required => false,
                    auth_module => ejabberd_auth_external,tls_verify => false,
                    tls_options => [compression_none],
                    mgmt_max_queue => infinity,access => c2s,
                    caps_resources => {0,nil},
                    mgmt_state => inactive,
                    socket_monitor => #Ref<0.1588370629.2594439170.230886>,
                    ip => {{0,0,0,0,0,65535,9328,54146},32157},
                    mgmt_timeout => 100000,
                    stream_id => <<"12182745460139749350">>,
                    server => <<"test.com">>,
                    user => <<"5af5124665bf57a1b57a45fea8aae851">>,
                    mgmt_stanzas_out => 0,
                    csi_queue => {0,#{}},
                    mgmt_stanzas_req => 0,
                    pres_a => {0,nil},
                    stream_version => {1,0},
                    mod => ejabberd_c2s,stream_state => wait_for_bind,
                    mgmt_max_timeout => 100000,stream_restarted => true,
                    csi_state => active,tls_enabled => false,
                     mgmt_resend => true,mgmt_queue_type => ram,
                    stream_direction => in,lserver => <<"test.com">>,
                    owner => <0.15925.262>,zlib => false,mgmt_stanzas_in => 0,
                    resource => <<>>,lang => <<"en">>,
                    mgmt_ack_timeout => 60000,stream_compressed => false,
                    codec_options => [ignore_els],
                    stream_header_sent => true,
                    stream_timeout => {30000,-573554900318}}
   in function  mod_privacy:check_packet/4 (src/mod_privacy.erl, line 557)
   in call from ejabberd_hooks:safe_apply/4 (src/ejabberd_hooks.erl, line 236)
   in call from ejabberd_hooks:run_fold1/4 (src/ejabberd_hooks.erl, line 217)
   in call from ejabberd_c2s:process_message_in/2 (src/ejabberd_c2s.erl, line 635)
   in call from ejabberd_c2s:process_info/2 (src/ejabberd_c2s.erl, line 222)
   in call from ejabberd_hooks:safe_apply/4 (src/ejabberd_hooks.erl, line 236)
   in call from ejabberd_hooks:run_fold1/4 (src/ejabberd_hooks.erl, line 217)
   in call from xmpp_stream_in:handle_info/2 (src/xmpp_stream_in.erl, line 456)
** Arg 1 = allow
** Arg 2 = #{socket =>
                 {socket_state,gen_tcp,#Port<0.3717811>,262144,
                               #Ref<0.1588370629.2594570242.230885>,
                               {state,30000,20000,20000,1658990806695179},
                               none},
             xmlns => <<"jabber:client">>,stream_encrypted => false,
             stream_authenticated => true,shaper => c2s_shaper,
             tls_required => false,auth_module => ejabberd_auth_external,
             tls_verify => false,
             tls_options => [compression_none],
             mgmt_max_queue => infinity,access => c2s,
             caps_resources => {0,nil},
             mgmt_state => inactive,
             socket_monitor => #Ref<0.1588370629.2594439170.230886>,
             ip => {{0,0,0,0,0,65535,9328,54146},32157},
             mgmt_timeout => 100000,stream_id => <<"12182745460139749350">>,
             server => <<"test.com">>,
             user => <<"5af5124665bf57a1b57a45fea8aae851">>,
             mgmt_stanzas_out => 0,
             csi_queue => {0,#{}},
             mgmt_stanzas_req => 0,
             pres_a => {0,nil},
             stream_version => {1,0},
             mod => ejabberd_c2s,stream_state => wait_for_bind,
             mgmt_max_timeout => 100000,stream_restarted => true,
             csi_state => active,tls_enabled => false,mgmt_resend => true,
             mgmt_queue_type => ram,stream_direction => in,
             lserver => <<"test.com">>,owner => <0.15925.262>,zlib => false,
             mgmt_stanzas_in => 0,resource => <<>>,lang => <<"en">>,
             mgmt_ack_timeout => 60000,stream_compressed => false,
             codec_options => [ignore_els],
             stream_header_sent => true,
             stream_timeout => {30000,-573554900318}}
** Arg 3 = {message,<<"888fbfaa0dad4b7693826ff16d857727">>,normal,<<>>,
            {jid,<<"i8dmhrw87ehqtpu4">>,<<"conference.test.com">>,<<>>,
             <<"i8dmhrw87ehqtpu4">>,<<"conference.test.com">>,<<>>},
            {jid,<<"5af5124665bf57a1b57a45fea8aae851">>,<<"test.com">>,
             <<>>,<<"5af5124665bf57a1b57a45fea8aae851">>,<<"test.com">>,
             <<>>},
            [],[],undefined,
            [{ps_event,
              {ps_items,<<>>,<<"urn:xmpp:mucsub:nodes:messages">>,
               [{ps_item,<<>>,<<"888fbfaa0dad4b7693826ff16d857727">>,
                 [{message,<<"888fbfaa0dad4b7693826ff16d857727">>,groupchat,
                   <<"en">>,
                   {jid,<<"i8dmhrw87ehqtpu4">>,<<"conference.test.com">>,
                    <<"fo14dl1sb0ispe5p">>,<<"i8dmhrw87ehqtpu4">>,
                    <<"conference.test.com">>,<<"fo14dl1sb0ispe5p">>},
                   {jid,<<"5af5124665bf57a1b57a45fea8aae851">>,
                    <<"test.com">>,<<>>,
                    <<"5af5124665bf57a1b57a45fea8aae851">>,<<"test.com">>,
                    <<>>},
                   [],
                   [{text,<<>>,
                     <<230,136,145,231,156,139,231,156,139,229,142,187,227,
                       128,130>>}],
                   undefined,
                   [{mam_archived,
                     {jid,<<"i8dmhrw87ehqtpu4">>,<<"conference.test.com">>,
                      <<>>,<<"i8dmhrw87ehqtpu4">>,<<"conference.test.com">>,
                      <<>>},
                     <<"1658990807319169">>},
                    {stanza_id,
                     {jid,<<"i8dmhrw87ehqtpu4">>,<<"conference.test.com">>,
                      <<>>,<<"i8dmhrw87ehqtpu4">>,<<"conference.test.com">>,
                      <<>>},
                     <<"1658990807319169">>}],
                   #{ip => {0,0,0,0,0,65535,29638,51263},
                     mam_archived => true,
                     muc_sender_real_jid =>
                      {jid,<<"fo14dl1sb0ispe5p">>,<<"test.com">>,
                       <<"Desktop">>,<<"fo14dl1sb0ispe5p">>,<<"test.com">>,
                       <<"Desktop">>},
                     stanza_id => 1658990807319169}}],
                 <<>>,<<>>}],
               undefined,<<>>,undefined},
              undefined,undefined,undefined,undefined,undefined}],
            #{in_muc_mam => true,sm_copy => true,
              stanza_id => 1658990807631454}}
** Arg 4 = in

[prefiks]

That would fix that problem, but that's not correct solution here. I think this is result of buggy client, looks like it start sending message, before it finishes session initialization (looks like it didn't send bind requests). Do you know what client is that?

That fix will only paperback this problem, but there will be problem later on, this session is not properly registered, so it for example can't receive messages from other client/services. Probably correct thing to do here would be closing that session with error.

[cisiqo]

We use a client developed by ourselves, and the android library uses the Smack.

The problem is that after xep-0198 ack_timeout times out, xep-0198 will send the queued message again.

[prefiks]

Hm, interesting, would you be able to capture session traffic when this happen, so i could see when we are receiving this? At this point session i think shouldn't be registered in session manager so it shouldn't even know where send those messages, so i wonder how those messages got there...

[cisiqo]

When the ack_timeout set by the xep-1098 module times out, the socket connection will be forcibly disconnected. At this point, the xep-0198 module will re-send the messages in the queue that are not acked through ejabberd_router:route.

After the ack_timeout set by the xep-0198 module times out, the c2s_terminated of mod_stream_mgmt will be triggered, and then the method route_unacked_stanzas will be executed to resend all messages in the queue. Then these messages are routed to the ejabberd_sm module, and the route_message method is executed. Since the current user socket is disconnected, the current resource is not online, and then the message is executed before the offline_message_hook hook, you need to check the packet, and then The hook privacy_check_packet is triggered.

[prefiks]

Sorry for a delay, it seems i missed your message.

So i still don't know how that is possible. We register session in database only after bind call (which would make sure there is jid field in state and there would not be stream_state => wait_for_bind in it), so ejabberd_router:route() shouldn't be able to send anything to that process before that is called. Do you have some custom modules in your system that could affect this? Could you show modules sections from your config?

[cisiqo]

This is config https://gist.github.com/cisiqo/edb81ebc63db9be661f0ac2fd2019102 of my test ejabberd. I don't use custom modules, the problem still occurs. The configuration related to this problem is mod_stream_mgmt.

[licaon-kter]

There were some stream issues fixed in 22.05 or HEAD, did you test with these too?

[cisiqo]

@licaon-kter No.

[licaon-kter]

@cisiqo then please do test :)

[cisiqo]

@licaon-kter OK, if I upgrade to this version or above.