search

processone / ejabberd

Robust, Ubiquitous and Massively Scalable Messaging Platform (XMPP, MQTT, SIP Server)
https://www.process-one.net/en/ejabberd/
Other
6.01k stars 1.5k forks source link

In-Band Registration Only Working on Some Clients #4094

Open user95680119 opened 9 months ago

user95680119 commented 9 months ago

Environment

Bug description

When I try registering a new user inside of Dino (Linux), Siskin (IOS), or Monal (IOS), it doesn't register any user and it prints "unexpected event from XML driver" into the ejabberd log. But when I try registering a new user inside of Pidgin (Linux) or Gajim (Linux), it works just fine by registering the new user without warning. Logging into a preregistered account on any of the above clients works just fine.

Configuration ```yaml loglevel: 4 hide_sensitive_log_data: true log_rotate_count: 0 default_db: sql sql_type: pgsql sql_server: "localhost" sql_database: "ejabberd" sql_username: "ejabberd" sql_password: "hidden" hosts: - "MYDOMAIN" certfiles: - "/etc/ejabberd/certs/*/*.pem" define_macro: 'TLS_CIPHERS': "HIGH:!aNULL:!eNULL:!3DES:@STRENGTH" 'TLS_OPTIONS': - "no_sslv3" - "no_tlsv1" - "no_tlsv1_1" - "cipher_server_preference" - "no_compression" c2s_ciphers: 'TLS_CIPHERS' s2s_ciphers: 'TLS_CIPHERS' c2s_protocol_options: 'TLS_OPTIONS' s2s_protocol_options: 'TLS_OPTIONS' listen: - port: 5222 ip: "::" module: ejabberd_c2s max_stanza_size: 262144 shaper: c2s_shaper access: c2s starttls_required: true protocol_options: 'TLS_OPTIONS' - port: 5223 ip: "::" module: ejabberd_c2s max_stanza_size: 262144 shaper: c2s_shaper access: c2s tls: true protocol_options: 'TLS_OPTIONS' - port: 5269 ip: "::" module: ejabberd_s2s_in max_stanza_size: 524288 - port: 5443 ip: "::" module: ejabberd_http tls: true protocol_options: 'TLS_OPTIONS' request_handlers: /api: mod_http_api /bosh: mod_bosh /upload: mod_http_upload /ws: ejabberd_http_ws - port: 5280 ip: "::" module: ejabberd_http tls: true protocol_options: 'TLS_OPTIONS' request_handlers: /admin: ejabberd_web_admin /.well-known/acme-challenge: ejabberd_acme disable_sasl_mechanisms: - "digest-md5" - "X-OAUTH2" s2s_use_starttls: required auth_password_format: scram acl: admin: user: - "r" local: user_regexp: "" loopback: ip: - 127.0.0.0/8 - ::1/128 access_rules: local: allow: local c2s: deny: blocked allow: all announce: allow: admin configure: allow: admin muc_create: allow: local pubsub_createnode: allow: local trusted_network: allow: loopback register: allow: all api_permissions: "console commands": from: - ejabberd_ctl who: all what: "*" "admin access": who: access: allow: - acl: loopback - acl: admin oauth: scope: "ejabberd:admin" access: allow: - acl: loopback - acl: admin what: - "*" - "!stop" - "!start" "public commands": who: ip: 127.0.0.1/8 what: - status - connected_users_number shaper: normal: rate: 3000 burst_size: 20000 fast: 200000 shaper_rules: max_user_sessions: 10 max_user_offline_messages: 5000: admin 100: all c2s_shaper: none: admin normal: all s2s_shaper: fast registration_timeout: infinity modules: mod_adhoc: {} mod_admin_extra: {} mod_announce: access: announce mod_avatar: {} mod_blocking: {} mod_bosh: {} mod_caps: {} mod_carboncopy: {} mod_client_state: {} mod_configure: {} mod_disco: {} mod_fail2ban: {} mod_http_api: {} mod_http_upload: put_url: https://@HOST@:5443/upload custom_headers: "Access-Control-Allow-Origin": "https://@HOST@" "Access-Control-Allow-Methods": "GET,HEAD,PUT,OPTIONS" "Access-Control-Allow-Headers": "Content-Type" mod_last: {} mod_mam: assume_mam_usage: true default: always mod_mqtt: {} mod_muc: host: gc.MYDOMAIN access: - allow access_admin: - allow: admin access_create: muc_create access_persistent: muc_create access_mam: - allow default_room_options: mam: true mod_muc_admin: {} mod_offline: access_max_user_messages: max_user_offline_messages mod_ping: {} mod_pres_counter: count: 5 interval: 60 mod_privacy: {} mod_private: {} mod_pubsub: access_createnode: pubsub_createnode plugins: - flat - pep force_node_config: "eu.siacs.conversations.axolotl.*": access_model: open storage:bookmarks: access_model: whitelist mod_push: {} mod_push_keepalive: {} mod_register: access_from: register registration_watchers: [r@MYDOMAIN] welcome_message: subject: "Welcome!" body: |- Hi. Welcome to this XMPP server. mod_roster: versioning: true mod_s2s_dialback: {} mod_shared_roster: {} mod_sic: {} mod_stream_mgmt: resend_on_timeout: if_offline mod_stun_disco: {} mod_vcard: search: false mod_vcard_xupdate: {} mod_version: {} ```
Log ``` 2023-10-05 07:47:16.356083+00:00 [info] <0.123.0>@ejabberd_config:load/1:82 Loading configuration from /etc/ejabberd/ejabberd.yml 2023-10-05 07:47:17.112346+00:00 [info] <0.123.0>@ejabberd_config:load/1:89 Configuration loaded successfully 2023-10-05 07:47:17.663366+00:00 [info] <0.353.0>@ejabberd_systemd:init/1:92 Watchdog notifications enabled 2023-10-05 07:47:18.013439+00:00 [info] <0.352.0>@gen_mod:start_modules/0:130 Loading modules for MYDOMAIN 2023-10-05 07:47:19.099289+00:00 [info] <0.519.0>@mod_mqtt:init_topic_cache/2:644 Building MQTT cache for MYDOMAIN, this may take a while 2023-10-05 07:47:19.319589+00:00 [info] <0.123.0>@ejabberd_cluster_mnesia:wait_for_sync/1:123 Waiting for Mnesia synchronization to complete 2023-10-05 07:47:19.462150+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.462698+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/upload.MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.463179+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/proxy.MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.463458+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/gc.MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.463760+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/pubsub.MYDOMAIN/fullchain.pem: at line 56: certificate is signed by unknown CA 2023-10-05 07:47:19.464020+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.464249+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/upload.MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.464602+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/proxy.MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.464997+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/gc.MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.465395+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/pubsub.MYDOMAIN/fullchain.pem: at line 56: certificate is signed by unknown CA 2023-10-05 07:47:19.465689+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.466064+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificatein /etc/ejabberd/certs/upload.MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.466651+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/proxy.MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.466972+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/gc.MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.467512+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/pubsub.MYDOMAIN/fullchain.pem: at line 56: certificate is signed by unknown CA 2023-10-05 07:47:19.467758+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.468210+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/upload.MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.468561+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/proxy.MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.468882+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/gc.MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.469257+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/pubsub.MYDOMAIN/fullchain.pem: at line 56: certificate is signed by unknown CA 2023-10-05 07:47:19.469654+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.470072+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/upload.MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.470419+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/proxy.MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.470737+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/gc.MYDOMAIN/fullchain.pem: at line 55: certificate is signed by unknown CA 2023-10-05 07:47:19.471054+00:00 [warning] <0.384.0>@ejabberd_pkix:log_warnings/1:393 Invalid certificate in /etc/ejabberd/certs/pubsub.MYDOMAIN/fullchain.pem: at line 56: certificate is signed by unknown CA 2023-10-05 07:47:19.707540+00:00 [info] <0.123.0>@ejabberd_app:start/2:63 ejabberd 23.01-1 is started in the node ejabberd@localhost in 3.70s 2023-10-05 07:47:19.712896+00:00 [info] <0.382.0>@ejabberd_listener:init/4:160 Start accepting TLS connections at [::]:5443 for ejabberd_http 2023-10-05 07:47:19.712871+00:00 [info] <0.381.0>@ejabberd_listener:init/4:160 Start accepting TCP connections at [::]:5269 for ejabberd_s2s_in 2023-10-05 07:47:19.713700+00:00 [info] <0.379.0>@ejabberd_listener:init/4:160 Start accepting TCP connections at [::]:5222 for ejabberd_c2s 2023-10-05 07:47:19.713784+00:00 [info] <0.383.0>@ejabberd_listener:init/4:160 Start accepting TLS connections at [::]:5280 for ejabberd_http 2023-10-05 07:47:19.714397+00:00 [info] <0.380.0>@ejabberd_listener:init/4:160 Start accepting TLS connections at [::]:5223 for ejabberd_c2s 2023-10-05 07:49:29.018336+00:00 [info] <0.379.0>@ejabberd_listener:accept/7:273 (<0.576.0>) Accepted connection hidden_by_ejabberd -> [::ffff:SERVERIP]:5222 2023-10-05 07:49:29.600765+00:00 [warning] <0.576.0> unexpected event from XML driver: {xmlstreamelement, {xmlel,<<"starttls">>, [{<<"xmlns">>, <<"urn:ietf:params:xml:ns:xmpp-tls">>}], []}}; xmlstreamstart was expected ```
badlop commented 9 months ago

