search

vukoye / xmpp_dart

Lightweight XMPP client library written in Dart
Apache License 2.0
83 stars 64 forks source link

SASL Handshake Authentication dropped / response unreceived by ejabberd server #50

Open chinitadelrey opened 3 years ago

chinitadelrey commented 3 years ago

I am running example.dart on emulator and connecting to ejabberd on localhost.

I got the connection to work by subbing the host parameter in XmppAmountSettings with the IP address from ifconfig, while keeping localhost as the domain. However, the connection is dropped when the ejabberd server doesn't seem to receive the response to the challenge for the SASL authentication.

Any idea why? Many thanks in advance! Thank you for creating this package.

UPDATE: I think my issue could also be with using a certificate from an untrusted authority, as Adium prompts me to continue to connect -- but in that case,

1) should not ejabberd be showing that the authentication failed for that reason (& not a timeout) 2) what can we do to accept untrusted connections for testing purposes / avoid this issue?

xmpp_dart log: 

[log] <auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl" mechanism="SCRAM-SHA-1">biwsbj10ZXN0MixyPStkQlI5RHI4K3VER3hBSlZmSVJJUU9oaFpmN2NrcmFqOS83aDJ1YTBQMEt0M1gxR1FtNFgrV2VuNjhvWDhScVY=</auth>
[log] D/[ConnectionNegotiatorManager]: ACTIVE FEATURE: {name: SaslAuthenticationFeature, name_space: null, priority: 1000, state: NegotiatorState.NEGOTIATING}, isReady: true
[log] ---Xmpp Receiving:---
[log] <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj0rZEJSOURyOCt1REd4QUpWZklSSVFPaGhaZjdja3JhajkvN2gydWEwUDBLdDNYMUdRbTRYK1dlbjY4b1g4UnFWTWQwWWF1VEFqcGUxMlIzRkpzcUxJZz09LHM9OEh3UUtBTzN3V2xHNEg2WmlqU2hiQT09LGk9NDA5Ng==</challenge>
[log] ---Xmpp Sending:---
[log] <response xmlns="urn:ietf:params:xml:ns:xmpp-sasl">Yz1iaXdzLHI9K2RCUjlEcjgrdURHeEFKVmZJUklRT2hoWmY3Y2tyYWo5LzdoMnVhMFAwS3QzWDFHUW00WCtXZW42OG9YOFJxVk1kMFlhdVRBanBlMTJSM0ZKc3FMSWc9PSxwPVdlQ1VjdDBrYjdwN0RzaklMZlB5VWNNMVo0dz0=</response>
[log] ---Xmpp Receiving:---
[log] <stream:error><connection-timeout xmlns='urn:ietf:params:xml:ns:xmpp-streams'/><text xml:lang='en' xmlns='urn:ietf:params:xml:ns:xmpp-streams'>Idle connection</text></stream:error>

ejabberd log: 

20:43:19.953 [info]  (tls|<0.969.0>) Received XML on stream = "<auth xmlns=\"urn:ietf:params:xml:ns:xmpp-sasl\" mechanism=\"SCRAM-SHA-1\">biwsbj10ZXN0MixyPStkQlI5RHI4K3VER3hBSlZmSVJJUU9oaFpmN2NrcmFqOS83aDJ1YTBQMEt0M1gxR1FtNFgrV2VuNjhvWDhScVY=</auth>"

20:43:19.954 [debug] Running hook :c2s_handle_recv: :mod_stream_mgmt::c2s_handle_recv/3

20:43:19.993 [info]  (tls|<0.969.0>) Send XML on stream = "<challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj0rZEJSOURyOCt1REd4QUpWZklSSVFPaGhaZjdja3JhajkvN2gydWEwUDBLdDNYMUdRbTRYK1dlbjY4b1g4UnFWTWQwWWF1VEFqcGUxMlIzRkpzcUxJZz09LHM9OEh3UUtBTzN3V2xHNEg2WmlqU2hiQT09LGk9NDA5Ng==</challenge>"

