Auth and debug fail #2

bellwood · 2017-07-14T16:06:49Z

I enabled debug to see why I wasn't receiving notifications and the following is the result when I create a dummy account to fire off a notification:

[2017-07-14 16:01:16 +0000] info [whostmgr5] wwwacct::Notify Notification => 
***Redacted***, ***Redacted*** via XMPP [eventimportance => Low (3)]
ERROR: Debug filehandle could not be opened.
        Debugging disabled.
       (Operation not permitted)
ERROR: Debug filehandle could not be opened.
        Debugging disabled.
       (Operation not permitted)
[2017-07-14 16:01:17 +0000] warn [whostmgr5] Failed to send notification of type “XMPP”: One or more notification attempts failed. Details below:
Error: XMPP authentication failed: $VAR1 = 'No such file or directory';

Error: XMPP authentication failed: $VAR1 = '';
 at /usr/local/cpanel/Cpanel/iContact.pm line 547.
	Cpanel::iContact::__ANON__(__CPANEL_HIDDEN__...) called at /usr/local/cpanel/3rdparty/perl/524/lib64/perl5/cpanel_lib/Try/Tiny.pm line 122
	Try::Tiny::try(CODE(0x7be6208), Try::Tiny::Catch=REF(0x7be6c28)) called at /usr/local/cpanel/Cpanel/iContact.pm line 548
	Cpanel::iContact::_send_notifications(HASH(0x7072298), HASH(0x70c5928), ARRAY(0x7bde980)) called at /usr/local/cpanel/Cpanel/iContact.pm line 502
	Cpanel::iContact::icontact("subject", "New account: omgtest (omgtest.tld)", "html_related", ARRAY(0x78660e0), "x_headers", HASH(0x7c2e500), "event_name", "Notify", ...) called at /usr/local/cpanel/Cpanel/iContact/Class.pm line 504
	Cpanel::iContact::Class::_todo_inside_daemon(Cpanel::iContact::Class::wwwacct::Notify=HASH(0x71e9a70)) called at /usr/local/cpanel/Cpanel/iContact/Class.pm line 332
	Cpanel::iContact::Class::__ANON__() called at /usr/local/cpanel/Cpanel/iContact/Class.pm line 80
	Cpanel::iContact::Class::__ANON__() called at /usr/local/cpanel/3rdparty/perl/524/lib64/perl5/cpanel_lib/Try/Tiny.pm line 101
	eval {...} called at /usr/local/cpanel/3rdparty/perl/524/lib64/perl5/cpanel_lib/Try/Tiny.pm line 92
	Try::Tiny::try(CODE(0x71e9c08), Try::Tiny::Catch=REF(0x6b6bf18)) called at /usr/local/cpanel/Cpanel/iContact/Class.pm line 85
	Cpanel::iContact::Class::__ANON__() called at /usr/local/cpanel/Cpanel/ForkAsync.pm line 64
	eval {...} called at /usr/local/cpanel/Cpanel/ForkAsync.pm line 64
	Cpanel::ForkAsync::do_in_child(CODE(0x71e9b60)) called at /usr/local/cpanel/Cpanel/iContact/Class.pm line 87
	Cpanel::iContact::Class::_do_in_daemon(CODE(0x71e9ae8)) called at /usr/local/cpanel/Cpanel/iContact/Class.pm line 334
	Cpanel::iContact::Class::send(Cpanel::iContact::Class::wwwacct::Notify=HASH(0x71e9a70)) called at /usr/local/cpanel/Cpanel/iContact/Class.pm line 323
	Cpanel::iContact::Class::new(__CPANEL_HIDDEN__, __CPANEL_HIDDEN__, __CPANEL_HIDDEN__, __CPANEL_HIDDEN__, __CPANEL_HIDDEN__, __CPANEL_HIDDEN__, __CPANEL_HIDDEN__, __CPANEL_HIDDEN__, ...) called at /usr/local/cpanel/Cpanel/Notify.pm line 79
	Cpanel::Notify::__ANON__() called at /usr/local/cpanel/Cpanel/Notify.pm line 152
	Cpanel::Notify::_notification_backend("wwwacct::Notify", "No status set", 1, CODE(0x700a508)) called at /usr/local/cpanel/Cpanel/Notify.pm line 81
	Cpanel::Notify::notification_class("class", "wwwacct::Notify", "application", "wwwacct::Notify", "constructor_args", ARRAY(0x700a0b8)) called at /usr/local/cpanel/Whostmgr/Accounts/Create.pm line 1437
	Whostmgr::Accounts::Create::_wwwacct("no_cache_update", 0, "featurelist", "default", "hascgi", "n", "max_defer_fail_percentage", "unlimited", ...) called at /usr/local/cpanel/Whostmgr/Accounts/Create.pm line 1951
	Whostmgr::Accounts::Create::__createaccount("dkim", 1, "quota", "unlimited", "contactemail", "", "pkgname", "", ...) called at /usr/local/cpanel/Whostmgr/Accounts/Create.pm line 2001
	Whostmgr::Accounts::Create::_createaccount("dkim", 1, "quota", "unlimited", "contactemail", "", "pkgname", "", ...) called at whostmgr/bin/whostmgr5.pl line 753
	main::wwwacct() called at whostmgr/bin/whostmgr5.pl line 228

