search

jsxc / xmpp-cloud-auth

:key: Authentication hub for Nextcloud+JSXC→Prosody, ejabberd, saslauthd, Postfix
https://www.jsxc.org
MIT License
60 stars 18 forks source link

The authentication stopped working out of the blue #34

Closed AlesAlitis closed 6 years ago

AlesAlitis commented 6 years ago

Hello,

About a month ago I managed to set up Nexcloud JSXC to work with a local Prosody server. However, since two days ago authentication started failing for some users (just after the latest update of the JSXC app in Nextcloud). Since yesterday, though, neither the Nextcloud app nor external clients can authenticate anymore. From the Prosody logs, it looks like mod_auth_external.lua is the problem. I have attached Prosody log form a failed authentication attempt

Aug 30 10:13:24 socket  debug   server.lua: auto-starting ssl negotiation...
Aug 30 10:13:24 socket  debug   server.lua: attempting to start tls on tcp{client}: 0x27c3288
Aug 30 10:13:24 socket  debug   server.lua: accepted new client connection from 127.0.0.1:54570 to 5281
Aug 30 10:13:24 socket  debug   server.lua: ssl handshake done
Aug 30 10:13:24 http.server     debug   Firing event: POST my.domain.com/http-bind/
Aug 30 10:13:24 mod_bosh        debug   Handling new request table: 0x27d1670: <body rid='3155859811' xmlns='http://jabber.org/protocol/httpbind' to='my.domain.com' xml:lang='en' wait='60' hold='1'$
----------
Aug 30 10:13:24 mod_bosh        debug   BOSH body open (sid: <none>)
Aug 30 10:13:24 bosh73c688fd-5296-4049-828e-473349724e05        debug   BOSH session created for request from 123.456.789.123
Aug 30 10:13:24 mod_bosh        info    New BOSH session, assigned it sid '73c688fd-5296-4049-828e-473349724e05'
Aug 30 10:13:24 mod_bosh        debug   We have an open request, so sending on that
Aug 30 10:13:24 mod_bosh        debug   Request destroyed: table: 0x27ca6e0
Aug 30 10:13:24 bosh73c688fd-5296-4049-828e-473349724e05        debug   BOSH session marked as inactive (for 60s)
Aug 30 10:13:24 mod_bosh        debug   Session 73c688fd-5296-4049-828e-473349724e05 has 0 out of 1 requests open
Aug 30 10:13:24 mod_bosh        debug   and there are 0 things in the send_buffer:
Aug 30 10:13:24 http.server     debug   Firing event: POST my.domain.com/http-bind/
Aug 30 10:13:24 mod_bosh        debug   Handling new request table: 0x27d44c0: <body rid='3155859812' xmlns='http://jabber.org/protocol/httpbind' sid='73c688fd-5296-4049-828e-473349724e05'><auth xmlns='u$
----------
Aug 30 10:13:24 mod_bosh        debug   BOSH body open (sid: 73c688fd-5296-4049-828e-473349724e05)
Aug 30 10:13:24 mod_bosh        debug   BOSH stanza received: <auth mechanism='PLAIN' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>

Aug 30 10:13:24 bosh73c688fd-5296-4049-828e-473349724e05        debug   Received[c2s_unauthed]: <auth mechanism='PLAIN' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Aug 30 10:13:24 mod_bosh        error   Traceback[bosh]: /opt/xmpp-cloud-auth/prosody-modules/mod_auth_external.lua:64: attempt to index local 'pty' (a nil value)
stack traceback:
        /opt/xmpp-cloud-auth/prosody-modules/mod_auth_external.lua:64: in function 'send_query'
        /opt/xmpp-cloud-auth/prosody-modules/mod_auth_external.lua:118: in function </opt/xmpp-cloud-auth/prosody-modules/mod_auth_external.lua:103>
        (tail call): ?
        (tail call): ?
        /opt/xmpp-cloud-auth/prosody-modules/mod_auth_external.lua:154: in function 'plain_test'
        /usr/lib64/prosody/util/sasl/plain.lua:72: in function </usr/lib64/prosody/util/sasl/plain.lua:38>
        (tail call): ?
        /usr/lib64/prosody/modules/mod_saslauth.lua:77: in function </usr/lib64/prosody/modules/mod_saslauth.lua:66>
        (tail call): ?
        /usr/lib64/prosody/util/events.lua:67: in function 'fire_event'
        ...
        /usr/lib64/prosody/net/http/server.lua:109: in function 'process_next'
        /usr/lib64/prosody/net/http/server.lua:125: in function 'success_cb'
        /usr/lib64/prosody/net/http/parser.lua:173: in function 'feed'
        /usr/lib64/prosody/net/http/server.lua:154: in function </usr/lib64/prosody/net/http/server.lua:153>
        (tail call): ?
        /usr/lib64/prosody/net/server_select.lua:868: in function </usr/lib64/prosody/net/server_select.lua:850>
        [C]: in function 'xpcall'
        /usr/lib64/prosody/../../bin/prosody:376: in function 'loop'
        /usr/lib64/prosody/../../bin/prosody:407: in main chunk
        [C]: ?
