No s2s-connectivity between ejabberd and xmpp.jp

[delitrem]

Hello there.

I'm in doubt where is a bug, so I write here first. :) I have ejabberd (version is 24.07, compiled from source using erlang 27.0.1) which has no problems in communication with several XMPP-servers (tested ones: conversations.im, jabberes.org, process-one.net and may be some others), but has no s2s-connectivity with xmpp.jp. In log there is just a message about s2s_out timeout and no more info. Meanwhile prosody works fine with that server. And also ejabberd works when I turn off tls for s2s. I'm testing the connectivity by sending disco iq from xmpp-client.

[delitrem]

My ejabberd is running under Guix System, but it seems it doesn't matter -- I have also tested it with Debian GNU/Linux (from docker box). SSL certs are from Letsencrypt, if it is important. Here are some logs related to this issue:

2024-08-22 13:51:08.842101+03:00 [notice] <0.710.0> (tls|<0.710.0>) Received XML on stream = <<"<iq xmlns=\"jabber:client\" to=\"xmpp.jp\" type=\"get\" id=\"102ee996-ae6e-4da2-b8df-9e568f21ddef\"><query xmlns=\"http://jabber.org/protocol/disco#info\" /></iq>">>
2024-08-22 13:51:08.843573+03:00 [debug] <0.710.0>@ejabberd_router:do_route/1:384 Route:
#iq{id = <<"102ee996-ae6e-4da2-b8df-9e568f21ddef">>,type = get,
    lang = <<"en">>,
    from = #jid{user = <<"test">>,server = <<"[REDACTED]">>,
                resource = <<"gajim.IE4D5THK">>,luser = <<"test">>,
                lserver = <<"[REDACTED]">>,lresource = <<"gajim.IE4D5THK">>},
    to = #jid{user = <<>>,server = <<"xmpp.jp">>,resource = <<>>,luser = <<>>,
              lserver = <<"xmpp.jp">>,lresource = <<>>},
    sub_els = [#xmlel{name = <<"query">>,
                      attrs = [{<<"xmlns">>,
                                <<"http://jabber.org/protocol/disco#info">>}],
                      children = []}],
    meta = #{ip => {0,0,0,0,0,65535,2602,10762}}}
2024-08-22 13:51:08.843821+03:00 [debug] <0.710.0>@ejabberd_s2s:route/1:325 Local route:
#iq{id = <<"102ee996-ae6e-4da2-b8df-9e568f21ddef">>,type = get,
    lang = <<"en">>,
    from = #jid{user = <<"test">>,server = <<"[REDACTED]">>,
                resource = <<"gajim.IE4D5THK">>,luser = <<"test">>,
                lserver = <<"[REDACTED]">>,lresource = <<"gajim.IE4D5THK">>},
    to = #jid{user = <<>>,server = <<"xmpp.jp">>,resource = <<>>,luser = <<>>,
              lserver = <<"xmpp.jp">>,lresource = <<>>},
    sub_els = [#xmlel{name = <<"query">>,
                      attrs = [{<<"xmlns">>,
                                <<"http://jabber.org/protocol/disco#info">>}],
                      children = []}],
    meta = #{ip => {0,0,0,0,0,65535,2602,10762}}}
