extauth ok when manual action, but nok when service ejabberd launch program

[PgC-95]

Environment

• ejabberd version: ejabberd 25.8.0
• Erlang version: erlang26 or erlang27 or erlang28
• OS: Linux (Alpine) and Linux (Debian)
• Installed from: ghcr.io/processone/ejabberd in docker

Configuration

hosts:
  - "localhost"
auth_method:
  - external
extauth_program: "/opt/ejabberd/conf/script.py"
extauth_pool_size: 3
auth_use_cache: false
loglevel: 5
log_rotate_count: 0
host_config:
  localhost:
    sql_type: pgsql
    sql_server: xxxxxxxxx
    sql_database: xxxxx
    sql_username: xxxxxx
    sql_password: xxxxxxxxx
    auth_method: [sql]
certfiles:
  - "/opt/ejabberd/conf/pem.pem"
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
    shaper: s2s_shaper
  -
    port: 5443
    ip: "::"
    module: ejabberd_http
    tls: true
    protocol_options: 'TLS_OPTIONS'
    request_handlers:
      /api: mod_http_api
      /bosh: mod_bosh
      /admin: ejabberd_web_admin
      /ws: ejabberd_http_ws
  -
    port: 5280
    ip: "::"
    module: ejabberd_http
    tls: true
    protocol_options: 'TLS_OPTIONS'
    request_handlers:
      /ws: ejabberd_http_ws
      /api: mod_http_api
      /admin: ejabberd_web_admin
      /.well-known/acme-challenge: ejabberd_acme
  -
    port: 5478
    ip: "::"
    transport: udp
    module: ejabberd_stun
    use_turn: true
  -
    port: 1883
    ip: "::"
    module: mod_mqtt
    backlog: 1000
disable_sasl_mechanisms:
  - "DIGEST-MD5"
  - "SCRAM-SHA-512-PLUS"
  - "SCRAM-SHA-512"
  - "SCRAM-SHA-256-PLUS"
  - "SCRAM-SHA-256"
  - "SCRAM-SHA-1-PLUS"
  - "SCRAM-SHA-1"
  - "X-OAUTH2"
s2s_use_starttls: required
auth_password_format: plain
acl:
  local:
    user_regexp: ""
  loopback:
    ip:
      - 127.0.0.0/8
      - ::1/128
      - 172.17.0.0/24
  admin:
     user:
       - "admin"
       - "admin@localhost"
access_rules:
  local:
    allow:
      - local
      - admin
  c2s:
    allow: all
  announce:
    allow: admin
  configure:
    allow: admin
  muc_create:
    allow: local
  pubsub_createnode:
    allow: local
  trusted_network:
    allow: loopback
api_permissions:
  "console commands":
    from: ejabberd_ctl
    who: all
    what: "*"
  "webadmin commands":
    from: ejabberd_web_admin
    who: admin
    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:
      acl: loopback
      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
    1100: all
  c2s_shaper:
    none: admin
    normal: all
  s2s_shaper: fast
modules:
  mod_adhoc: {}
  mod_auth: {}
  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_http_api: {}
  mod_last: {}
  mod_mam:
    assume_mam_usage: true
    default: always
  mod_mqtt: {}
  mod_muc:
    access:
      - allow
    access_admin:
      - allow: admin
    access_create: muc_create
    access_persistent: muc_create
    access_mam:
      - allow
    default_room_options:
      persistent: true
      mam: true
  mod_muc_admin: {}
  mod_offline:
  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:
      storage:bookmarks:
        access_model: whitelist
  mod_push:
    notify_on: messages
    include_sender: true
  mod_push_keepalive: {}
  mod_roster:
    versioning: true
  mod_s2s_bidi: {}
  mod_s2s_dialback: {}
  mod_shared_roster: {}
  mod_sic: {}
  mod_stats: {}
  mod_stream_mgmt:
    resend_on_timeout: if_offline
  mod_stun_disco: {}
  mod_vcard:
    search: false
  mod_vcard_xupdate: {}
  mod_version: {}

Errors from error.log/crash.log

