Occur Forbideden c2s session and closed after 20.x ver

[Ktshas]

Hi.

I am attempting to upgrade ejabberd from version 18.12 to 23.10. We are using the extauth module, and we have confirmed that it is a program that simply returns true for "isuser" and "auth." Although I didn't create it, this seems intentional. We use ejabberd to connect with set-top boxes, and since we cannot register ejabberd for every set-top box, it seems like a reasonable approach.

However, there were no issues with this in version 18.12. The problem seems to have arisen from version 20 onwards (I couldn't confirm with version 19 as the installation failed).

Since updating to 23.10, none of the devices, tsung, or pidgin can connect, and the returned messages are all the same. However, when I tested with the original, uncustomized ejabberd 23.10, I confirmed that pidgin connects properly. Therefore, I suspect it might not be an issue with the authentication module.

However, I have no idea which part is causing the problem. My speculation is that perhaps the authentication procedure has been strengthened since version 20, requiring additional configurations, but I cannot be certain. I will attach the logs:

2024-02-22 09:02:06.222176+00:00 [info] (<0.3047.0>) Accepted connection 172.16.9.252:53380 -> 172.16.9.102:5223
2024-02-22 09:02:06.250272+00:00 [notice] (tcp|<0.3047.0>) Received XML on stream = <<"<?xml version='1.0' ?>">>
2024-02-22 09:02:06.261073+00:00 [notice] (tcp|<0.3047.0>) Received XML on stream = <<"<stream:stream to='krms.commufa.jp' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>">>
2024-02-22 09:02:06.261681+00:00 [notice] (tcp|<0.3047.0>) Send XML on stream = <<"<?xml version='1.0'?><stream:stream id='2830981450195449202' version='1.0' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' from='krms.commufa.jp' xmlns='jabber:client'>">>
2024-02-22 09:02:06.262346+00:00 [notice] (tcp|<0.3047.0>) Send XML on stream = <<"<stream:features><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'><required/></starttls></stream:features>">>
2024-02-22 09:02:06.262853+00:00 [debug] Running hook c2s_handle_send: mod_push:c2s_stanza/3
2024-02-22 09:02:06.264719+00:00 [notice] (tcp|<0.3047.0>) Received XML on stream = <<"<starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>">>
2024-02-22 09:02:06.265578+00:00 [notice] (tcp|<0.3047.0>) Send XML on stream = <<"<proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>">>
2024-02-22 09:02:06.265912+00:00 [debug] Running hook c2s_handle_send: mod_push:c2s_stanza/3
2024-02-22 09:02:06.317592+00:00 [notice] (tls|<0.3047.0>) Received XML on stream = <<"<stream:stream to='krms.commufa.jp' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>">>
2024-02-22 09:02:06.318200+00:00 [notice] (tls|<0.3047.0>) Send XML on stream = <<"<?xml version='1.0'?><stream:stream id='15418490996513873017' version='1.0' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' from='krms.commufa.jp' xmlns='jabber:client'>">>
2024-02-22 09:02:06.318811+00:00 [notice] (tls|<0.3047.0>) Send XML on stream = <<"<stream:features><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>PLAIN</mechanism><mechanism>X-OAUTH2</mechanism></mechanisms></stream:features>">>
2024-02-22 09:02:06.319288+00:00 [debug] Running hook c2s_handle_send: mod_push:c2s_stanza/3
2024-02-22 09:02:06.324318+00:00 [notice] (tls|<0.3047.0>) Received XML on stream = <<"<auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='PLAIN' xmlns:ga='http://www.google.com/talk/protocol/auth' ga:client-uses-full-bind-result='true'>AHRza2ltAGthb24uMTIzNA==</auth>">>
2024-02-22 09:02:06.325079+00:00 [debug] Running hook c2s_auth_result: ejabberd_c2s:process_auth_result/3
2024-02-22 09:02:06.325470+00:00 [info] (tls|<0.3047.0>) Accepted c2s PLAIN authentication for tskim@krms.commufa.jp by external backend from 172.16.9.252
2024-02-22 09:02:06.325903+00:00 [notice] (tls|<0.3047.0>) Send XML on stream = <<"<success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'/>">>
2024-02-22 09:02:06.326300+00:00 [debug] Running hook c2s_handle_send: mod_push:c2s_stanza/3
2024-02-22 09:02:06.337938+00:00 [notice] (tls|<0.3047.0>) Received XML on stream = <<"<stream:stream to='krms.commufa.jp' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>">>
2024-02-22 09:02:06.338460+00:00 [notice] (tls|<0.3047.0>) Send XML on stream = <<"<?xml version='1.0'?><stream:stream id='4614230201486469110' version='1.0' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' from='krms.commufa.jp' xmlns='jabber:client'>">>
2024-02-22 09:02:06.338989+00:00 [debug] Running hook c2s_post_auth_features: mod_roster:get_versioning_feature/2
2024-02-22 09:02:06.339354+00:00 [debug] Running hook c2s_post_auth_features: mod_caps:caps_stream_features/2
2024-02-22 09:02:06.339614+00:00 [debug] Running hook disco_local_features: mod_announce:disco_features/5
2024-02-22 09:02:06.339969+00:00 [debug] Running hook disco_local_features: mod_blocking:disco_features/5
2024-02-22 09:02:06.340223+00:00 [debug] Running hook disco_local_features: mod_carboncopy:disco_features/5
2024-02-22 09:02:06.340604+00:00 [debug] Running hook disco_local_features: mod_configure:get_local_features/5
2024-02-22 09:02:06.340947+00:00 [debug] Running hook disco_local_features: mod_privacy:disco_features/5
2024-02-22 09:02:06.341324+00:00 [debug] Running hook disco_local_features: mod_caps:disco_features/5
2024-02-22 09:02:06.341566+00:00 [debug] Running hook disco_local_features: mod_adhoc:get_local_features/5
2024-02-22 09:02:06.341930+00:00 [debug] Running hook disco_local_features: mod_disco:get_local_features/5
2024-02-22 09:02:06.342292+00:00 [debug] Running hook disco_local_identity: mod_announce:disco_identity/5
2024-02-22 09:02:06.342518+00:00 [debug] Running hook disco_local_identity: mod_configure:get_local_identity/5
2024-02-22 09:02:06.342834+00:00 [debug] Running hook disco_local_identity: mod_caps:disco_identity/5
2024-02-22 09:02:06.343041+00:00 [debug] Running hook disco_local_identity: mod_adhoc:get_local_identity/5
2024-02-22 09:02:06.343322+00:00 [debug] Running hook disco_local_identity: mod_disco:get_local_identity/5
2024-02-22 09:02:06.343531+00:00 [debug] Running hook disco_info: mod_caps:disco_info/5
2024-02-22 09:02:06.343831+00:00 [debug] Running hook disco_info: mod_disco:get_info/5
2024-02-22 09:02:06.344139+00:00 [notice] (tls|<0.3047.0>) Send XML on stream = <<"<stream:features><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/><session xmlns='urn:ietf:params:xml:ns:xmpp-session'><optional/></session><c ver='jU7nacXvN7UcMkAIpQYC3r39axM=' node='http://www.process-one.net/en/ejabberd/' hash='sha-1' xmlns='http://jabber.org/protocol/caps'/><ver xmlns='urn:xmpp:features:rosterver'/></stream:features>">>
2024-02-22 09:02:06.344830+00:00 [debug] Running hook c2s_handle_send: mod_push:c2s_stanza/3
2024-02-22 09:02:06.356844+00:00 [notice] (tls|<0.3047.0>) Received XML on stream = <<"<iq type='set' id='purpleacf50529'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/></iq>">>
2024-02-22 09:02:06.357416+00:00 [warning] (tls|<0.3047.0>) Forbidden c2s session for tskim@krms.commufa.jp/82505555941415050171954
2024-02-22 09:02:06.357908+00:00 [notice] (tls|<0.3047.0>) Send XML on stream = <<"<iq type='error' id='purpleacf50529'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/><error code='405' type='cancel'><not-allowed xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/><text xml:lang='en' xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'>Access denied by service policy</text></error></iq>">>
2024-02-22 09:02:06.358502+00:00 [debug] Running hook c2s_handle_send: mod_push:c2s_stanza/3
2024-02-22 09:02:06.413079+00:00 [notice] (tls|<0.3047.0>) Received XML on stream = <<"</stream:stream>">>
2024-02-22 09:02:06.413615+00:00 [debug] Running hook c2s_closed: ejabberd_c2s:process_closed/2
2024-02-22 09:02:06.414046+00:00 [debug] Running hook c2s_terminated: ejabberd_c2s:process_terminated/2
2024-02-22 09:02:06.414319+00:00 [notice] (tls|<0.3047.0>) Send XML on stream = <<"</stream:stream>">>

Thank you.

[prefiks]

I believe this is result of hitting deny rule in access assigned to c2s listener, please check your listener config for port 5223 and see what access: you have assigned to it, it looks it returns deny

[Ktshas]

Thank you so much your support.
I checked diff my 18.12 config and original 23.10 config.
Then edited my ejabberd.yml file To follow the rules of version 23.10.
finally disappear the forbidden session message!!

But don't progress after this SQL message.

2024-02-23 05:26:20.583893+00:00 [notice] (tls|<0.3031.0>) Received XML on stream = <<"">>
2024-02-23 05:26:20.585158+00:00 [debug] SQL: "REPLACE INTO sm(usec, pid, node, username, resource, priority, info) VALUES (1708665980000094, '<0.3031.0>', 'krms_xmpp@krms_xmpp_server_12', 'tskim', '140875160389904576771890', '', '[{ip,{{172,16,9,252},57896}},\n {conn,c2s_tls},\n {auth_module,ejabberd_auth_external}]');"

I will check mysql connection, and source code 23.10.
It seems that the connection open logic has changed in 18.12.
So i start to analyze 23.12 source code from now.

If I do that and still can't figure out the cause, I'll ask for help again.
However, if you have any hints about this symptom, I would appreciate it if you could let me know.

Thank you.

[licaon-kter]

do note that there are many SQL changes since 18.12, so read each upgrade step from 18.12 till 23.10: https://docs.ejabberd.im/admin/upgrade/#specific-version-upgrade-notes

[Ktshas]

Ok, I will close this issue, session forbidden problem solved by editing the config file.
And the additional question by comment that about

SQL: "REPLACE INTO sm(usec, pid, node, username, resource, priority, info) VALUES (1708665980000094, '<0.3031.0>', 'krms_xmpp@krms_xmpp_server_12', 'tskim', '140875160389904576771890', '', '[{ip,{{172,16,9,252},57896}},\n {conn,c2s_tls},\n {auth_module,ejabberd_auth_external}]');"

solved also, but i don't know what i do. sorry about that.
Maybe, this problem was not occur when i set don't use mysql.
And one thing is certain, the sm table was different 18.12 and 23.10,so i did remove sm table then make again by adding update_sql_schema: true in config file.