Not working with Prosody and Nextcloud

mejo- commented 7 years ago

Hi, I try (and so far: failed) to setup JSXC Nextcloud plugin on a Nextcloud 10 instance with an external Prosody XMPP server.

My guess is that for some reason Prosody doesn't run external_auth_command, but I'm not sure.

The system is Debian 9 Stretch with Prosody 0.9.12, Nextcloud 10 and latest OJSXC 3.2.0-beta.1
mod_auth_external is enabled in the Prosody config (tried both the latest version from Prosody Modules and the one from your repo)
xmpp-cloud-auth is cloned to /opt/jsxc/xmpp-cloud-auth and external_cloud.py made executable (chmod +x)

Prosody is configured according to the README:

modules_enabled = {
           [...]
           "bosh";
           "auth_external";
};
[...]
authentication = "external"
external_auth_command = "/opt/jsxc/xmpp-cloud-auth/external_cloud.py -t prosody -u https://cloud.domain.tld/index.php/apps/ojsxc/ajax/externalApi.php -s ****** -l /var/log/prosody"

Apache Proxy for /http-bind/ is configured and works

The settings in OJSXC App are as follows (settings with empty values stripped down):

   "ojsxc": {
        "apiSecret": "******",
        "boshUrl": "/http-bind/",
        "enabled": "yes",
        "installed_version": "3.2.0-beta.1",
        "ocsid": "162257",
        "serverType": "external",
        "timeLimitedToken": "false",
        "types": "prelogin",
        "xmppDomain": "cloud.domain.tld",
        "xmppOverwrite": "false",
        "xmppPreferMail": "false",
        "xmppResource": "",
        "xmppStartMinimized": "false"
    },

When I try to login to Nextcloud, the login takes forever and in prosody.log I see the following log messages:

Apr 05 20:52:47 socket  debug   server.lua: accepted new client connection from 127.0.0.1:45304 to 5280
Apr 05 20:52:47 http.server debug   Firing event: POST cloud.domain.tld/http-bind/
Apr 05 20:52:47 mod_bosh    debug   Handling new request table: 0x55ad71c75fd0: <body rid='3419421983' xmlns='http://jabber.org/protocol/httpbind' to='cloud.domain.tld' 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'/>
----------
Apr 05 20:52:47 mod_bosh    debug   BOSH body open (sid: <none>)
Apr 05 20:52:47 bosh7434778b-8b67-481d-9da1-f1edc1af4baa    debug   BOSH session created for request from *.*.*.*
Apr 05 20:52:47 mod_bosh    info    New BOSH session, assigned it sid '7434778b-8b67-481d-9da1-f1edc1af4baa'
Apr 05 20:52:47 mod_bosh    debug   We have an open request, so sending on that
Apr 05 20:52:47 mod_bosh    debug   Request destroyed: table: 0x55ad71c7ba10
Apr 05 20:52:47 bosh7434778b-8b67-481d-9da1-f1edc1af4baa    debug   BOSH session marked as inactive (for 60s)
Apr 05 20:52:47 mod_bosh    debug   Session 7434778b-8b67-481d-9da1-f1edc1af4baa has 0 out of 1 requests open
Apr 05 20:52:47 mod_bosh    debug   and there are 0 things in the send_buffer:
Apr 05 20:52:47 http.server debug   Firing event: POST cloud.domain.tld/http-bind/
Apr 05 20:52:47 mod_bosh    debug   Handling new request table: 0x55ad71c180c0: <body rid='3419421984' xmlns='http://jabber.org/protocol/httpbind' sid='7434778b-8b67-481d-9da1-f1edc1af4baa'/>
----------
Apr 05 20:52:47 mod_bosh    debug   BOSH body open (sid: 7434778b-8b67-481d-9da1-f1edc1af4baa)
Apr 05 20:52:47 mod_bosh    debug   Session 7434778b-8b67-481d-9da1-f1edc1af4baa has 1 out of 1 requests open
Apr 05 20:52:47 mod_bosh    debug   and there are 0 things in the send_buffer:
Apr 05 20:52:47 mod_bosh    debug   Have nothing to say, so leaving request unanswered for now