I tried ejabberd 23.01 compiled from source in Debian, and setup loglevel: debug

Gajim 1.8.0 and Pidgin 2.14.12 register correctly for me too.

Dino 0.4.3 doesn't show the registration window correctly, so I cannot reach the problem you see. My ejabberd log shows that Dino requests the registration, but when ejabberd shows it, Dino closes the connection... Some of the lines shown on the log:

2023-10-05 11:18:00.860990+02:00 [notice] (tls|<0.1359.0>)
  Received XML on stream =
  <<"<iq id='fbd04b86-1a85-461a-a898-2c370bd8c06d' type='get' to='test7.localhost'>
             <query xmlns='jabber:iq:register'/></iq>">>
2023-10-05 11:18:00.862145+02:00 [notice] (tls|<0.1359.0>)
  Send XML on stream =
  <<"<iq xml:lang='en' from='test7.localhost' type='result' id='fbd04b86-1a85-461a-a898-2c370bd8c06d'>
            <query xmlns='jabber:iq:register'>
                <username/>
                <password/>
                <instructions>Choose a username and password to register with this server</instructions>
            </query></iq>">>
2023-10-05 11:18:00.864586+02:00 [notice] (tls|<0.1359.0>)
  Received XML on stream =
  <<"</stream:stream>">>

