Unexpected behavior when using LDAP backup server

[GitHubUser4234]

Hi,

We have set a backup host in the LDAP wizard under "LDAP / AD integration"->"Advanced"->"Connection Settings" and after upgrading from NC 12 to NC 13.0.2 something strange happens:

1)

When the backup host is unreachable (to reproduce, just replace the port with an incorrect value), and a LDAP user tries to login with a wrong password, he will be redirected to an "Internal Server Error" page. Note that the primary LDAP server is still reachable, green light is showing in the LDAP wizard and users can login with the correct password. Once the port of the backup host is corrected, users trying to login with wrong password can see the normal "Wrong password" message at the login screen again. Here the server log during the "Internal Server Error":

Server log

{"reqId":"WzCpqRoiXdjq2EDB9sJGgwAAAAY","level":1,"time":"2018-06-25T16:36:57+08:00","remoteAddr":"10.10.10.10","user":"--","app":"admin_audit","method":"PROPFIND","url":"\/server\/remote.php\/webdav\/","message":"Login attempt: \"tester\"","userAgent":"testingsapp","version":"13.0.2.1"}
{"reqId":"WzCpqRoiXdjq2EDB9sJGgwAAAAY","level":0,"time":"2018-06-25T16:36:57+08:00","remoteAddr":"10.10.10.10","user":"--","app":"user_ldap","method":"PROPFIND","url":"\/server\/remote.php\/webdav\/","message":"initializing paged search for  Filter (&(|(objectclass=inetOrgPerson))(uid=tester)) base Array\n(\n    [0] => ou=testou,o=testo\n)\n attr Array\n(\n    [0] => entryuuid\n    [1] => nsuniqueid\n    [2] => objectguid\n    [3] => guid\n    [4] => ipauniqueid\n    [5] => dn\n    [6] => uid\n    [7] => samaccountname\n    [8] => memberof\n    [9] => \n    [10] => \n    [11] => mail\n    [12] => displayname\n    [13] => \n    [14] => jpegphoto\n    [15] => thumbnailphoto\n)\n limit 5003 offset 0","userAgent":"testingsapp","version":"13.0.2.1"}
{"reqId":"WzCpqRoiXdjq2EDB9sJGgwAAAAY","level":0,"time":"2018-06-25T16:36:57+08:00","remoteAddr":"10.10.10.10","user":"--","app":"user_ldap","method":"PROPFIND","url":"\/server\/remote.php\/webdav\/","message":"Ready for a paged search","userAgent":"testingsapp","version":"13.0.2.1"}
{"reqId":"WzCpqRoiXdjq2EDB9sJGgwAAAAY","level":0,"time":"2018-06-25T16:36:57+08:00","remoteAddr":"10.10.10.10","user":"--","app":"user_ldap","method":"PROPFIND","url":"\/server\/remote.php\/webdav\/","message":"initializing paged search for  Filter (&(|(objectclass=inetOrgPerson))(uid=tester)) base Array\n(\n    [0] => ou=testou,o=testo\n)\n attr Array\n(\n    [0] => entryuuid\n    [1] => nsuniqueid\n    [2] => objectguid\n    [3] => guid\n    [4] => ipauniqueid\n    [5] => dn\n    [6] => uid\n    [7] => samaccountname\n    [8] => memberof\n    [9] => \n    [10] => \n    [11] => mail\n    [12] => displayname\n    [13] => \n    [14] => jpegphoto\n    [15] => thumbnailphoto\n)\n limit 5003 offset 0","userAgent":"testingsapp","version":"13.0.2.1"}
{"reqId":"WzCpqRoiXdjq2EDB9sJGgwAAAAY","level":0,"time":"2018-06-25T16:36:57+08:00","remoteAddr":"10.10.10.10","user":"--","app":"user_ldap","method":"PROPFIND","url":"\/server\/remote.php\/webdav\/","message":"Ready for a paged search","userAgent":"testingsapp","version":"13.0.2.1"}
{"reqId":"WzCpqRoiXdjq2EDB9sJGgwAAAAY","level":0,"time":"2018-06-25T16:36:57+08:00","remoteAddr":"10.10.10.10","user":"--","app":"user_ldap","method":"PROPFIND","url":"\/server\/remote.php\/webdav\/","message":"LDAP error Invalid credentials (49) after calling ldap_bind","userAgent":"testingsapp","version":"13.0.2.1"}
{"reqId":"WzCpqRoiXdjq2EDB9sJGgwAAAAY","level":2,"time":"2018-06-25T16:36:57+08:00","remoteAddr":"10.10.10.10","user":"--","app":"user_ldap","method":"PROPFIND","url":"\/server\/remote.php\/webdav\/","message":"Bind failed: 49: Invalid credentials","userAgent":"testingsapp","version":"13.0.2.1"}
{"reqId":"WzCpqRoiXdjq2EDB9sJGgwAAAAY","level":3,"time":"2018-06-25T16:36:57+08:00","remoteAddr":"10.10.10.10","user":"--","app":"no app in context","method":"PROPFIND","url":"\/server\/remote.php\/webdav\/","message":"Exception: {\"Exception\":\"OC\\\\ServerNotAvailableException\",\"Message\":\"Lost connection to LDAP server.\",\"Code\":0,\"Trace\":\"#0 \\\/www\\\/nextcloud\\\/apps\\\/user_ldap\\\/lib\\\/LDAP.php(371): OCA\\\\User_LDAP\\\\LDAP->processLDAPError(Resource id #42)\\n#1 \\\/www\\\/nextcloud\\\/apps\\\/user_ldap\\\/lib\\\/LDAP.php(295): OCA\\\\User_LDAP\\\\LDAP->postFunctionCall()\\n#2 \\\/www\\\/nextcloud\\\/apps\\\/user_ldap\\\/lib\\\/LDAP.php(46): OCA\\\\User_LDAP\\\\LDAP->invokeLDAPMethod(*** sensitive parameters replaced ***)\\n#3 \\\/www\\\/nextcloud\\\/apps\\\/user_ldap\\\/lib\\\/Connection.php(644): OCA\\\\User_LDAP\\\\LDAP->bind(*** sensitive parameters replaced ***)\\n#4 \\\/www\\\/nextcloud\\\/apps\\\/user_ldap\\\/lib\\\/Connection.php(571): OCA\\\\User_LDAP\\\\Connection->bind(*** sensitive parameters replaced ***)\\n#5 \\\/www\\\/nextcloud\\\/apps\\\/user_ldap\\\/lib\\\/Connection.php(184): OCA\\\\User_LDAP\\\\Connection->establishConnection()\\n#6 \\\/www\\\/nextcloud\\\/apps\\\/user_ldap\\\/lib\\\/Connection.php(192): OCA\\\\User_LDAP\\\\Connection->init()\\n#7 \\\/www\\\/nextcloud\\\/apps\\\/user_ldap\\\/lib\\\/Connection.php(625): OCA\\\\User_LDAP\\\\Connection->getConnectionResource()\\n#8 \\\/www\\\/nextcloud\\\/apps\\\/user_ldap\\\/lib\\\/Access.php(1531): OCA\\\\User_LDAP\\\\Connection->bind(*** sensitive parameters replaced ***)\\n#9 \\\/www\\\/nextcloud\\\/apps\\\/user_ldap\\\/lib\\\/User_LDAP.php(201): OCA\\\\User_LDAP\\\\Access->areCredentialsValid(*** sensitive parameters replaced ***)\\n#10 [internal function]: OCA\\\\User_LDAP\\\\User_LDAP->checkPassword(*** sensitive parameters replaced ***)\\n#11 \\\/www\\\/nextcloud\\\/apps\\\/user_ldap\\\/lib\\\/User_Proxy.php(108): call_user_func_array(Array, Array)\\n#12 \\\/www\\\/nextcloud\\\/apps\\\/user_ldap\\\/lib\\\/Proxy.php(150): OCA\\\\User_LDAP\\\\User_Proxy->callOnLastSeenOn('tester', 'checkPassword', Array, false)\\n#13 \\\/www\\\/nextcloud\\\/apps\\\/user_ldap\\\/lib\\\/User_Proxy.php(196): OCA\\\\User_LDAP\\\\Proxy->handleRequest('tester', 'checkPassword', Array)\\n#14 \\\/www\\\/nextcloud\\\/lib\\\/private\\\/User\\\/Manager.php(204): OCA\\\\User_LDAP\\\\User_Proxy->checkPassword(*** sensitive parameters replaced ***)\\n#15 \\\/www\\\/nextcloud\\\/lib\\\/private\\\/User\\\/Session.php(558): OC\\\\User\\\\Manager->checkPasswordNoLogging(*** sensitive parameters replaced ***)\\n#16 \\\/www\\\/nextcloud\\\/lib\\\/private\\\/User\\\/Session.php(335): OC\\\\User\\\\Session->loginWithPassword(*** sensitive parameters replaced ***)\\n#17 \\\/www\\\/nextcloud\\\/lib\\\/private\\\/User\\\/Session.php(411): OC\\\\User\\\\Session->login(*** sensitive parameters replaced ***)\\n#18 \\\/www\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Auth.php(130): OC\\\\User\\\\Session->logClientIn(*** sensitive parameters replaced ***)\\n#19 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Backend\\\/AbstractBasic.php(105): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Auth->validateUserPass(*** sensitive parameters replaced ***)\\n#20 \\\/www\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Auth.php(253): Sabre\\\\DAV\\\\Auth\\\\Backend\\\\AbstractBasic->check(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#21 \\\/www\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Auth.php(155): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Auth->auth(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#22 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Plugin.php(199): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Auth->check(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#23 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Plugin.php(150): Sabre\\\\DAV\\\\Auth\\\\Plugin->check(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#24 [internal function]: Sabre\\\\DAV\\\\Auth\\\\Plugin->beforeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#25 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#26 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(466): Sabre\\\\Event\\\\EventEmitter->emit('beforeMethod', Array)\\n#27 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#28 \\\/www\\\/nextcloud\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/webdav.php(80): Sabre\\\\DAV\\\\Server->exec()\\n#29 \\\/www\\\/nextcloud\\\/remote.php(164): require_once('\\\/www\\\/nextcloud\\\/...')\\n#30 {main}\",\"File\":\"\\\/www\\\/nextcloud\\\/apps\\\/user_ldap\\\/lib\\\/LDAP.php\",\"Line\":333}","userAgent":"testingsapp","version":"13.0.2.1"}
{"reqId":"WzCpqRoiXdjq2EDB9sJGgwAAAAY","level":4,"time":"2018-06-25T16:36:57+08:00","remoteAddr":"10.10.10.10","user":"--","app":"webdav","method":"PROPFIND","url":"\/server\/remote.php\/webdav\/","message":"Exception: {\"Exception\":\"Sabre\\\\DAV\\\\Exception\\\\ServiceUnavailable\",\"Message\":\"OC\\\\ServerNotAvailableException: Lost connection to LDAP server.\",\"Code\":0,\"Trace\":\"#0 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Plugin.php(199): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Auth->check(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#1 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Plugin.php(150): Sabre\\\\DAV\\\\Auth\\\\Plugin->check(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#2 [internal function]: Sabre\\\\DAV\\\\Auth\\\\Plugin->beforeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#3 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#4 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(466): Sabre\\\\Event\\\\EventEmitter->emit('beforeMethod', Array)\\n#5 \\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#6 \\\/www\\\/nextcloud\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/webdav.php(80): Sabre\\\\DAV\\\\Server->exec()\\n#7 \\\/www\\\/nextcloud\\\/remote.php(164): require_once('\\\/www\\\/nextcloud\\\/...')\\n#8 {main}\",\"File\":\"\\\/www\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Auth.php\",\"Line\":163}","userAgent":"testingsapp","version":"13.0.2.1"}