Aug 30 10:13:24 mod_bosh        debug   Session 73c688fd-5296-4049-828e-473349724e05 has 1 out of 1 requests open
Aug 30 10:13:24 mod_bosh        debug   and there are 0 things in the send_buffer:
Aug 30 10:13:24 mod_bosh        debug   Have nothing to say, so leaving request unanswered for now
Aug 30 10:13:25 socket  debug   server.lua: auto-starting ssl negotiation...
Aug 30 10:13:25 socket  debug   server.lua: attempting to start tls on tcp{client}: 0x27d9858
Aug 30 10:13:25 socket  debug   server.lua: accepted new client connection from 127.0.0.1:54576 to 5281
Aug 30 10:13:25 socket  debug   server.lua: ssl handshake done
Aug 30 10:13:25 http.server     debug   Firing event: POST my.domain.com/http-bind/
Aug 30 10:13:25 mod_bosh        debug   Handling new request table: 0x27ea2e0: <body rid='3155859812' xmlns='http://jabber.org/protocol/httpbind' sid='73c688fd-5296-4049-828e-473349724e05'><auth xmlns='u$
----------
Aug 30 10:13:25 mod_bosh        debug   BOSH body open (sid: 73c688fd-5296-4049-828e-473349724e05)
Aug 30 10:13:25 bosh73c688fd-5296-4049-828e-473349724e05        debug   rid repeated, ignoring: 3155859812 (diff 0)
Aug 30 10:13:25 mod_bosh        debug   Session 73c688fd-5296-4049-828e-473349724e05 has 2 out of 1 requests open
Aug 30 10:13:25 mod_bosh        debug   and there are 0 things in the send_buffer:
Aug 30 10:13:25 mod_bosh        debug   We are holding too many requests, so...
Aug 30 10:13:25 mod_bosh        debug   ...sending an empty response
Aug 30 10:13:25 mod_bosh        debug   We have an open request, so sending on that
Aug 30 10:13:25 mod_bosh        debug   Request destroyed: table: 0x27d45c0
Aug 30 10:13:25 mod_bosh        debug   Have nothing to say, so leaving request unanswered for now
Aug 30 10:13:31 http.server     debug   Firing event: POST my.domain.com/http-bind/
Aug 30 10:13:31 mod_bosh        debug   Handling new request table: 0x27e69e0: <body rid='122237649' xmlns='http://jabber.org/protocol/httpbind' to='my.domain.com' xml:lang='en' wait='60' hold='1' $
----------
Aug 30 10:13:31 mod_bosh        debug   BOSH body open (sid: <none>)
Aug 30 10:13:31 bosh1929425a-a666-4eb5-a46d-82c12cfa48c6        debug   BOSH session created for request from 123.456.789.123
Aug 30 10:13:31 mod_bosh        info    New BOSH session, assigned it sid '1929425a-a666-4eb5-a46d-82c12cfa48c6'
Aug 30 10:13:31 mod_bosh        debug   We have an open request, so sending on that
Aug 30 10:13:31 mod_bosh        debug   Request destroyed: table: 0x27e7730
Aug 30 10:13:31 bosh1929425a-a666-4eb5-a46d-82c12cfa48c6        debug   BOSH session marked as inactive (for 60s)
Aug 30 10:13:31 mod_bosh        debug   Session 1929425a-a666-4eb5-a46d-82c12cfa48c6 has 0 out of 1 requests open
Aug 30 10:13:31 mod_bosh        debug   and there are 0 things in the send_buffer:
Aug 30 10:13:31 http.server     debug   Firing event: POST my.domain.com/http-bind/
Aug 30 10:13:31 mod_bosh        debug   Handling new request table: 0x27f3bd0: <body rid='122237650' xmlns='http://jabber.org/protocol/httpbind' sid='1929425a-a666-4eb5-a46d-82c12cfa48c6'><auth xmlns='ur$
----------
Aug 30 10:13:31 mod_bosh        debug   BOSH body open (sid: 1929425a-a666-4eb5-a46d-82c12cfa48c6)
Aug 30 10:13:31 mod_bosh        debug   BOSH stanza received: <auth mechanism='PLAIN' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>