20:43:19.994 [debug] Running hook :c2s_handle_send: :mod_push::c2s_stanza/3

20:43:19.994 [debug] Running hook :c2s_handle_send: :mod_push_keepalive::c2s_stanza/3

20:43:19.994 [debug] Running hook :c2s_handle_send: :mod_stream_mgmt::c2s_handle_send/3

20:43:28.592 [info]  (tls|<0.969.0>) Send XML on stream = "<stream:error><connection-timeout xmlns='urn:ietf:params:xml:ns:xmpp-streams'/><text xml:lang='en' xmlns='urn:ietf:params:xml:ns:xmpp-streams'>Idle connection</text></stream:error>"

20:43:28.593 [debug] Running hook :c2s_handle_send: :mod_push::c2s_stanza/3

20:43:28.593 [debug] Running hook :c2s_handle_send: :mod_push_keepalive::c2s_stanza/3

20:43:28.593 [debug] Running hook :c2s_handle_send: :mod_stream_mgmt::c2s_handle_send/3

20:43:28.593 [debug] Running hook :c2s_closed: :mod_stream_mgmt::c2s_closed/2

20:43:28.593 [debug] Running hook :c2s_closed: :ejabberd_c2s::process_closed/2

20:43:28.594 [debug] Running hook :c2s_terminated: :mod_stream_mgmt::c2s_terminated/2

20:43:28.594 [debug] Running hook :c2s_terminated: :mod_pubsub::on_user_offline/2

20:43:28.594 [debug] Running hook :c2s_terminated: :ejabberd_c2s::process_terminated/2

20:43:28.595 [info]  (tls|<0.969.0>) Send XML on stream = "</stream:stream>"

Here are truncated logs for a complete handshake for the same server with desktop Adium client, in case it is helpful:

21:18:29.641 [debug] Running hook :c2s_pre_auth_features: :mod_register::stream_feature_register/2

21:18:29.668 [info]  (tls|<0.1049.0>) Send XML on stream = "<stream:features><mechanisms xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><mechanism>DIGEST-MD5</mechanism><mechanism>PLAIN</mechanism><mechanism>SCRAM-SHA-512-PLUS</mechanism><mechanism>SCRAM-SHA-512</mechanism><mechanism>SCRAM-SHA-256-PLUS</mechanism><mechanism>SCRAM-SHA-256</mechanism><mechanism>SCRAM-SHA-1-PLUS</mechanism><mechanism>SCRAM-SHA-1</mechanism><mechanism>X-OAUTH2</mechanism></mechanisms><register xmlns='http://jabber.org/features/iq-register'/></stream:features>"

21:18:29.670 [debug] Running hook :c2s_handle_send: :mod_push::c2s_stanza/3

21:18:29.670 [debug] Running hook :c2s_handle_send: :mod_push_keepalive::c2s_stanza/3

21:18:29.670 [debug] Running hook :c2s_handle_send: :mod_stream_mgmt::c2s_handle_send/3

21:18:29.681 [info]  (tls|<0.1049.0>) Received XML on stream = "<auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='DIGEST-MD5' xmlns:ga='http://www.google.com/talk/protocol/auth' ga:client-uses-full-bind-result='true'/>"

21:18:29.681 [debug] Running hook :c2s_handle_recv: :mod_stream_mgmt::c2s_handle_recv/3

21:18:29.688 [info]  (tls|<0.1049.0>) Send XML on stream = "<challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>bm9uY2U9IjE1MjM0NTQ1NjE2OTM3MTA1NDQ0Iixxb3A9ImF1dGgiLGNoYXJzZXQ9dXRmLTgsYWxnb3JpdGhtPW1kNS1zZXNz</challenge>"

21:18:29.688 [debug] Running hook :c2s_handle_send: :mod_push::c2s_stanza/3

21:18:29.688 [debug] Running hook :c2s_handle_send: :mod_push_keepalive::c2s_stanza/3

21:18:29.689 [debug] Running hook :c2s_handle_send: :mod_stream_mgmt::c2s_handle_send/3

