ldap: Improve logging.

Our ldap integration is quite sensitive to misconfigurations, so more
logging is better than less to help debug those issues.
Despite the following docstring on ZulipLDAPException:

"Since this inherits from _LDAPUser.AuthenticationFailed, these will
be caught and logged at debug level inside django-auth-ldap's
authenticate()"

We weren't actually logging anything, because debug level messages were
ignored due to our general logging settings. It is however desirable to
log these errors, as they can prove useful in debugging configuration
problems. The django_auth_ldap logger can get fairly spammy on debug
level, so we delegate ldap logging to a separate file
/var/log/zulip/ldap.log to avoid spamming server.log too much.

zerver/tests/test_auth_backends.py

@@ -3246,7 +3246,8 @@ class TestQueryLDAP(ZulipLDAPTestCase):
     def test_user_not_present(self) -> None:
         # othello doesn't have an entry in our test directory
         values = query_ldap(self.example_email('othello'))
-        self.assertEqual(values, ['No such user found'])
+        self.assert_length(values, 1)
+        self.assertIn('No such user found', values[0])
 
     @override_settings(AUTHENTICATION_BACKENDS=('zproject.backends.ZulipLDAPAuthBackend',))
     def test_normal_query(self) -> None:

zproject/backends.py

@@ -286,7 +286,7 @@ def email_belongs_to_ldap(realm: Realm, email: str) -> bool:
     else:
         return False
 
-
+ldap_logger = logging.getLogger("zulip.ldap")
 class ZulipLDAPException(_LDAPUser.AuthenticationFailed):
     """Since this inherits from _LDAPUser.AuthenticationFailed, these will
     be caught and logged at debug level inside django-auth-ldap's authenticate()"""
@@ -368,7 +368,10 @@ class ZulipLDAPAuthBackendBase(ZulipAuthMixin, LDAPBackend):
         if _LDAPUser(self, result).attrs is None:
             # Check that there actually is an ldap entry matching the result username
             # we want to return. Otherwise, raise an exception.
-            raise ZulipLDAPExceptionNoMatchingLDAPUser()
+            error_message = "No ldap user matching django_to_ldap_username result: {}. Input username: {}"
+            raise ZulipLDAPExceptionNoMatchingLDAPUser(
+                error_message.format(result, username)
+            )
 
         return result
 
@@ -541,7 +544,8 @@ class ZulipLDAPAuthBackend(ZulipLDAPAuthBackendBase):
             # to the user's LDAP username before calling the
             # django-auth-ldap authenticate().
             username = self.django_to_ldap_username(username)
-        except ZulipLDAPExceptionNoMatchingLDAPUser:
+        except ZulipLDAPExceptionNoMatchingLDAPUser as e:
+            ldap_logger.debug("{}: {}".format(self.__class__.__name__, e))
             if return_data is not None:
                 return_data['no_matching_ldap_user'] = True
             return None
@@ -753,8 +757,8 @@ def query_ldap(email: str) -> List[str]:
     if backend is not None:
         try:
             ldap_username = backend.django_to_ldap_username(email)
-        except ZulipLDAPExceptionNoMatchingLDAPUser:
-            values.append("No such user found")
+        except ZulipLDAPExceptionNoMatchingLDAPUser as e:
+            values.append("No such user found: {}".format(e))
             return values
 
         ldap_attrs = _LDAPUser(backend, ldap_username).attrs

zproject/settings.py

@@ -640,6 +640,7 @@ EMAIL_LOG_PATH = zulip_path("/var/log/zulip/send_email.log")
 EMAIL_MIRROR_LOG_PATH = zulip_path("/var/log/zulip/email_mirror.log")
 EMAIL_DELIVERER_LOG_PATH = zulip_path("/var/log/zulip/email-deliverer.log")
 EMAIL_CONTENT_LOG_PATH = zulip_path("/var/log/zulip/email_content.log")
+LDAP_LOG_PATH = zulip_path("/var/log/zulip/ldap.log")
 LDAP_SYNC_LOG_PATH = zulip_path("/var/log/zulip/sync_ldap_user_data.log")
 QUEUE_ERROR_DIR = zulip_path("/var/log/zulip/queue_error")
 DIGEST_LOG_PATH = zulip_path("/var/log/zulip/digest.log")
@@ -745,6 +746,12 @@ LOGGING = {
             'formatter': 'default',
             'filename': ERROR_FILE_LOG_PATH,
         },
+        'ldap_file': {
+            'level': 'DEBUG',
+            'class': 'logging.handlers.WatchedFileHandler',
+            'formatter': 'default',
+            'filename': LDAP_LOG_PATH,
+        },
     },
     'loggers': {
         # The Python logging module uses a hierarchy of logger names for config:
@@ -812,6 +819,11 @@ LOGGING = {
         # },
 
         # other libraries, alphabetized
+        'django_auth_ldap': {
+            'level': 'DEBUG',
+            'handlers': ['console', 'ldap_file', 'errors_file'],
+            'propagate': False,
+        },
         'pika.adapters': {
             # pika is super chatty on INFO.
             'level': 'WARNING',
@@ -854,6 +866,11 @@ LOGGING = {
         'zerver.management.commands.deliver_scheduled_messages': {
             'level': 'DEBUG',
         },
+        'zulip.ldap': {
+            'level': 'DEBUG',
+            'handlers': ['console', 'ldap_file', 'errors_file'],
+            'propagate': False,
+        },
         'zulip.management': {
             'handlers': ['file', 'errors_file'],
             'propagate': False,

zproject/test_settings.py

@@ -124,6 +124,7 @@ if not CASPER_TESTS:
     set_loglevel('zulip.requests', 'CRITICAL')
     set_loglevel('zulip.management', 'CRITICAL')
     set_loglevel('django.request', 'ERROR')
+    set_loglevel('django_auth_ldap', 'WARNING')
     set_loglevel('fakeldap', 'ERROR')
     set_loglevel('zulip.send_email', 'ERROR')
     set_loglevel('zerver.lib.push_notifications', 'WARNING')