Auth and debug fail

[bellwood]

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

[bellwood]

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]

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]

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]

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

[troglodyne]

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]

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]

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]

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]

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]

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]

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]

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]

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]

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]

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]

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.