and then ~1 minute later:

Apr 05 20:53:00 boshe842c651-fa5d-4d0b-a356-04ba6065d405    debug   BOSH client inactive too long, destroying session at 1491418380
Apr 05 20:53:00 boshe842c651-fa5d-4d0b-a356-04ba6065d405    debug   Destroying session for (unknown) ((unknown)@cloud.domain.tld): BOSH client silent for over 60 seconds
Apr 05 20:53:35 mod_bosh    debug   table: 0x55ad71dd0db0 was soon to timeout (at 1491418418, now 1491418418), sending empty response
Apr 05 20:53:35 mod_bosh    debug   We have an open request, so sending on that
Apr 05 20:53:35 mod_bosh    debug   Request destroyed: table: 0x55ad71dd0db0
Apr 05 20:53:35 bosh0dbbb355-7c98-4b94-a58e-7d99d2861aab    debug   BOSH session marked as inactive (for 60s)
Apr 05 20:53:44 mod_bosh    debug   table: 0x55ad71bd2c50 was soon to timeout (at 1491418427, now 1491418427), sending empty response
Apr 05 20:53:44 mod_bosh    debug   We have an open request, so sending on that
Apr 05 20:53:44 mod_bosh    debug   Request destroyed: table: 0x55ad71bd2c50
Apr 05 20:53:44 bosh7434778b-8b67-481d-9da1-f1edc1af4baa    debug   BOSH session marked as inactive (for 60s)
Apr 05 20:53:44 http.server debug   Firing event: POST cloud.domain.tld/http-bind/
Apr 05 20:53:44 mod_bosh    debug   Handling new request table: 0x55ad71c48d00: <body rid='3419421985' xmlns='http://jabber.org/protocol/httpbind' sid='7434778b-8b67-481d-9da1-f1edc1af4baa'/>
----------
Apr 05 20:53:44 mod_bosh    debug   BOSH body open (sid: 7434778b-8b67-481d-9da1-f1edc1af4baa)
Apr 05 20:53:44 mod_bosh    debug   Session 7434778b-8b67-481d-9da1-f1edc1af4baa has 1 out of 1 requests open
Apr 05 20:53:44 mod_bosh    debug   and there are 0 things in the send_buffer:
Apr 05 20:53:44 mod_bosh    debug   Have nothing to say, so leaving request unanswered for now

Do you have an idea what's going wrong here? The same setup with internal XMPP server from the App works great but now with an external Prosody XMPP server (running on the same host) obviously something's wrong.

Thanks for the work on JSXC by the way, it's a great peace of software!

mejo- commented 7 years ago

Forgot to mention the actual problem: when trying to login to Nextcloud (with the OJSXC App enabled), nothing happens except the wheel keeps spinning. No error message, no change. Logging in takes ages.

sualko commented 7 years ago

Did you restart prosody? I think there should be a message in the log about the external auth script. There should be also two log files (extauth.(err|log)) in /var/log/prosody/.

mejo- commented 7 years ago

Hi @sualko,

I restarted Prosody several times. For some reason no message about external auth script appears in prosody.log. Also, no extauth.{err,log} in /var/log/prosody/.

I tried to run the script external_cloud.py manually (as user prosody) which created the log files in /var/log/prosody/.

So apparently something's wrong with the Prosody config, it doesn't use the external_auth_command. Any idea?

sualko commented 7 years ago

Is there maybe another authentication = line?

mejo- commented 7 years ago

No, certainly not. I tried to connect with Pidgin now and got the following error:

Apr 06 13:11:03 c2s55e78f049ed0 debug   Sent reply <stream:stream> to client
Apr 06 13:11:03 c2s55e78f049ed0 debug   Received[c2s_unauthed]: <auth mechanism='PLAIN' http://www.google.com/talk/protocol/authclient-uses-full-bind-result='true' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Apr 06 13:11:03 cloud.domain.tld:auth_external  debug   Started auth process
Apr 06 13:11:03 cloud.domain.tld:auth_external  warn    Unable to interpret data from auth process, [45 bytes]
Apr 06 13:11:03 cloud.domain.tld:auth_external  warn    Unable to interpret data from auth process, [45 bytes]
Apr 06 13:11:03 cloud.domain.tld: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>