Aug 30 10:13:31 bosh1929425a-a666-4eb5-a46d-82c12cfa48c6        debug   Received[c2s_unauthed]: <auth mechanism='PLAIN' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Aug 30 10:13:31 mod_bosh        error   Traceback[bosh]: /opt/xmpp-cloud-auth/prosody-modules/mod_auth_external.lua:64: attempt to index local 'pty' (a nil value)
stack traceback:
        /opt/xmpp-cloud-auth/prosody-modules/mod_auth_external.lua:64: in function 'send_query'
        /opt/xmpp-cloud-auth/prosody-modules/mod_auth_external.lua:118: in function </opt/xmpp-cloud-auth/prosody-modules/mod_auth_external.lua:103>
        (tail call): ?
        (tail call): ?
        /opt/xmpp-cloud-auth/prosody-modules/mod_auth_external.lua:154: in function 'plain_test'
        /usr/lib64/prosody/util/sasl/plain.lua:72: in function </usr/lib64/prosody/util/sasl/plain.lua:38>
        (tail call): ?
        /usr/lib64/prosody/modules/mod_saslauth.lua:77: in function </usr/lib64/prosody/modules/mod_saslauth.lua:66>
        (tail call): ?
        /usr/lib64/prosody/util/events.lua:67: in function 'fire_event'
        ...
        /usr/lib64/prosody/net/http/server.lua:109: in function 'process_next'
        /usr/lib64/prosody/net/http/server.lua:125: in function 'success_cb'
        /usr/lib64/prosody/net/http/parser.lua:173: in function 'feed'
        /usr/lib64/prosody/net/http/server.lua:154: in function </usr/lib64/prosody/net/http/server.lua:153>
        (tail call): ?
        /usr/lib64/prosody/net/server_select.lua:868: in function </usr/lib64/prosody/net/server_select.lua:850>
        [C]: in function 'xpcall'
        /usr/lib64/prosody/../../bin/prosody:376: in function 'loop'
        /usr/lib64/prosody/../../bin/prosody:407: in main chunk
        [C]: ?
Aug 30 10:13:31 mod_bosh        debug   Session 1929425a-a666-4eb5-a46d-82c12cfa48c6 has 1 out of 1 requests open
Aug 30 10:13:31 mod_bosh        debug   and there are 0 things in the send_buffer:
Aug 30 10:13:31 mod_bosh        debug   Have nothing to say, so leaving request unanswered for now

Nothing is outputted in xcauth.log or xcauth.err. I am using prosody.cfg.lua from the wiki guide but with the proper authentication script name. The following modes are enabled:

modules_enabled = {

        -- Generally required
                "roster";
                "saslauth";
                "tls";
                "dialback";
                "disco";

        -- Not essential, but recommended
                "private";
                "vcard";

        -- Nice to have
                "version";
                "uptime";
                "time";
                "ping";
                "pep";

        -- Admin interfaces
                "admin_adhoc";

        -- HTTP modules
                "bosh";

        -- Other specific functionality
                "posix";
                "groups";
                "carbons";
                "mam";
                "smacks";
};

And here are my proxy settings in Apache:

        ProxyVia On
        ProxyPreserveHost On
        ProxyRequests Off
        SSLProxyEngine On
        SSLProxyVerify none
        SSLProxyCheckPeerCN off
        SSLProxyCheckPeerName off

    ProxyPass /http-bind/ https://localhost:5281/http-bind/
    ProxyPassReverse /http-bind/ https://localhost:5281/http-bind/

Authentication was working just fine until last week for both Nextcloud JSXC and external clients. No updates were done on the server OS. Nextcloud was updated to the latest stable version (12.0.2).

Any ideas?

MarcelWaldvogel commented 6 years ago

Thanks for the logs. My gaze first locked on the following error:

/opt/xmpp-cloud-auth/prosody-modules/mod_auth_external.lua:64: attempt to index local 'pty' (a nil value)