If you enable debug loglevel in ejabberd configuration, does it show any relevant XML traffic?

What version of Dino are you using? Maybe I can install your same version, or you can update to the latest Dino 0.4.3.

I don't have an iOS or Mac to try Monal and Siskin, can you try other Linux clients?

user95680119 commented 9 months ago

Hi, I am using the same version of Dino as you, 0.4.3. I tried registering with both Gajim (1.8.1) and Profanity (0.14.0) and both registered a new user just fine. Here are my logs with loglevel: set to debug.

Connecting with Dino (0.4.3)


2023-10-05 11:04:51.811931+00:00 [info] <0.380.0>@ejabberd_listener:accept/7:273 (<0.576.0>) Accepted connection hidden_by_ejabberd -> [::ffff:SERVERIP]:5222

2023-10-05 11:04:51.820758+00:00 [notice] <0.576.0> (tcp|<0.576.0>) 
    Received XML on stream = 
    <<"<stream:stream to='MYDOMAIN' version='1.0'xmlns='jabber:client'xmlns:stream='http://etherx.jabber.org/streams'>">>

2023-10-05 11:04:51.846211+00:00 [notice] <0.576.0> (tcp|<0.576.0>)
    Send XML on stream = 
    <<"<?xml version='1.0'?><stream:stream id='6638884739733093058' version='1.0' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' from='MYDOMAIN' xmlns='jabber:client'>">>