This is quite problematic as it affects users when the backup host is unreachable.

2)

When the checkbox "Configuration active" is unchecked, all LDAP users cannot login anymore, even if the primary LDAP server is still reachable and green light is showing in the LDAP wizard. LDAP users who try to login with a correct password, simply see the "Wrong password" message at the login screen. Once the checkbox is ticked again, login works again, too. Here is the server log when "Wrong password" message appears:

Server log

{"reqId":"WzDMfWyxJmLaHAAN4BEEqgAAAAA","level":1,"time":"2018-06-25T19:05:34+08:00","remoteAddr":"10.10.10.10","user":"--","app":"admin_audit","method":"POST","url":"\/server\/index.php\/login?user=tester","message":"Login attempt: \"tester\"","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:62.0) Gecko\/20100101 Firefox\/62.0","version":"13.0.2.1"}
{"reqId":"WzDMfWyxJmLaHAAN4BEEqgAAAAA","level":2,"time":"2018-06-25T19:05:34+08:00","remoteAddr":"10.10.10.10","user":"--","app":"core","method":"POST","url":"\/server\/index.php\/login?user=tester","message":"Login failed: 'tester' (Remote IP: '10.10.10.10')","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:62.0) Gecko\/20100101 Firefox\/62.0","version":"13.0.2.1"}
{"reqId":"WzDMfWyxJmLaHAAN4BEEqgAAAAA","level":1,"time":"2018-06-25T19:05:36+08:00","remoteAddr":"10.10.10.10","user":"--","app":"core","method":"POST","url":"\/server\/index.php\/login?user=tester","message":"Bruteforce attempt from \"10.10.10.10\" detected for action \"login\".","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:62.0) Gecko\/20100101 Firefox\/62.0","version":"13.0.2.1"}
{"reqId":"WzDMgI4dwLqOvkYy8OmhWwAAAAo","level":0,"time":"2018-06-25T19:05:36+08:00","remoteAddr":"10.10.10.10","user":"--","app":"core","method":"GET","url":"\/server\/index.php\/login?user=tester","message":"Scss is disabled for \/www\/nextcloud\/core\/css\/jquery-ui-fixes.scss, ignoring","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:62.0) Gecko\/20100101 Firefox\/62.0","version":"13.0.2.1"}
{"reqId":"WzDMgI4dwLqOvkYy8OmhWwAAAAo","level":0,"time":"2018-06-25T19:05:36+08:00","remoteAddr":"10.10.10.10","user":"--","app":"core","method":"GET","url":"\/server\/index.php\/login?user=tester","message":"Scss is disabled for \/www\/nextcloud\/core\/css\/server.scss, ignoring","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:62.0) Gecko\/20100101 Firefox\/62.0","version":"13.0.2.1"}
{"reqId":"WzDMgI4dwLqOvkYy8OmhWwAAAAo","level":0,"time":"2018-06-25T19:05:36+08:00","remoteAddr":"10.10.10.10","user":"--","app":"core","method":"GET","url":"\/server\/index.php\/login?user=tester","message":"Scss is disabled for \/www\/nextcloud\/core\/css\/share.scss, ignoring","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:62.0) Gecko\/20100101 Firefox\/62.0","version":"13.0.2.1"}
{"reqId":"WzDMgI4dwLqOvkYy8OmhWwAAAAo","level":0,"time":"2018-06-25T19:05:36+08:00","remoteAddr":"10.10.10.10","user":"--","app":"core","method":"GET","url":"\/server\/index.php\/login?user=tester","message":"Scss is disabled for \/www\/nextcloud\/core\/css\/jquery.ocdialog.scss, ignoring","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:62.0) Gecko\/20100101 Firefox\/62.0","version":"13.0.2.1"}