21:18:29.690 [info]  (tls|<0.1049.0>) Received XML on stream = "<response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dXNlcm5hbWU9InRlc3QiLHJlYWxtPSJsb2NhbGhvc3QiLG5vbmNlPSIxNTIzNDU0NTYxNjkzNzEwNTQ0NCIsY25vbmNlPSI2MDk3N2Y2MTYxMjI0MzEwOTY0ZDdkMTNjIixuYz0wMDAwMDAwMSxxb3A9YXV0aCxkaWdlc3QtdXJpPSJ4bXBwL2xvY2FsaG9zdCIscmVzcG9uc2U9ZTBiNjBiOGVjYzQ3OWIwMDQ1Y2M2Zjc3OWUyYmM3MDUsY2hhcnNldD11dGYtOA==</response>"

21:18:29.690 [debug] Running hook :c2s_handle_recv: :mod_stream_mgmt::c2s_handle_recv/3

21:18:29.694 [info]  (tls|<0.1049.0>) Send XML on stream = "<challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cnNwYXV0aD04OTZhMTVkM2MwM2E3OTNhYzZlMGU5NzQzNzQ5ZGM2NQ==</challenge>"

21:18:29.694 [debug] Running hook :c2s_handle_send: :mod_push::c2s_stanza/3

21:18:29.694 [debug] Running hook :c2s_handle_send: :mod_push_keepalive::c2s_stanza/3

21:18:29.694 [debug] Running hook :c2s_handle_send: :mod_stream_mgmt::c2s_handle_send/3

21:18:29.694 [info]  (tls|<0.1049.0>) Received XML on stream = "<response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'/>"

21:18:29.695 [debug] Running hook :c2s_handle_recv: :mod_stream_mgmt::c2s_handle_recv/3

21:18:29.696 [debug] Running hook :c2s_auth_result: :ejabberd_c2s::process_auth_result/3

21:18:29.697 [info]  (tls|<0.1049.0>) Accepted c2s DIGEST-MD5 authentication for test@localhost by mnesia backend from ::1

21:18:29.697 [debug] Running hook :c2s_auth_result: :mod_fail2ban::c2s_auth_result/3

21:18:29.699 [info]  (tls|<0.1049.0>) Send XML on stream = "<success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'/>"

21:18:29.699 [debug] Running hook :c2s_handle_send: :mod_push::c2s_stanza/3

21:18:29.699 [debug] Running hook :c2s_handle_send: :mod_push_keepalive::c2s_stanza/3

21:18:29.699 [debug] Running hook :c2s_handle_send: :mod_stream_mgmt::c2s_handle_send/3

21:18:29.699 [info]  (tls|<0.1049.0>) Received XML on stream = "<stream:stream to='localhost' xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' version='1.0'>"

21:18:29.700 [info]  (tls|<0.1049.0>) Send XML on stream = "<?xml version='1.0'?><stream:stream id='9752890484746968509' version='1.0' xml:lang='en' xmlns:stream='http://etherx.jabber.org/streams' from='localhost' xmlns='jabber:client'>"

21:18:29.700 [debug] Running hook :c2s_stream_started: :mod_client_state::c2s_stream_started/2

21:18:29.700 [debug] Running hook :c2s_stream_started: :mod_stream_mgmt::c2s_stream_started/2

21:18:29.700 [debug] Running hook :c2s_stream_started: :mod_fail2ban::c2s_stream_started/2

21:18:29.700 [debug] Running hook :c2s_post_auth_features: :mod_client_state::add_stream_feature/2

21:18:29.700 [debug] Running hook :c2s_post_auth_features: :mod_roster::get_versioning_feature/2

21:18:29.703 [debug] Running hook :c2s_post_auth_features: :mod_stream_mgmt::c2s_stream_features/2

21:18:29.705 [debug] Running hook :c2s_post_auth_features: :mod_caps::caps_stream_features/2

21:18:29.707 [debug] Running hook :disco_local_features: :mod_announce::disco_features/5