The lpty module (aka lua-lpty with package managers) is the one responsible for starting the external process, xcauth.py in this case.

I would guess that the module could not be loaded. Did you change anything related to lpty or module loading in Prosody?

BTW: If you also updated xmpp-cloud-auth, it will no longer look for xcauth.conf in the program directory and may now require bcrypt (aka python-bcrypt)

MarcelWaldvogel commented 6 years ago

BTW: I have been unhappy with lpty behavior (see e.g. #21), so on my Prosody test server, I use the experimental socket interface and have systemd listen to localhost:23664 and start xcauth.py on demand. Even if it has nothing to do with your current problem, I found this setup to be much more reliable.

AlesAlitis commented 6 years ago

Thank you for the fast replay. I haven't change anything with the prosody server since I set it up. However, updates were installed which may have caused the issue. My xcauth.conf is located in \etc and python-bcrypt is already installed. The strange thing is that the issue did not affect all users right away and in the beginning there were no errors in prosody.log

I will experiment with the socked interface when I have time and see if I mange to make it work.

MarcelWaldvogel commented 6 years ago

Prosody internal caching could be the reason for the delay some users experienced (and of course, users on long-lived connections will only experience it on reconnect).

AlesAlitis commented 6 years ago

Hello again. I setup the socket interface and testing with telnet gives the expected results (I had to change the owner to of /etc/xcauth.conf to xcauth). However, whit Prosody I get this error:

Sep 04 09:46:07 socket  debug   server.lua: auto-starting ssl negotiation...
Sep 04 09:46:07 socket  debug   server.lua: attempting to start tls on tcp{client}: 0x2c422b8
Sep 04 09:46:07 socket  debug   server.lua: accepted new client connection from 127.0.0.1:46240 to 5281
Sep 04 09:46:07 socket  debug   server.lua: ssl handshake done
Sep 04 09:46:07 http.server     debug   Firing event: POST nextcloud.my_domain.com/http-bind/
Sep 04 09:46:07 mod_bosh        debug   Handling new request table: 0x2c7a670: <body rid='1791402522' xmlns='http://jabber.org/protocol/httpbind' to='nextcloud.my_domain.com' xml:lang='en' wait='60' hold='1' ' content='text/xml; charset=utf-8' ver='1.6' xmpp:version='1.0' xmlns:xmpp='urn:xmpp:xbosh'/>
----------
Sep 04 09:46:07 mod_bosh        debug   BOSH body open (sid: <none>)
Sep 04 09:46:07 bosh036013b8-f1db-413e-aa66-24c4e2c008d9        debug   BOSH session created for request from 123.456.789.123
Sep 04 09:46:07 mod_bosh        info    New BOSH session, assigned it sid '036013b8-f1db-413e-aa66-24c4e2c008d9'
Sep 04 09:46:07 mod_bosh        debug   We have an open request, so sending on that
Sep 04 09:46:07 mod_bosh        debug   Request destroyed: table: 0x29b2110
Sep 04 09:46:07 bosh036013b8-f1db-413e-aa66-24c4e2c008d9        debug   BOSH session marked as inactive (for 60s)
Sep 04 09:46:07 mod_bosh        debug   Session 036013b8-f1db-413e-aa66-24c4e2c008d9 has 0 out of 1 requests open
Sep 04 09:46:07 mod_bosh        debug   and there are 0 things in the send_buffer:
Sep 04 09:46:07 http.server     debug   Firing event: POST nextcloud.my_domain.com/http-bind/
Sep 04 09:46:07 mod_bosh        debug   Handling new request table: 0x2c088f0: <body rid='1791402523' xmlns='http://jabber.org/protocol/httpbind' sid='036013b8-f1db-413e-aa66-24c4e2c008d9'><auth xmlns='urn:ietf:params:xml:ns:xmpp-sasl' mechanism='PLAIN'>dGVzdEBuZXh0LnBhcmFrYXJvLmNvLmpwAHRlc3QAQnlsX0J1a18xMzkz</auth></body>
----------
Sep 04 09:46:07 mod_bosh        debug   BOSH body open (sid: 036013b8-f1db-413e-aa66-24c4e2c008d9)
Sep 04 09:46:07 mod_bosh        debug   BOSH stanza received: <auth mechanism='PLAIN' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>

Sep 04 09:46:07 bosh036013b8-f1db-413e-aa66-24c4e2c008d9        debug   Received[c2s_unauthed]: <auth mechanism='PLAIN' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Sep 04 09:46:07 nextcloud.my_domain.com:auth_external       warn    Auth process exited unexpectedly with permission denied 0, restarting
Sep 04 09:46:07 nextcloud.my_domain.com:auth_external       warn    Error while waiting for result from auth process: unknown error
Sep 04 09:46:07 nextcloud.my_domain.com:saslauth    debug   sasl reply: <failure xmlns='urn:ietf:params:xml:ns:xmpp-sasl'><not-authorized/><text>Unable to authorize you with the authentication credentials you&apos;ve sent.</text></failure>
Sep 04 09:46:07 mod_bosh        debug   We have an open request, so sending on that
Sep 04 09:46:07 mod_bosh        debug   Request destroyed: table: 0x2c08a90
Sep 04 09:46:07 bosh036013b8-f1db-413e-aa66-24c4e2c008d9        debug   BOSH session marked as inactive (for 60s)
Sep 04 09:46:07 mod_bosh        debug   Session 036013b8-f1db-413e-aa66-24c4e2c008d9 has 0 out of 1 requests open
Sep 04 09:46:07 mod_bosh        debug   and there are 0 things in the send_buffer:

There are no errors generated in the xcauth.err .

Do you thing it is related to the permissions of xcauth.conf? I tried with both xcauth and prosody as file owners. Here is how they are now:

-rw-------. 1 prosody prosody 2287 Aug 30 09:21 /etc/xcauth.conf
AlesAlitis commented 6 years ago

Ok, the "Auth process exited unexpectedly with permission denied 0, restarting" was caused by SElinux. It looks like those fixed it:

# ausearch -c 'lua' --raw | audit2allow -M my-lua
# semodule -i my-lua.pp
# semanage port -a -t jabber_client_port_t -p tcp 23664

However, I am still getting strange behaviour. Test users logs in with no issues, however, when I try my account I get:

INFO: FAILURE: Could not authenticate user my_user@nextcloud.mydomain.com: noauth

I have no issues authenticating the same user via telnet on the socket. This user has TOTP second-factor auth enabled on it. Could this be the issue?

AlesAlitis commented 6 years ago

I can log-in in external clients with both the test and my accounts. This leads me to believe that the issue is with JSXC rather then with xcauth. Thank you for the help and for the great work.

MarcelWaldvogel commented 6 years ago

Thanks for the SElinux information/debugging!

Trying to diagnose the remaining problem:

AlesAlitis commented 6 years ago

Do you have an @ in your user name?

No @s were in the creation of the user names. Can other users log in with JSXC?

Some users can, but not all. For the affected users the JSXC bubbles button do not appear at all.

Did you enable time-limited tokens in the Nextcloud JSXC admin section?

It was on when the issue started but I disabled it since then.

Do you have any special characters in the password? (Does a temporary change to another password with as few special characters as possible solve the problem?)

A lot. It's a random generated password from a password manager. However, a test account with password containing the same special charecters did not have any issues loging in.

Assuming you have no @ in the login name and the other experiments did not result in any good lead: Can you try switching to the "Managed server"? Does the same problem still occur?

I tried it and got the same issue.

It looks like it was something stupid that I had to do in the first place: after deleting the cookies for my NextCloud instance I am able to log-in once again. My guess is that the last update of JSXC broke them in some way. All that is left is to find out why the Groups plug-in is not working as expected, but this is not for here.

Thank you for all the help! I hope this helps in some way wit the future development of the script.

MarcelWaldvogel commented 6 years ago

Ah, so this seems to be related to jsxc/jsxc#615. Entering jsxc.deleteAllData() in the JavaScript console also should help. @sualko is currently not available, but he will look into this after he returns. Closing this in favor of jsxc/jsxc#615.

Groups: Do you mean shared roster groups or some other groups?

AlesAlitis commented 6 years ago

Yes, it's shared roster groups.

MarcelWaldvogel commented 6 years ago

Can you describe it in a new ticket in https://github.com/jsxc/prosody-cloud-roster/issues/ ? I'll gladly have a look at it.

AlesAlitis commented 6 years ago

I decided to try to test ejabberd for a while and see if I like it better. I will keep an eye to the cloud roster module, however.

MarcelWaldvogel commented 6 years ago

There is also shared roster support available for ejabberd (using ejabberdctl from xmpp-cloud-auth; therefore somewhat slower at login).