csrado commented 1 year ago

Hello community,

Trying to get up and running ejabberd and chatsecure push notification. in Jabberd log see error:

mod_push:notify/5:532 pubsub.chatsecure.org rejected notification for xxx@xxx.xx (368A0306-3DBE-47A3-B557-9F16845A6E3D) temporarily: Stream reset by peer (remote-server-timeout)

When do tcpdump, TLS 1.2 exchange looks ok, 3 packets with application data (encrypted), chatsecure sending message "Encrypted Alert", connection closed.

-> update, debug is here

2023-08-23 11:07:18.388923+00:00 [debug] <0.646.0>@ejabberd_s2s:start_connection/3:362 Finding connection for {<<"msg.xxx.xom">>,<<"pubsub.chatsecure.org">>}

2023-08-23 11:07:18.390753+00:00 [info] <0.686.0>@ejabberd_s2s_out:init/1:289 Outbound s2s connection started: msg.xxx.xom -> pubsub.chatsecure.org 2023-08-23 11:07:18.391138+00:00 [debug] <0.686.0>@ejabberd_hooks:safe_apply/4:315 Running hook s2s_out_init: mod_s2s_dialback:s2s_out_init/2 2023-08-23 11:07:18.391959+00:00 [debug] <0.646.0>@ejabberd_s2s:choose_pid/2:412 Using ejabberd_s2s_out <0.686.0>

2023-08-23 11:07:18.392191+00:00 [debug] <0.646.0>@ejabberd_s2s:route/1:329 Sending to process <0.686.0>