21:18:29.710 [debug] Running hook :disco_local_features: :mod_blocking::disco_features/5

21:18:29.710 [debug] Running hook :disco_local_features: :mod_carboncopy::disco_features/5

21:18:29.710 [debug] Running hook :disco_local_features: :mod_configure::get_local_features/5

21:18:29.716 [debug] Running hook :disco_local_features: :mod_offline::get_sm_features/5

21:18:29.716 [debug] Running hook :disco_local_features: :mod_privacy::disco_features/5

21:18:29.717 [debug] Running hook :disco_local_features: :mod_caps::disco_features/5

21:18:29.718 [debug] Running hook :disco_local_features: :mod_pubsub::disco_local_features/5

21:18:29.720 [debug] Running hook :disco_local_features: :mod_adhoc::get_local_features/5

21:18:29.720 [debug] Running hook :disco_local_features: :mod_disco::get_local_features/5

21:18:29.724 [debug] Running hook :disco_local_identity: :mod_announce::disco_identity/5

21:18:29.726 [debug] Running hook :disco_local_identity: :mod_configure::get_local_identity/5

21:18:29.726 [debug] Running hook :disco_local_identity: :mod_caps::disco_identity/5

21:18:29.726 [debug] Running hook :disco_local_identity: :mod_pubsub::disco_local_identity/5

21:18:29.726 [debug] Running hook :disco_local_identity: :mod_adhoc::get_local_identity/5

21:18:29.726 [debug] Running hook :disco_local_identity: :mod_disco::get_local_identity/5

21:18:29.728 [debug] Running hook :disco_info: :mod_offline::get_info/5

21:18:29.730 [debug] Running hook :disco_info: :mod_caps::disco_info/5

21:18:29.730 [debug] Running hook :disco_info: :mod_disco::get_info/5

21:18:29.735 [info]  (tls|<0.1049.0>) Send XML on stream = "<stream:features><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'/><session xmlns='urn:ietf:params:xml:ns:xmpp-session'><optional/></session><c ver='NqMDrgCx03HLh3URMusgDnNsR30=' node='http://www.process-one.net/en/ejabberd/' hash='sha-1' xmlns='http://jabber.org/protocol/caps'/><sm xmlns='urn:xmpp:sm:2'/><sm xmlns='urn:xmpp:sm:3'/><ver xmlns='urn:xmpp:features:rosterver'/><csi xmlns='urn:xmpp:csi:0'/></stream:features>"

21:18:29.735 [debug] Running hook :c2s_handle_send: :mod_push::c2s_stanza/3

21:18:29.735 [debug] Running hook :c2s_handle_send: :mod_push_keepalive::c2s_stanza/3

21:18:29.735 [debug] Running hook :c2s_handle_send: :mod_stream_mgmt::c2s_handle_send/3

21:18:29.736 [info]  (tls|<0.1049.0>) Received XML on stream = "<iq type='set' id='purple72c5e989'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><resource>resource-name</resource></bind></iq>"

21:18:29.737 [debug] Running hook :c2s_handle_recv: :mod_stream_mgmt::c2s_handle_recv/3

21:18:29.737 [debug] Running hook :c2s_session_opened: :mod_carboncopy::c2s_session_opened/1

21:18:29.738 [info]  (tls|<0.1049.0>) Opened c2s session for test@localhost/resource-name

21:18:29.738 [info]  (tls|<0.1049.0>) Send XML on stream = "<iq type='result' id='purple72c5e989'><bind xmlns='urn:ietf:params:xml:ns:xmpp-bind'><jid>test@localhost/resource-name</jid></bind></iq>"

21:18:29.738 [debug] Running hook :c2s_handle_send: :mod_push::c2s_stanza/3

21:18:29.738 [debug] Running hook :c2s_handle_send: :mod_push_keepalive::c2s_stanza/3

21:18:29.738 [debug] Running hook :c2s_handle_send: :mod_stream_mgmt::c2s_handle_send/3