Not sure whether you have to set the backup host on NC 12 first and then migrate to NC 13 to reproduce the above cases.

Any help is appreciated, thanks!

[nextcloud-bot]

GitMate.io thinks possibly related issues are #3655 (Lost connection to LDAP server), #3135 (NC 11 LDAP issue on server profiles), #3074 (Can't add LDAP server), #2158 (LDAP-Users can't use external storage), and #2372 (LDAP error when # used in filter).

[MorrisJobke]

cc @nextcloud/ldap

[blizzz]

About 1) I can reproduce it locally, too. Going to investigate it tomorrow.

About 2) the "Configuration active" flag covers the whole configuration. So, if that is unchecked the LDAP configuration is not being considered on normal operation, so this works as expected. Or do you mean "Disable Main Server" instead?

[GitHubUser4234]

Hi @blizzz :)

About 1) I can reproduce it locally, too. Going to investigate it tomorrow.

Great, thank you!

About 2) the "Configuration active" flag covers the whole configuration. So, if that is unchecked the LDAP configuration is not being considered on normal operation, so this works as expected. Or do you mean "Disable Main Server" instead?

Oh, thanks for the explanation, there was indeed the misinterpretation that the "Configuration active" flag was meant for the backup hosting settings below that checkbox. So basically we can forget about 2), a suggestion might be though that the UI might use some improvement to visually group the backup host fields together.