2023-08-23 11:07:18.392336+00:00 [debug] <0.646.0>@ejabberd_hooks:safe_apply/4:315 Running hook store_mam_message: mod_mam:store_mam_message/7 2023-08-23 11:07:18.677683+00:00 [notice] <0.686.0> (tcp|<0.686.0>) Send XML on stream = <<"<?xml version='1.0'?>">> 2023-08-23 11:07:18.875862+00:00 [debug] <0.646.0>@ejabberd_hooks:safe_apply/4:315 Running hook offline_message_hook: mod_offline:store_packet/1 2023-08-23 11:07:18.909589+00:00 [notice] <0.686.0> (tcp|<0.686.0>) Received XML on stream = <<"<stream:stream xmlns:stream=\"http://etherx.jabber.org/streams\" xmlns=\"jabber:server\" xmlns:db=\"jabber:server:dialback\" version=\"1.0\" id=\"db668632c54337451bea204c417cb1a6\">">> 2023-08-23 11:07:19.140481+00:00 [notice] <0.686.0> (tcp|<0.686.0>) Received XML on stream = <<"<starttls xmlns=\"urn:ietf:params:xml:ns:xmpp-tls\"></stream:features>">> 2023-08-23 11:07:19.141066+00:00 [notice] <0.686.0> (tcp|<0.686.0>) Send XML on stream = <<"">> 2023-08-23 11:07:19.373461+00:00 [notice] <0.686.0> (tcp|<0.686.0>) Received XML on stream = <<"<proceed xmlns=\"urn:ietf:params:xml:ns:xmpp-tls\"/>">> 2023-08-23 11:07:19.375849+00:00 [notice] <0.686.0> (tls|<0.686.0>) Send XML on stream = <<"<?xml version='1.0'?>">> 2023-08-23 11:07:19.534363+00:00 [debug] <0.646.0>@ejabberd_hooks:safe_apply/4:315 Running hook offline_message_hook: mod_push:offline_message/1 2023-08-23 11:07:19.534685+00:00 [debug] <0.646.0>@ejabberd_hooks:safe_apply/4:315 Running hook offline_message_hook: ejabberd_sm:bounce_offline_message/1 2023-08-23 11:07:19.535043+00:00 [notice] <0.646.0> (tls|<0.646.0>) Received XML on stream = <<"">> 2023-08-23 11:07:19.535468+00:00 [debug] <0.646.0>@ejabberd_hooks:safe_apply/4:315 Running hook c2s_handle_recv: mod_stream_mgmt:c2s_handle_recv/3 2023-08-23 11:07:19.535782+00:00 [debug] <0.646.0>@ejabberd_hooks:safe_apply/4:315 Running hook c2s_authenticated_packet: mod_client_state:c2s_authenticated_packet/2 2023-08-23 11:07:19.536325+00:00 [debug] <0.646.0>@ejabberd_hooks:safe_apply/4:315 Running hook c2s_authenticated_packet: mod_stream_mgmt:c2s_authenticated_packet/2 2023-08-23 11:07:19.537394+00:00 [debug] <0.646.0>@mod_stream_mgmt:check_h_attribute/2:480 macau@msg.xxx.xom/iPad acknowledged 21 of 21 stanzas 2023-08-23 11:07:19.537731+00:00 [debug] <0.646.0>@ejabberd_hooks:safe_apply/4:315 Running hook c2s_handle_recv: mod_stream_mgmt:c2s_handle_recv/3 2023-08-23 11:07:19.538022+00:00 [debug] <0.646.0>@ejabberd_hooks:safe_apply/4:315 Running hook c2s_authenticated_packet: mod_client_state:c2s_authenticated_packet/2 2023-08-23 11:07:19.538289+00:00 [debug] <0.646.0>@ejabberd_hooks:safe_apply/4:315 Running hook c2s_authenticated_packet: mod_stream_mgmt:c2s_authenticated_packet/2 2023-08-23 11:07:19.538624+00:00 [debug] <0.646.0>@mod_stream_mgmt:check_h_attribute/2:480 macau@msg.xxx.xom/iPad acknowledged 21 of 21 stanzas 2023-08-23 11:07:19.853012+00:00 [notice] <0.686.0> (tls|<0.686.0>) Received XML on stream = <<"<stream:stream xmlns:stream=\"http://etherx.jabber.org/streams\" xmlns=\"jabber:server\" xmlns:db=\"jabber:server:dialback\" version=\"1.0\" id=\"db668632c54337451bea204c417cb1a6\">">> 2023-08-23 11:07:20.085367+00:00 [notice] <0.686.0> (tls|<0.686.0>) Received XML on stream = <<"<mechanisms xmlns=\"urn:ietf:params:xml:ns:xmpp-sasl\">EXTERNAL</stream:features>">> 2023-08-23 11:07:20.087202+00:00 [debug] <0.686.0>@ejabberd_hooks:safe_apply/4:315 Running hook s2s_out_tls_verify: mod_s2s_dialback:s2s_out_tls_verify/2 2023-08-23 11:07:20.087916+00:00 [notice] <0.686.0> (tls|<0.686.0>) Send XML on stream = <<"c2kudHJlZXJlc291cmNlcy5tbw==">> 2023-08-23 11:07:20.322630+00:00 [notice] <0.686.0> (tls|<0.686.0>) Received XML on stream = <<"<failure xmlns=\"urn:ietf:params:xml:ns:xmpp-sasl\"></stream:stream>">> 2023-08-23 11:07:20.326158+00:00 [warning] <0.686.0>@ejabberd_s2s_out:handle_auth_failure/3:233 (tls|<0.686.0>) Failed outbound s2s EXTERNAL authentication msg.xxx.xom -> pubsub.chatsecure.org (45.55.5.246): Authentication failed: Peer responded with error: not-authorized 2023-08-23 11:07:20.326511+00:00 [debug] <0.686.0>@ejabberd_hooks:safe_apply/4:315 Running hook s2s_out_auth_result: mod_s2s_dialback:s2s_out_auth_result/2 2023-08-23 11:07:20.328594+00:00 [info] <0.686.0>@mod_s2s_dialback:s2s_out_auth_result/2:178 (tls|<0.686.0>) Retrying with s2s dialback authentication: msg.xxx.xom -> pubsub.chatsecure.org (45.55.5.246) 2023-08-23 11:07:20.337336+00:00 [notice] <0.686.0> (tls|<0.686.0>) Send XML on stream = <<"9ff800a1046847901b4f56559be4e2e6b8e67b46cb7e34c4dbc6f4b66f388bca</db:result>">> 2023-08-23 11:07:20.337811+00:00 [notice] <0.686.0> (tls|<0.686.0>) Send XML on stream = <<"</stream:stream>">> 2023-08-23 11:07:20.338283+00:00 [debug] <0.686.0>@ejabberd_hooks:safe_apply/4:315 Running hook s2s_out_closed: mod_s2s_dialback:s2s_out_closed/2 2023-08-23 11:07:20.338473+00:00 [debug] <0.686.0>@ejabberd_hooks:safe_apply/4:315 Running hook s2s_out_closed: ejabberd_s2s_out:process_closed/2 2023-08-23 11:07:20.338762+00:00 [warning] <0.686.0>@ejabberd_s2s_out:process_closed/2:157 Failed to establish outbound s2s connection msg.xxx.xom -> pubsub.chatsecure.org: Stream reset by peer; bouncing for 64 seconds 2023-08-23 11:07:20.339397+00:00 [debug] <0.686.0>@ejabberd_router:do_route/1:384 Route: 2023-08-23 11:07:20.339397+00:00 [debug] <0.686.0>@ejabberd_router:do_route/1:384 Route:

iq{id =

    <<"rr-1692788870377-4495702514281454328-FBe4CR8uKxiihXDakn09ek/01l0=-55238004">>,
type = error,lang = <<>>,
from =
    #jid{
        user = <<>>,server = <<"pubsub.chatsecure.org">>,resource = <<>>,
        luser = <<>>,lserver = <<"pubsub.chatsecure.org">>,
        lresource = <<>>},
to =
    #jid{
        user = <<>>,server = <<"msg.xxx.xom">>,resource = <<>>,
        luser = <<>>,lserver = <<"msg.xxx.xom">>,lresource = <<>>},
sub_els =
    [#pubsub{
         subscriptions = undefined,subscription = undefined,
         affiliations = undefined,
         publish =
             #ps_publish{
                 node = <<"BFD22A0E-C4A3-4ADC-96C1-6328CA492B92">>,
                 items =
                     [#ps_item{
                          xmlns = <<>>,id = <<>>,
                          sub_els =
                              [#push_notification{xdata = undefined}],
                          node = <<>>,publisher = <<>>}]},
         publish_options =
             #xdata{
                 type = submit,instructions = [],title = undefined,
                 reported = undefined,items = [],
                 fields =
                     [#xdata_field{
                          label = <<>>,type = undefined,
                          var = <<"FORM_TYPE">>,required = false,
                          desc = <<>>,
                          values =
                              [<<"http://jabber.org/protocol/pubsub#publish-options">>],
                          options = [],sub_els = []},
                      #xdata_field{
                          label = <<>>,type = undefined,var = <<"token">>,
                          required = false,desc = <<>>,
                          values =
                              [<<"eeb66a95dc4977e0b28763256ee21bc8a47f041a">>],
                          options = [],sub_els = []},
                      #xdata_field{
                          label = <<>>,type = undefined,
                          var = <<"endpoint">>,required = false,
                          desc = <<>>,
                          values =
                              [<<"https://push.chatsecure.org/api/v1/messages/">>],
                          options = [],sub_els = []}]},
         subscribe = undefined,unsubscribe = undefined,
         options = undefined,items = undefined,retract = undefined,
         create = undefined,configure = undefined,default = undefined,
         delete = undefined,purge = undefined,rsm = undefined},
     #stanza_error{
         type = wait,by = undefined,reason = 'remote-server-timeout',
         text = [#text{lang = <<"en">>,data = <<"Stream reset by peer">>}],
         sub_els = []}],
meta = #{}}

2023-08-23 11:07:20.340373+00:00 [info] <0.482.0>@mod_push:notify/5:532 pubsub.chatsecure.org rejected notification for chatsecure@msg.xxx.xom (BFD22A0E-C4A3-4ADC-96C1-6328CA492B92) temporarily: Stream reset by peer (remote-server-timeout)

Any idea?

Thank you

Letterus commented 9 months ago

Same issue using Metronome as a server. A fix would be great. Monal push server works.

It's:

Failed outbound s2s EXTERNAL authentication

Or for Metronome:

Feb 03 14:49:53 my.server.eu:sasl_s2s   info    SASL EXTERNAL with pubsub.chatsecure.org failed

So, some kind of SASL/TLS failure.

Letterus commented 9 months ago

Seems to be that issue: https://github.com/ChatSecure/ChatSecure-iOS/issues/1250

Neustradamus commented 3 months ago

@chrisballinger: Any progress on this ticket?

ChatSecure / ChatSecure-iOS

Push notification / ejabberd 23.04 to chatsecure 5.0.4 (171) #1265

iq{id =