21:18:29.739 [info]  (tls|<0.1049.0>) Received XML on stream = "<iq type='set' id='purple72c5e98a'><session xmlns='urn:ietf:params:xml:ns:xmpp-session'/></iq>"

21:18:29.739 [debug] Running hook :c2s_handle_recv: :mod_stream_mgmt::c2s_handle_recv/3

21:18:29.739 [debug] Running hook :c2s_authenticated_packet: :mod_client_state::c2s_authenticated_packet/2

21:18:29.739 [debug] Running hook :c2s_authenticated_packet: :mod_stream_mgmt::c2s_authenticated_packet/2

21:18:29.739 [debug] Running hook :user_send_packet: :mod_privacy::user_send_packet/1

21:18:29.740 [debug] Running hook :user_send_packet: :mod_vcard_xupdate::user_send_packet/1

21:18:29.740 [debug] Running hook :user_send_packet: :mod_caps::user_send_packet/1

21:18:29.740 [debug] Running hook :user_send_packet: :mod_mam::user_send_packet/1

21:18:29.740 [debug] Running hook :user_send_packet: :mod_carboncopy::user_send_packet/1

21:18:29.740 [debug] Running hook :user_send_packet: :mod_mam::user_send_packet_strip_tag/1

21:18:29.740 [debug] Running hook :c2s_filter_send: :mod_client_state::filter_chat_states/1

21:18:29.740 [debug] Running hook :c2s_filter_send: :mod_client_state::filter_pep/1

21:18:29.740 [debug] Running hook :c2s_filter_send: :mod_client_state::filter_presence/1

21:18:29.741 [debug] Running hook :c2s_filter_send: :mod_client_state::filter_other/1

21:18:29.741 [debug] Won't add stanza for test@localhost/resource-name to CSI queue

21:18:29.741 [debug] Flushing packets of @localhost from CSI queue of test@localhost/resource-name

21:18:29.741 [info]  (tls|<0.1049.0>) Send XML on stream = "<iq xml:lang='en' to='test@localhost/resource-name' from='localhost' type='result' id='purple72c5e98a'/>"

21:18:29.741 [debug] Running hook :c2s_handle_send: :mod_push::c2s_stanza/3

21:18:29.741 [debug] Running hook :c2s_handle_send: :mod_push_keepalive::c2s_stanza/3

21:18:29.741 [debug] Running hook :c2s_handle_send: :mod_stream_mgmt::c2s_handle_send/3

21:18:29.741 [info]  (tls|<0.1049.0>) Received XML on stream = "<iq type='get' id='purple72c5e98b' to='localhost'><query xmlns='http://jabber.org/protocol/disco#items'/></iq><iq type='get' id='purple72c5e98c' to='localhost'><query xmlns='http://jabber.org/protocol/disco#info'/></iq>"

21:18:29.742 [debug] Running hook :c2s_handle_recv: :mod_stream_mgmt::c2s_handle_recv/3

21:18:29.742 [debug] Running hook :c2s_authenticated_packet: :mod_client_state::c2s_authenticated_packet/2

21:18:29.742 [debug] Running hook :c2s_authenticated_packet: :mod_stream_mgmt::c2s_authenticated_packet/2

21:18:29.742 [debug] Running hook :user_send_packet: :mod_privacy::user_send_packet/1

21:18:29.742 [debug] Running hook :user_send_packet: :mod_vcard_xupdate::user_send_packet/1

21:18:29.742 [debug] Running hook :user_send_packet: :mod_caps::user_send_packet/1

21:18:29.742 [debug] Running hook :user_send_packet: :mod_mam::user_send_packet/1

21:18:29.742 [debug] Running hook :user_send_packet: :mod_carboncopy::user_send_packet/1

21:18:29.742 [debug] Running hook :user_send_packet: :mod_mam::user_send_packet_strip_tag/1

21:18:29.743 [debug] Running hook :privacy_check_packet: :mod_last::privacy_check_packet/4

21:18:29.743 [debug] Running hook :privacy_check_packet: :mod_privacy::check_packet/4