2024-08-22 13:51:08.843990+03:00 [debug] <0.710.0>@ejabberd_s2s:start_connection/3:363 Finding connection for {<<"[REDACTED]">>,<<"xmpp.jp">>}
2024-08-22 13:51:08.844197+03:00 [info] <0.726.0>@ejabberd_s2s_out:init/1:289 Outbound s2s connection started: [REDACTED] -> xmpp.jp
2024-08-22 13:51:08.844296+03:00 [debug] <0.726.0>@ejabberd_hooks:safe_apply/4:451 Running hook s2s_out_init: mod_s2s_dialback:s2s_out_init/2
2024-08-22 13:51:08.844619+03:00 [debug] <0.710.0>@ejabberd_s2s:choose_pid/2:413 Using ejabberd_s2s_out <0.726.0>
2024-08-22 13:51:08.844794+03:00 [debug] <0.710.0>@ejabberd_s2s:route/1:330 Sending to process <0.726.0>
2024-08-22 13:51:09.723041+03:00 [notice] <0.726.0> (tls|<0.726.0>) Send XML on stream = <<"<?xml version='1.0'?><stream:stream version='1.0' xml:lang='en' xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' to='xmpp.jp' from='[REDACTED]' xmlns='jabber:server'>">>
2024-08-22 13:51:10.005596+03:00 [notice] <0.726.0> (tls|<0.726.0>) Send XML on stream = <<"</stream:stream>">>
2024-08-22 13:51:10.005978+03:00 [debug] <0.726.0>@ejabberd_hooks:safe_apply/4:451 Running hook s2s_out_closed: mod_s2s_dialback:s2s_out_closed/2
2024-08-22 13:51:10.006086+03:00 [debug] <0.726.0>@ejabberd_hooks:safe_apply/4:451 Running hook s2s_out_closed: ejabberd_s2s_out:process_closed/2
2024-08-22 13:51:10.006294+03:00 [warning] <0.726.0>@ejabberd_s2s_out:process_closed/2:157 Failed to establish outbound s2s connection [REDACTED] -> xmpp.jp: Connection failed: connection closed; bouncing for 142 seconds
2024-08-22 13:51:10.006461+03:00 [debug] <0.726.0>@ejabberd_router:do_route/1:384 Route:
#iq{id = <<"102ee996-ae6e-4da2-b8df-9e568f21ddef">>,type = error,
    lang = <<"en">>,
    from =
        #jid{
            user = <<>>,server = <<"xmpp.jp">>,resource = <<>>,luser = <<>>,
            lserver = <<"xmpp.jp">>,lresource = <<>>},
    to =
        #jid{
            user = <<"test">>,server = <<"[REDACTED]">>,
            resource = <<"gajim.IE4D5THK">>,luser = <<"test">>,
            lserver = <<"[REDACTED]">>,lresource = <<"gajim.IE4D5THK">>},
    sub_els =
        [#xmlel{
             name = <<"query">>,
             attrs =
                 [{<<"xmlns">>,<<"http://jabber.org/protocol/disco#info">>}],
             children = []},
         #stanza_error{
             type = wait,by = undefined,reason = 'remote-server-timeout',
             text =
                 [#text{
                      lang = <<"en">>,
                      data = <<"Connection failed: connection closed">>}],
             sub_els = []}],
    meta = #{ip => {0,0,0,0,0,65535,2602,10762}}}
2024-08-22 13:51:10.006772+03:00 [debug] <0.726.0>@ejabberd_local:route/1:74 Local route:
#iq{id = <<"102ee996-ae6e-4da2-b8df-9e568f21ddef">>,type = error,
    lang = <<"en">>,
    from =
        #jid{
            user = <<>>,server = <<"xmpp.jp">>,resource = <<>>,luser = <<>>,
            lserver = <<"xmpp.jp">>,lresource = <<>>},
    to =
        #jid{
            user = <<"test">>,server = <<"[REDACTED]">>,
            resource = <<"gajim.IE4D5THK">>,luser = <<"test">>,
            lserver = <<"[REDACTED]">>,lresource = <<"gajim.IE4D5THK">>},
    sub_els =
        [#xmlel{
             name = <<"query">>,
             attrs =
                 [{<<"xmlns">>,<<"http://jabber.org/protocol/disco#info">>}],
             children = []},
         #stanza_error{
             type = wait,by = undefined,reason = 'remote-server-timeout',
             text =
                 [#text{
                      lang = <<"en">>,
                      data = <<"Connection failed: connection closed">>}],
             sub_els = []}],
    meta = #{ip => {0,0,0,0,0,65535,2602,10762}}}

[prefiks]

So i think this is caused by misconfiguration of xmpp.jp server, it looks like it have srv records for both xmpp-server and xmpps-server pointing to this same address/port, and i think that port works only as xmpp-server (it requires using starttls). And looks like we try first to connect to it using direct tls, and when that fails we abort connection completely. Probably changing our code to try to connect to next choice when that happens is something that we should add, i will look at that.

[prefiks]

I added commit 8e7489c that should help here.

[delitrem]

I added commit 8e7489c that should help here.

It seems there are some different problems, here is log:

2024-08-24 14:52:02.227652+03:00 [notice] <0.711.0> (tls|<0.711.0>) Received XML on stream = <<"<iq xmlns=\"jabber:client\" to=\"xmpp.jp\" type=\"get\" id=\"08d00e71-3989-49ea-8a8c-00e219bba19f\"><query xmlns=\"http://jabber.org/protocol/disco#info\" /></iq>">>
[...]
2024-08-24 14:52:02.551021+03:00 [error] <0.735.0> ** Generic server <0.735.0> terminating 
** Last message in was {'$gen_cast',connect}
** When Server state == #{owner => <0.735.0>,user => <<>>,
                          queue => {{[],[]},0,unlimited},
                          mod => ejabberd_s2s_out,server => <<"[REDACTED]">>,
                          resource => <<>>,password => <<>>,
                          codec_options => [ignore_els],
                          shaper => none,lang => <<"en">>,
                          stream_encrypted => false,
                          remote_server => <<"xmpp.jp">>,
                          server_host => <<"[REDACTED]">>,
                          xmlns => <<"jabber:server">>,db_enabled => true,
                          on_route => queue,
                          stream_id => <<"15390597103600140413">>,
                          stream_state => connecting,
                          stream_timeout => -576460531678,
                          stream_authenticated => false,
                          stream_direction => out,stream_restarted => false,
                          stream_version => {1,0},
                          stream_verified => false}