2025-09-12 10:05:28.302053+00:00 [info] <0.533.0>@ejabberd_listener:accept/7:382 (<0.19671.0>) Accepted connection [::ffff:172.17.0.1]:58838 -> [::ffff:172.17.0.6]:5222
2025-09-12 10:05:28.302547+00:00 [notice] <0.19671.0> (tcp|<0.19671.0>) Received XML on stream = <<"<?xml version='1.0' ?><stream:stream to='localhost' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>">>
2025-09-12 10:05:28.303088+00:00 [notice] <0.19671.0> (tcp|<0.19671.0>) Send XML on stream = <<"<?xml version='1.0'?><stream:stream id='16254405682368202107' version='1.0' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' from='localhost' xmlns='jabber:client'>">>
2025-09-12 10:05:28.303532+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_stream_started: mod_client_state:c2s_stream_started/2
2025-09-12 10:05:28.303748+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_stream_started: mod_stream_mgmt:c2s_stream_started/2
2025-09-12 10:05:28.303943+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_stream_started: mod_fail2ban:c2s_stream_started/2
2025-09-12 10:05:28.304232+00:00 [notice] <0.19671.0> (tcp|<0.19671.0>) Send XML on stream = <<"<stream:features><starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'><required/></starttls></stream:features>">>
2025-09-12 10:05:28.304610+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_handle_send: mod_push:c2s_stanza/3
2025-09-12 10:05:28.304764+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_handle_send: mod_push_keepalive:c2s_stanza/3
2025-09-12 10:05:28.304922+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_handle_send: mod_stream_mgmt:c2s_handle_send/3
2025-09-12 10:05:28.308733+00:00 [notice] <0.19671.0> (tcp|<0.19671.0>) Received XML on stream = <<"<starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>">>
2025-09-12 10:05:28.309007+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_handle_recv: mod_stream_mgmt:c2s_handle_recv/3
2025-09-12 10:05:28.309548+00:00 [notice] <0.19671.0> (tcp|<0.19671.0>) Send XML on stream = <<"<proceed xmlns='urn:ietf:params:xml:ns:xmpp-tls'/>">>
2025-09-12 10:05:28.309835+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_handle_send: mod_push:c2s_stanza/3
2025-09-12 10:05:28.309972+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_handle_send: mod_push_keepalive:c2s_stanza/3
2025-09-12 10:05:28.310146+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_handle_send: mod_stream_mgmt:c2s_handle_send/3
2025-09-12 10:05:28.334224+00:00 [notice] <0.19671.0> (tls|<0.19671.0>) Received XML on stream = <<"<stream:stream to='localhost' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>">>
2025-09-12 10:05:28.334644+00:00 [notice] <0.19671.0> (tls|<0.19671.0>) Send XML on stream = <<"<?xml version='1.0'?><stream:stream id='8191665311936687673' version='1.0' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' from='localhost' xmlns='jabber:client'>">>
2025-09-12 10:05:28.335033+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_stream_started: mod_client_state:c2s_stream_started/2
2025-09-12 10:05:28.335252+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_stream_started: mod_stream_mgmt:c2s_stream_started/2
2025-09-12 10:05:28.335405+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_stream_started: mod_fail2ban:c2s_stream_started/2
2025-09-12 10:05:28.336081+00:00 [notice] <0.19671.0> (tls|<0.19671.0>) Send XML on stream = <<"<stream:features><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>PLAIN</mechanism></mechanisms><sasl-channel-binding xmlns='urn:xmpp:sasl-cb:0'><channel-binding type='tls-exporter'/><channel-binding type='tls-server-end-point'/></sasl-channel-binding></stream:features>">>
2025-09-12 10:05:28.336484+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_handle_send: mod_push:c2s_stanza/3
2025-09-12 10:05:28.336685+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_handle_send: mod_push_keepalive:c2s_stanza/3
2025-09-12 10:05:28.336906+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_handle_send: mod_stream_mgmt:c2s_handle_send/3
2025-09-12 10:05:28.337132+00:00 [notice] <0.19671.0> (tls|<0.19671.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'>AGdkb2ZmAHBsb3Vm</auth>">>
2025-09-12 10:05:28.337513+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_handle_recv: mod_stream_mgmt:c2s_handle_recv/3
2025-09-12 10:05:33.338551+00:00 [error] <0.598.0>@ejabberd_sql:check_error/2:1425 SQL query 'Q111059269' at {ejabberd_auth_sql,{300,12}} failed: <<"timed out">>
2025-09-12 10:05:33.339073+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_auth_result: ejabberd_c2s:process_auth_result/3
2025-09-12 10:05:33.339256+00:00 [warning] <0.19671.0>@ejabberd_c2s:process_auth_result/3:312 (tls|<0.19671.0>) Failed c2s PLAIN authentication for ping@localhost from ::ffff:172.17.0.1: Invalid username or password
2025-09-12 10:05:33.339456+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_auth_result: mod_fail2ban:c2s_auth_result/3
2025-09-12 10:05:33.339767+00:00 [notice] <0.19671.0> (tls|<0.19671.0>) Send XML on stream = <<"<failure xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><not-authorized/><text xml:lang='en'>Invalid username or password</text></failure>">>
2025-09-12 10:05:33.340168+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_handle_send: mod_push:c2s_stanza/3
2025-09-12 10:05:33.340321+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_handle_send: mod_push_keepalive:c2s_stanza/3
2025-09-12 10:05:33.340466+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_handle_send: mod_stream_mgmt:c2s_handle_send/3
2025-09-12 10:05:33.348786+00:00 [notice] <0.19671.0> (tls|<0.19671.0>) Received XML on stream = <<"</stream:stream>">>
2025-09-12 10:05:33.349014+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_closed: mod_stream_mgmt:c2s_closed/2
2025-09-12 10:05:33.349207+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_closed: ejabberd_c2s:process_closed/2
2025-09-12 10:05:33.349532+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_terminated: mod_stream_mgmt:c2s_terminated/2
2025-09-12 10:05:33.349694+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_terminated: mod_pubsub:on_user_offline/2
2025-09-12 10:05:33.349834+00:00 [debug] <0.19671.0>@ejabberd_hooks:safe_apply/4:451 Running hook c2s_terminated: ejabberd_c2s:process_terminated/2
2025-09-12 10:05:33.349960+00:00 [notice] <0.19671.0> (tls|<0.19671.0>) Send XML on stream = <<"</stream:stream>">>
2025-09-12 10:06:26.365090+00:00 [error] <0.18747.0>@gen_server:error_info/8:2646 GenServer #PID<0.18747.0> terminating

Bug description

I use a python script to authenticate from an external API. I tested it manually, pushing auth:user:host:passwd, and it pass, it can return the token :

2025-09-09 13:31:49 [INFO] Starting authentication script.
2025-09-09 13:31:49 [DEBUG] Waiting for input...
2025-09-09 13:31:49 [DEBUG] Expecting 29 bytes of input.
2025-09-09 13:31:49 [DEBUG] Received data: auth:ping:localhost:pong
2025-09-09 13:31:49 [DEBUG] Parsed input → Action: auth, username: ping, Password: ***
2025-09-09 13:31:49 [INFO] Authenticating username='ping'
2025-09-09 13:31:49 [DEBUG] POST https://externalserver/api/login with payload: {'username': 'ping', 'password': 'pong'}
2025-09-09 13:31:49 [DEBUG] Starting new HTTPS connection (1): externalserver:443
2025-09-09 13:31:49 [DEBUG] https://externalserver:443 "POST /api/login HTTP/1.1" 200 None
2025-09-09 13:31:49 [DEBUG] API response: status_code=200, body='{"tokens":{"accessToken":"eyJhbGciOiJI .......

But when i try it with the ejabberd service, it fails (you can see it on fails logs)

I tryied differents solutions. I tryied too first to install in a debian 12 and the problem is the same.

If you have a solution for me... or something which can help me.

[badlop]

First you setup one vhost, "localhost":

hosts:
  - "localhost"

Then you tell ejabberd to use an external script to authenticate users by default in all the vhosts:

auth_method:
  - external
extauth_program: "/opt/ejabberd/conf/script.py"
extauth_pool_size: 3

And then you tell ejabberd to use SQL to authenticate users specifically in localhost:

host_config:
  localhost:
    sql_type: pgsql
    sql_server: xxxxxxxxx
    sql_database: xxxxx
    sql_username: xxxxxx
    sql_password: xxxxxxxxx
    auth_method: [sql]

Then, quite obviously, when a client logins to an account in "localhost", ejabberd will use the SQL authentication method. And that returns "timed out", which later ejabberd reports to the client as "invalid username or password". Maybe the SQL database is not properly configured, ot the sql server is not running, or the account is not registered in the sql database...

2025-09-12 10:05:28.302547+00:00 [notice]
  <0.19671.0> (tcp|<0.19671.0>)
  Received XML on stream = <<"<?xml version='1.0' ?>
  <stream:stream
    to='localhost'
    xmlns='jabber:client'
    xmlns:stream='http://etherx.jabber.org/streams'
    version='1.0'>">>

2025-09-12 10:05:33.338551+00:00 [error]
  <0.598.0>@ejabberd_sql:check_error/2:1425
  SQL query 'Q111059269' at {ejabberd_auth_sql,{300,12}} failed:
  <<"timed out">>

2025-09-12 10:05:33.339256+00:00 [warning]
  <0.19671.0>@ejabberd_c2s:process_auth_result/3:312 (tls|<0.19671.0>)
  Failed c2s PLAIN authentication for ping@localhost from ::ffff:172.17.0.1:
  Invalid username or password

---

If you plan to have only one vhost, and want to use external authentication, and SQL storage for other stuff (like rosters, offline messages, ...) then configure:

hosts:
  - "localhost"

auth_method:
  - external
extauth_program: "/opt/ejabberd/conf/script.py"
extauth_pool_size: 3

sql_type: pgsql
sql_server: xxxxxxxxx
sql_database: xxxxx
sql_username: xxxxxx
sql_password: xxxxxxxxx
default_db: sql

If you plan to have several vhosts in the future, and want to use external authentication in all of them, SQL storage in "localhost", and mnesia in other vhosts:

hosts:
  - "localhost"

auth_method:
  - external
extauth_program: "/opt/ejabberd/conf/script.py"
extauth_pool_size: 3

host_config:
  localhost:
    sql_type: pgsql
    sql_server: xxxxxxxxx
    sql_database: xxxxx
    sql_username: xxxxxx
    sql_password: xxxxxxxxx
    default_db: sql