I don't know whether that's expected behaviour (as the script probably only authenticates against Nextcloud accounts and doesn't allow connections from external clients), but at least it looks like the auth_external stuff is recognized now. I used username+password credentials that do exist on the Nextcloud instance by the way.

I also tried external_auth_protocol = "ejabberd" which produced the following error log:

Apr 06 13:06:46 c2s55d4793e6d30 debug   Sent reply <stream:stream> to client
Apr 06 13:06:46 c2s55d4793e6d30 debug   Received[c2s_unauthed]: <auth mechanism='PLAIN' http://www.google.com/talk/protocol/authclient-uses-full-bind-result='true' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Apr 06 13:06:46 cloud.domain.tld:auth_external  debug   Started auth process
Apr 06 13:06:46 cloud.domain.tld:auth_external  warn    Unable to interpret data from auth process, error: lpty failed to start child process: No such file or directory
Apr 06 13:06:46 cloud.domain.tld:auth_external  warn    Unable to interpret data from auth process, error: lpty failed to start child process: No such file or directory
Apr 06 13:06:46 cloud.domain.tld: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>

mejo- commented 7 years ago

I tried again with Nextcloud and the same settings (external_auth_protocol = "generic"). Same logs as above. So my guess is that Prosody doesn't even start the authentication process when a connection is coming from OJSXC, right? Probably something is wrong with my bosh proxy setup? Because that's the difference between Pidgin and OJSXC: the former uses XMPP directly, the latter uses bosh proxy, right?

sualko commented 7 years ago

doesn't allow connections from external clients

It does. The idea behind this script is, that you can use the same credentials for your nc and xmpp account.

Probably something is wrong with my bosh proxy setup?

You can use Pidgin also with BOSH, can you try this? Does the xmpp domain in the admin settings fit your xmpp server config?

If you run the script manually, can you verify that the script is working correctly? auth:USERNAME:SERVER:PASSWORD should either return 0 or 1. (Please run in prosody mode)

mejo- commented 7 years ago

Indeed, the bosh proxy configuration was wrong. I fixed it now by using the following configuration in my Apache2 VHost:

<VirtualHost *:443>
    ServerName cloud.domain.tld
    [...]
    ProxyVia On
    ProxyPreserveHost On
    ProxyRequests Off
    SSLProxyEngine On
    SSLProxyVerify none
    SSLProxyCheckPeerCN off
    SSLProxyCheckPeerName off
    ProxyPass /http-bind/ https://cloud.domain.tld:5281/http-bind/
    ProxyPassReverse /http-bind/ https://cloud.domain.tld:5281/http-bind/
    [...]
</VirtualHost>

Now I see the following logs in prosody.log when I try to login with Nextcloud:

Apr 06 13:26:36 mod_bosh    debug   BOSH stanza received: <auth mechanism='PLAIN' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>

Apr 06 13:26:36 boshd22a7be9-bc9e-4f16-a5fc-45c45a2f7f52    debug   Received[c2s_unauthed]: <auth mechanism='PLAIN' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Apr 06 13:26:36 cloud.domain.tld:auth_external  warn    Auth process exited unexpectedly with exit 1, restarting
Apr 06 13:26:36 cloud.domain.tld:auth_external  warn    Auth process exited unexpectedly with exit 1, restarting
Apr 06 13:26:36 cloud.domain.tld:auth_external  warn    Error while waiting for result from auth process: unknown error
Apr 06 13:26:36 cloud.domain.tld:auth_external  warn    Error while waiting for result from auth process: unknown error
Apr 06 13:26:36 cloud.domain.tld: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>
Apr 06 13:26:36 mod_bosh    debug   We have an open request, so sending on that
Apr 06 13:26:36 mod_bosh    debug   Request destroyed: table: 0x55e78f0a7c00

So similar errors when logging in from Pidgin and via OJSXC now.

mejo- commented 7 years ago

I tried to run the script manually again:

echo "auth:test_user:cloud.domain.tld:******" | sudo -u prosody /opt/jsxc/xmpp-cloud-auth/external_cloud.py -t prosody -u 'https://cloud.domain.tld/index.php/apps/ojsxc/ajax/externalApi.php' -s '******' -l /var/log/prosody -d

This returns endless lines with 0 until I manually interrupt with Ctrl+C.

In /var/log/prosody/extauth.log I see the following line once for each returned 0:

2017-04-06 13:33:44,293 INFO: Receive operation

Is this expected behaviour? Any ideas?

sualko commented 7 years ago

You have to run sudo -u prosody -H to check that all modules are installed correctly. After checking it once more, I got an TypeError: Incorrect padding in my extauth.err. I will look into this error if I have some more time.

mejo- commented 7 years ago

I cannot reproduce this. If I run sudo -u prosody prosody -H (after stopping Prosody first), the daemon starts without any warnings/errors. And if I try to connect to it (either with Pidgin or with OJSXC) I get the same errors in prosody.log again. But no logs are appended to extauth.{log,err} at all :(

sualko commented 7 years ago

No,no, I meant if you test the script. It should be like sudo -u prosody -H /opt/jsxc/xmpp-cloud-auth/external_cloud.py ... and please test without echo. It just waits for your input.

Changing line 23 to

try:
        token = b64decode(password.translate(usersafe_encoding) + "=======")
    except:
        logging.debug('Could not decode base64')
        return False

fixed my above error. Can you confirm that?

mejo- commented 7 years ago

Ok, now I got it. Sorry ;)

When running the script with sudo -u prosody -H and give auth:test_user:cloud.domain.tld:****** as input, it seems to work. From /var/log/prosody/extauth.log:

2017-04-06 14:01:32,761 INFO: Receive operation auth
2017-04-06 14:01:32,761 DEBUG: Token is too short
2017-04-06 14:01:32,763 DEBUG: Starting new HTTPS connection (1): cloud.domain.tld
2017-04-06 14:01:32,896 DEBUG: https://cloud.domain.tld:443 "POST /index.php/apps/ojsxc/ajax/externalApi.php HTTP/1.1" 200 48
2017-04-06 14:01:32,899 INFO: Cloud says this password is valid

Only the "Token is too short" debug msg is a bit confusing.

So seems like the script and its authentication verification works, right? So the problem must be somewhere in Prosody invoking the script.

mejo- commented 7 years ago

By the way, I tried your patch for line 23 of the script and it didn't change anything. I mean, I didn't run into the issue you spotted anyway, but at least your patch didn't stop it from working either :)

mejo- commented 7 years ago

Ha, one step further: I tried your version of mod_auth_external.lua again (had the upstream one from prosody-modules active in my latest tests). Now it seems like the script is invoked. When I try to login, extauth.log gets:

2017-04-06 14:09:00,056 INFO: Start external auth script for prosody with endpoint: https://cloud.domain.tld/index.php/apps/ojsxc/ajax/externalApi.php
2017-04-06 14:09:00,056 INFO: Log location: /var/log/prosody
2017-04-06 14:09:00,056 INFO: Log level: DEBUG
2017-04-06 14:09:00,056 INFO: Receive operation auth
2017-04-06 14:09:00,057 DEBUG: Token is too short
2017-04-06 14:09:00,062 DEBUG: Starting new HTTPS connection (1): cloud.domain.tld
2017-04-06 14:09:00,188 DEBUG: https://cloud.domain.tld:443 "POST /index.php/apps/ojsxc/ajax/externalApi.php HTTP/1.1" 200 48
2017-04-06 14:09:00,191 INFO: Cloud says this password is valid

Also, when connecting directly with Pidgin, it works now :) Only with OJSXC over bosh, it still fails:

Apr 06 14:08:59 mod_bosh    debug   BOSH body open (sid: f1438eef-22aa-47d6-a291-a614f705b091)
Apr 06 14:08:59 mod_bosh    debug   BOSH stanza received: <auth mechanism='PLAIN' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>

Apr 06 14:08:59 boshf1438eef-22aa-47d6-a291-a614f705b091    debug   Received[c2s_unauthed]: <auth mechanism='PLAIN' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>
Apr 06 14:08:59 cloud.domain.tld:auth_external  debug   Started auth process
Apr 06 14:08:59 cloud.domain.tld:auth_external  debug   Sent 44 bytes
Apr 06 14:08:59 cloud.domain.tld:auth_external  warn    Unable to interpret data from auth process, [45 bytes]
Apr 06 14:08:59 cloud.domain.tld:auth_external  warn    Unable to interpret data from auth process, [45 bytes]
Apr 06 14:08:59 cloud.domain.tld: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>
Apr 06 14:08:59 mod_bosh    debug   We have an open request, so sending on that
Apr 06 14:08:59 mod_bosh    debug   Request destroyed: table: 0x561ac0de0150
Apr 06 14:08:59 boshf1438eef-22aa-47d6-a291-a614f705b091    debug   BOSH session marked as inactive (for 60s)
Apr 06 14:08:59 mod_bosh    debug   Session f1438eef-22aa-47d6-a291-a614f705b091 has 0 out of 1 requests open
Apr 06 14:08:59 mod_bosh    debug   and there are 0 things in the send_buffer:

mejo- commented 7 years ago

Ok, after fiddling around a bit more with the bosh proxy in my Apache2 VHost config, login finally seems to work. Things I discovered:

If your Nextcloud instance is available over https, proxying to bosh over HTTPS seems to be required as well. Otherwise, the login will hang forever (probably because of some Content Security Policy).
You need to rewrite to the Domain/VHost that is configured as XMPP Domain in the OJSXP App.

In my case (with HTTPS enforced and Nextcloud at VHost cloud.example.org), the following works:

<VirtualHost *:443>
    ServerName cloud.domain.tld
    [...]
    ProxyVia On
    ProxyPreserveHost On
    ProxyRequests Off
    SSLProxyEngine On
    SSLProxyVerify none
    SSLProxyCheckPeerCN off
    SSLProxyCheckPeerName off
    ProxyPass /http-bind/ https://cloud.example.org:5281/http-bind/
    ProxyPassReverse /http-bind/ https://cloud.example.org:5281/http-bind/
    [...]
</VirtualHost>

Now the login works, but per default my contacts list is empty in OJSXC and I fail to add contacts to the list. But I'll open a new issue for that.

Thanks a lot @sualko for guiding me. It's much appreciated :)

mejo- commented 7 years ago

After thinking again about it, maybe extending the Prepare apache Wiki page would be a good idea. A suggestion:

If your Nextcloud/ownCloud instance is running behind HTTPS, you might need to forward the requests to the HTTPS-secured bosh server in order to stay in line with the Content Security Policy. An example:

<VirtualHost *:443>
  ServerName cloud.domain.tld
  [...]
  ProxyVia On
  ProxyPreserveHost On
  ProxyRequests Off
  SSLProxyEngine On
  # The following three settings are necessary if Apache fails to verify
  # the SSL certificate of your XMPP bosh server.
  SSLProxyVerify none
  SSLProxyCheckPeerCN off
  SSLProxyCheckPeerName off
  ProxyPass /http-bind/ https://cloud.example.org:5281/http-bind/
  ProxyPassReverse /http-bind/ https://cloud.example.org:5281/http-bind/
  [...]
</VirtualHost>

sualko commented 7 years ago

In my experience you don't have to use the https bosh binding even if you proxy from a https site. Why this was necessary in your setup isn't clear to me, but anyway I'm glad that it is working for you now.

jsxc / xmpp-cloud-auth

Not working with Prosody and Nextcloud #6