** Reason for termination == 
** {function_clause,
       [{xmpp_socket,finish_tls_handshake,
            [{socket_state,gen_tcp,#Port<0.96>,infinity,
                 #Ref<0.1376625168.3993632769.70929>,none,none,none}],
            [{file,
                 "/path/to/ejabberd/_build/default/lib/xmpp/src/xmpp_socket.erl"},
             {line,194}]},
        {xmpp_stream_out,connect,2,
            [{file,
                 "/path/to/ejabberd/_build/default/lib/xmpp/src/xmpp_stream_out.erl"},
             {line,1408}]},
        {xmpp_stream_out,handle_cast,2,
            [{file,
                 "/path/to/ejabberd/_build/default/lib/xmpp/src/xmpp_stream_out.erl"},
             {line,352}]},
        {p1_server,handle_msg,8,
            [{file,
                 "/path/to/ejabberd/_build/default/lib/p1_utils/src/p1_server.erl"},
             {line,696}]},
        {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,329}]}]}
[...]
2024-08-24 14:52:02.553046+03:00 [notice] <0.711.0> (tls|<0.711.0>) Send XML on stream = <<"<iq xml:lang='en' to='test@[REDACTED]/gajim.IE4D5THK' from='xmpp.jp' type='error' id='08d00e71-3989-49ea-8a8c-00e219bba19f'><query xmlns='http://jabber.org/protocol/disco#info'/><error type='wait'><internal-server-error xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/><text xml:lang='en' xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'>Internal server error</text></error></iq>">>
2024-08-24 14:52:02.551651+03:00 [error] <0.735.0>@proc_lib:crash_report/4:948 CRASH REPORT:
  crasher:
    initial call: xmpp_stream_out:init/1
    pid: <0.735.0>
    registered_name: []
    exception exit: {function_clause,
                        [{xmpp_socket,finish_tls_handshake,
                             [{socket_state,gen_tcp,#Port<0.96>,infinity,
                                  #Ref<0.1376625168.3993632769.70929>,none,
                                  none,none}],
                             [{file,
                                  "/path/to/ejabberd/_build/default/lib/xmpp/src/xmpp_socket.erl"},
                              {line,194}]},
                         {xmpp_stream_out,connect,2,
                             [{file,
                                  "/path/to/ejabberd/_build/default/lib/xmpp/src/xmpp_stream_out.erl"},
                              {line,1408}]},
                         {xmpp_stream_out,handle_cast,2,
                             [{file,
                                  "/path/to/ejabberd/_build/default/lib/xmpp/src/xmpp_stream_out.erl"},
                              {line,352}]},
                         {p1_server,handle_msg,8,
                             [{file,
                                  "/path/to/ejabberd/_build/default/lib/p1_utils/src/p1_server.erl"},
                              {line,696}]},
                         {proc_lib,init_p_do_apply,3,
                             [{file,"proc_lib.erl"},{line,329}]}]}
      in function  p1_server:terminate/7 (/path/to/ejabberd/_build/default/lib/p1_utils/src/p1_server.erl, line 878)
    ancestors: [ejabberd_s2s_out_sup,ejabberd_sup,<0.119.0>]
    message_queue_len: 1
    messages: [{tcp,#Port<0.96>,<<>>}]
    links: [<0.359.0>,#Port<0.96>]
    dictionary: [{rand_seed,{#{type => exsss,next => #Fun<rand.0.40079776>,
                                bits => 58,uniform => #Fun<rand.1.40079776>,
                                uniform_n => #Fun<rand.2.40079776>,
                                jump => #Fun<rand.3.40079776>},
                              [174501472407194391|229034340837039495]}},
                  {'$internal_queue_len',0},
                  {already_terminated,true}]
    trap_exit: false
    status: running
    heap_size: 6772
    stack_size: 29
    reductions: 102043
  neighbours:

[prefiks]

Yeah, i missed some things, i commited fix for that today, so if you can try current master.

[delitrem]

Yeah, i missed some things, i commited fix for that today, so if you can try current master.

That was up-to-date master branch with last commit 34a58863e3c3b77fc081fca194d4ab7ab16647fe.

[prefiks]

Ah, fix for that commited

[delitrem]

Ah, fix for that commited

Thank you very much, now it works as expected.