[blizzz]

@GitHubUser4234 It looks like this can be fixed with some code simplification :D You may want to try with that patch (against stable13 branch):

diff --git a/apps/user_ldap/lib/Connection.php b/apps/user_ldap/lib/Connection.php
index 758d3f906b..fb039a306e 100644
--- a/apps/user_ldap/lib/Connection.php
+++ b/apps/user_ldap/lib/Connection.php
@@ -504,6 +504,8 @@ class Connection extends LDAPUtility {
 
    /**
     * Connects and Binds to LDAP
+    *
+    * @throws ServerNotAvailableException
     */
    private function establishConnection() {
        if(!$this->configuration->ldapConfigurationActive) {
@@ -545,17 +547,11 @@ class Connection extends LDAPUtility {
                || $this->getFromCache('overrideMainServer'));
            $isBackupHost = (trim($this->configuration->ldapBackupHost) !== "");
            $bindStatus = false;
-           $error = -1;
            try {
                if (!$isOverrideMainServer) {
                    $this->doConnect($this->configuration->ldapHost,
                        $this->configuration->ldapPort);
-                   $bindStatus = $this->bind();
-                   $error = $this->ldap->isResource($this->ldapConnectionRes) ?
-                       $this->ldap->errno($this->ldapConnectionRes) : -1;
-               }
-               if($bindStatus === true) {
-                   return $bindStatus;
+                   return $this->bind();
                }
            } catch (ServerNotAvailableException $e) {
                if(!$isBackupHost) {
@@ -564,7 +560,7 @@ class Connection extends LDAPUtility {
            }
 
            //if LDAP server is not reachable, try the Backup (Replica!) Server
-           if($isBackupHost && ($error !== 0 || $isOverrideMainServer)) {
+           if($isBackupHost || $isOverrideMainServer) {
                $this->doConnect($this->configuration->ldapBackupHost,
                                 $this->configuration->ldapBackupPort);
                $this->bindResult = [];

The thoughts behind the change are: we're should contact the backup server only when the first one is offline. This is already being dealt with the ServerNotAvailableException exception. So, if none occurs we can directly return the bind state. And therefore we don't need to take the error code into account.

I am going to wind my head around it a bit more (thinking of edge cases) and put it into a proper PR eventually.

[GitHubUser4234]

Thanks @blizzz , tests indicate that the patch fixes the issue.

Having a quick look at the old code, it looks like $bindStatus isn't true as otherwise the bind state would have returned similarly to the new code?

Great, so once the PR is ready we would then apply the final patch to our environment, thanks a lot!

[blizzz]

@GitHubUser4234 the bind against LDAP is the auth attempt, and when that fails, e.g. wrong password, we'll have it false and LDAP responds with 49 error code.

[GitHubUser4234]

Oh yeah, that perfectly fits the pattern described in 1), great! 😃

[blizzz]

@GitHubUser4234 PR is created in #10031, the backport to 13 in #10032

[GitHubUser4234]

Thanks @blizzz :)))))