2023-10-05 11:04:51.848907+00:00 [notice] <0.576.0> (tcp|<0.576.0>) 
    Send XML on stream =
    <<"<stream:features>
        <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'><required/></starttls>
    </stream:features>">>

2023-10-05 11:04:52.106018+00:00 [notice] <0.576.0> (tcp|<0.576.0>) 
    Received XML on stream =
    <<"<starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>">>

2023-10-05 11:04:52.215920+00:00 [notice] <0.576.0> (tcp|<0.576.0>)
    Send XML on stream =
    <<"<proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>">>

2023-10-05 11:04:52.924355+00:00 [notice] <0.576.0> (tls|<0.576.0>)
    Received XML on stream =
    <<"<stream:stream to='MYDOMAIN' version='1.0' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams'>">>

2023-10-05 11:04:52.925287+00:00 [notice] <0.576.0> (tls|<0.576.0>)
    Send XML on stream =
    <<"<?xml version='1.0'?><stream:stream id='7790905245421028027' version='1.0' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' from='MYDOMAIN' xmlns='jabber:client'>">>

2023-10-05 11:04:52.948269+00:00 [notice] <0.576.0> (tls|<0.576.0>)
    Send XML on stream =
    <<"<stream:features>
        <mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
        <mechanism> PLAIN </mechanism>
        <mechanism> SCRAM-SHA-1-PLUS </mechanism>
        <mechanism>SCRAM-SHA-1</mechanism> 
        </mechanisms>
        <register xmlns='http://jabber.org/features/iq-register'/>
    </stream:features>">>

2023-10-05 11:04:53.147511+00:00 [notice] <0.576.0> (tls|<0.576.0>) 
    Received XML on stream =
    <<"<iq id='c5cbec81-7e79-4e95-a0bf-f556a3dbb1a5' type='get' to='MYDOMAIN'><query xmlns='jabber:iq:register'/></iq>">>

2023-10-05 11:04:53.149247+00:00 [notice] <0.576.0> (tls|<0.576.0>) 
    Send XML on stream =
    <<"<iq xml:lang='en' from='MYDOMAIN' type='result' id='c5cbec81-7e79-4e95-a0bf-f556a3dbb1a5'>
    <query xmlns='jabber:iq:register'>
        <username/>
        <password/>
        <instructions>Choose a username and password to register with this server</instructions>
    </query></iq>">>

2023-10-05 11:04:53.435977+00:00 [notice] <0.576.0> (tls|<0.576.0>) 
    Received XML on stream =
    <<"</stream:stream>">>

2023-10-05 11:04:53.439313+00:00 [notice] <0.576.0> (tls|<0.576.0>) 
    Send XML on stream =
    <<"</stream:stream>">>

2023-10-05 11:07:58.112501+00:00 [notice] <0.585.0> (tcp|<0.585.0>) 
    Received XML on stream =
    <<"<stream:stream to='MYDOMAIN'  version='1.0' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams'>">>

Connecting with Siskin IM (7.3.3)


2023-10-05 11:07:58.110756+00:00 [info] <0.380.0>@ejabberd_listener:accept/7:273 (<0.585.0>) Accepted connection hidden_by_ejabberd -> [::ffff:SERVERIP]:5222

2023-10-05 11:07:58.115339+00:00 [notice] <0.585.0> (tcp|<0.585.0>)
    Send XML on stream =
    <<"<?xml version='1.0'?><stream:stream id='17707439241658982967' version='1.0' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' from='MYDOMAIN' xmlns='jabber:client'>">>

2023-10-05 11:07:58.119863+00:00 [notice] <0.585.0> (tcp|<0.585.0>) 
    Send XML on stream =
    <<"<stream:features>
        <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'><required/></starttls>
    </stream:features>">>

2023-10-05 11:07:58.408027+00:00 [notice] <0.585.0> (tcp|<0.585.0>)
    Received XML on stream =
    <<"<starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>">>

2023-10-05 11:07:58.412492+00:00 [notice] <0.585.0> (tcp|<0.585.0>)
    Send XML on stream =
    <<"<proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>">>