Push notification / ejabberd 23.04 to chatsecure 5.0.4 (171)

[csrado]

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 = <<"<stream:stream version='1.0' xml:lang='en' xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' to='pubsub.chatsecure.org' from='msg.xxx.xom' xmlns='jabber:server'>">>
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 = <<"stream:features<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 = <<"<stream:stream version='1.0' xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' to='pubsub.chatsecure.org' from='msg.xxx.xom' xmlns='jabber:server'>">>
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 = <<"stream:features<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 = <<"<db:result to='pubsub.chatsecure.org' from='msg.xxx.xom'>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]

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]

Seems to be that issue: #1250

[Neustradamus]

@chrisballinger: Any progress on this ticket?