Edit: make test and make install worked without incident when installing

The text was updated successfully, but these errors were encountered:

bellwood · 2017-07-14T16:48:08Z

So I changed up the logging path to /tmp/xmpp.log and I'm getting:

XML::Stream: Read: buff(<failure xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><not-authorized/></failure>)
XMPP::Conn: AuthSASL: Authentication failed.

When I use the same username and password (as configured in cPanel) in Adium, I can connect no issue.

bellwood · 2017-08-01T18:54:45Z

So I was able to get around the auth issues by changing:

my @result = $xmpp_conn->AuthSend(

To:

my @result = $xmpp_conn->AuthIQAuth(

....to avoid SASL issues.

Still getting:

Error: XMPP authentication failed: $VAR1 = 'No such file or directory';

Error: XMPP authentication failed: $VAR1 = '';
 at /usr/local/cpanel/Cpanel/iContact.pm line 547.

...the number of which those Error: lines occur is directly related to the number of recipients specified

troglodyne · 2017-09-08T13:57:24Z

Sorry for not seeing this one a when it was initially filed. Maybe my email filtering is too aggressive.

Will try to investigate this soon.

bellwood · 2017-09-08T14:11:17Z

No worries - if it helps we are trying to auth through to our ejabberd servers...

troglodyne · 2017-09-08T14:46:47Z

My server is also running ejabberd. I saw similar issues while building this related to not initially passing in the 'component name', which is why I added that as an option. You'll get mysterious auth failures in Net::XMPP when not passing in a component name that matches what ejabberd thinks the node's hostname is. The only way I got reliable debugging info to realize this was by upping the loglevel in ejabberd then tailing the log on the server (Net::XMPP's debugging is next to useless). Oddly, for me there wasn't even any misconfiguration on the server side -- Net::XMPP just wasn't sending in the correct hostname without also sending in the component name. Supposedly this doesn't happen with other XMPP servers, but who knows?

Anyways, let me know if that helps. Otherwise, is this a public XMPP server (can I register an account there so that I can send messages to myself and further debug the issue)?

bellwood · 2017-09-08T15:03:33Z

It is a private server but its federated.

Updated my primary XMPP.pm to the latest and enabled debugging which now does give some further details:

[2017-09-08 14:56:20 +0000] warn [suspendacct] Failed to send notification of type “XMPP”: One or more notification attempts failed. Details below:
Error: XMPP connection failed: $VAR1 = {
          'node' => bless( {
                             'TAG' => 'stream:error',
                             'CHILDREN' => [
                                             bless( {
                                                      'RAWXML' => [],
                                                      'TAG' => 'host-unknown',
                                                      'ATTRIBS' => {
                                                                     'xmlns' => 'urn:ietf:params:xml:ns:xmpp-streams'
                                                                   }
                                                    }, 'XML::Stream::Node' )
                                           ],
                             'RAWXML' => []
                           }, 'XML::Stream::Node' ),
          'type' => 'host-unknown'
        };
 at /usr/local/cpanel/Cpanel/iContact.pm line 548.

I've set component name to the FQDN of the host... SRV are good we are fully federated

bellwood · 2017-09-08T15:10:47Z

ejabberd side:

2017-09-08 15:06:44.107 [debug] <0.16498.12>@ejabberd_receiver:process_data:284 Received XML on stream = <<"<?xml version='1.0'?><stream:stream version='1.0' xmlns:stream='http://etherx.jabber.org/streams' xmlns='jabber:client' to='myejabberhostname.tld' from='mycpanelhostname.tld' xml:lang='en' >">>
2017-09-08 15:06:44.107 [debug] <0.16499.12>@ejabberd_c2s:send_text:1924 Send XML on stream = <<"<?xml version='1.0'?><stream:stream xmlns='jabber:client' xmlns:stream='http://etherx.jabber.org/streams' id='13464868883747332834' from='rawdomain.tld' version='1.0' xml:lang='en'>">>
2017-09-08 15:06:44.107 [debug] <0.16499.12>@ejabberd_c2s:send_text:1924 Send XML on stream = <<"<stream:error><host-unknown xmlns='urn:ietf:params:xml:ns:xmpp-streams'></host-unknown></stream:error>">>
2017-09-08 15:06:44.107 [debug] <0.16499.12>@ejabberd_c2s:send_text:1924 Send XML on stream = <<"</stream:stream>">>

bellwood · 2017-09-08T15:49:17Z

and cpanel side debug level 2:

XML::Stream: Send: (<response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'></response>)
XML::Stream: Process: block(0)
XMPP::Conn: AuthSASL: haven't authed yet... let's wait.
XMPP::Conn: Process: timeout(1)
XML::Stream: Read: buff(<failure xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><not-authorized/></failure>)
XML::Stream: Node: _handle_element: sid(2118189179703330220) sax(XML::Stream::Parser=HASH(0x535ba98)) tag(failure) att( xmlns urn:ietf:params:xml:ns:xmpp-sasl )
XML::Stream: Node: _handle_element: check( -1 )
XML::Stream: Node: _handle_element: sid(2118189179703330220) sax(XML::Stream::Parser=HASH(0x535ba98)) tag(not-authorized) att( )
XML::Stream: Node: _handle_element: check( 0 )
XML::Stream: Node: _handle_close: sid(2118189179703330220) sax(XML::Stream::Parser=HASH(0x535ba98)) tag(not-authorized)
XML::Stream: Node: _handle_close: check( 1 )
XML::Stream: Node: _handle_close: check2( 0 )
XML::Stream: Node: _handle_close: sid(2118189179703330220) sax(XML::Stream::Parser=HASH(0x535ba98)) tag(failure)
XML::Stream: Node: _handle_close: check( 0 )
XML::Stream: Node: _handle_close: check2( -1 )
XML::Stream: Process: block(0)
XMPP::Conn: AuthSASL: Authentication failed.

I know for a fact my auth is correct, ive used the credentials to login via adium

troglodyne · 2017-09-08T16:11:26Z

Definitely seems like I'm on the right track RE the component name issue I referenced since the server side seemed to indicate 'host-unknown'. There just has to be some other piece of the puzzle that causes these failures that I'm missing. Hopefully the additional details here should allow me to tweak my testing ejabberd server to simulate the failures and work on a fix, probably this weekend.

bellwood · 2017-09-08T16:19:13Z

Just as a note, if I leave component blank, I no longer get host unknowns, I just get auth failures.

My last reply with level 2 debugging is with the plugin using SRV records (no hardcoded component)

What version of ejabberd are you running (we're on ejabberd-16.09) and perhaps what necessary config do you have?

troglodyne · 2017-09-08T17:47:34Z

16.09-4 is my ejabberd version. As to the "necessary" configuration, I wouldn't know. I use c2s with starttls on port 5222, but I'd figure that's pretty standard. My auth method is set to 'internal'. Nothing I'd figure that is out of the ordinary.

bellwood · 2017-09-08T18:11:00Z

Thats all the same here as well... I'll keep an eye on the project, maybe something silly...

Thanks for the feedback, if you're on IRC (I'm on freenode) we could collab a bit

troglodyne · 2017-09-08T18:19:38Z

I can successfully reproduce the issue now after fiddling with things a bit. Not quite sure what I did yet, but I should be able to get to the bottom of it and push a fix up soon :D

troglodyne · 2017-09-08T22:19:05Z

Whatever this is, it appears to end with a socket error after which my Jabber server restarts (had to set loglevel to '5' to get this):
2017-09-08 18:05:58.311 [debug] <0.513.0>@ejabberd_socket:send:184 Error in fast_tls:send: {error,einval}

Otherwise, I've corrected the error handling -- it at least properly gives you the less nonsensical error message of 'not-authorized' now. From what I can tell, it is getting a request for auth , which the server responds with and we send , which seems right, but then it repeats a challenge a second time, which we issue a blank to. At that point the server returns a failure notice. Ugh. Will continue investigation this weekend.

troglodyne · 2017-09-09T01:40:10Z

Apparently the systemd service definition I had for ejabberd was acting up and sending SIGTERM to it over and over again. Was a red herring.

Real issue seems to be related to it preferring to use DIGEST-MD5 even though it's obsolete. Since I'm preferring STARTTLS anyways, using PLAIN or SCRAM would be fine, I think... though Net::XMPP doesn't appear to have any accessors for indicating your preference there. Gonna have to dig through Authen::SASL a bit I think.

troglodyne · 2017-09-09T03:27:01Z

Confirmed that this is a bug, though I can't be sure whether it is with Net::XMPP or ejabberd. In any case, when Net::XMPP encounters failures from an auth method, it does not attempt to use any of the other advertised login methods (like PLAIN), as setting 'disable_sasl_mechanisms: "DIGEST-MD5"' in my ejabberd.yml configuration file fixes the issue on my server. The way I intend to handle this is to rewrite the symbols in Net::XMPP local to the _send function in order to have it fall back to using PLAIN when it fails.

From what I can tell, libpurple issues a self-terminating XML tag as the second part of the challenge asked for here: https://wiki.xmpp.org/web/SASLandDIGEST-MD5

Whereas Net::XMPP issues a tag that is simply bereft of content on the interior. Either one of these should be OK to do, but it is the only visible difference in what gets sent to the server from libpurple versus Net::XMPP. This could be a parsing bug in ejabberd, not sure.

Also adds notice to readme about current known incompatibility

troglodyne self-assigned this Sep 8, 2017

troglodyne added a commit that referenced this issue Sep 9, 2017

Add functional testing ability to track down issue #2

4f02622

Also adds notice to readme about current known incompatibility

troglodyne added the question label Feb 15, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Auth and debug fail #2

Auth and debug fail #2

bellwood commented Jul 14, 2017 •

edited

Loading

bellwood commented Jul 14, 2017

bellwood commented Aug 1, 2017 •

edited

Loading

troglodyne commented Sep 8, 2017

bellwood commented Sep 8, 2017

troglodyne commented Sep 8, 2017

bellwood commented Sep 8, 2017

bellwood commented Sep 8, 2017 •

edited

Loading

bellwood commented Sep 8, 2017

troglodyne commented Sep 8, 2017

bellwood commented Sep 8, 2017

troglodyne commented Sep 8, 2017

bellwood commented Sep 8, 2017

troglodyne commented Sep 8, 2017

troglodyne commented Sep 8, 2017

troglodyne commented Sep 9, 2017

troglodyne commented Sep 9, 2017

Auth and debug fail #2

Auth and debug fail #2

Comments

bellwood commented Jul 14, 2017 • edited Loading

bellwood commented Jul 14, 2017

bellwood commented Aug 1, 2017 • edited Loading

troglodyne commented Sep 8, 2017

bellwood commented Sep 8, 2017

troglodyne commented Sep 8, 2017

bellwood commented Sep 8, 2017

bellwood commented Sep 8, 2017 • edited Loading

bellwood commented Sep 8, 2017

troglodyne commented Sep 8, 2017

bellwood commented Sep 8, 2017

troglodyne commented Sep 8, 2017

bellwood commented Sep 8, 2017

troglodyne commented Sep 8, 2017

troglodyne commented Sep 8, 2017

troglodyne commented Sep 9, 2017

troglodyne commented Sep 9, 2017

bellwood commented Jul 14, 2017 •

edited

Loading

bellwood commented Aug 1, 2017 •

edited

Loading

bellwood commented Sep 8, 2017 •

edited

Loading