From e559447f833fe12a2f7030ab6f80a20622cbfb84 Mon Sep 17 00:00:00 2001 From: Mateusz Mandera Date: Fri, 27 Dec 2019 23:03:00 +0100 Subject: [PATCH] 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 | 3 ++- zproject/backends.py | 14 +++++++++----- zproject/settings.py | 17 +++++++++++++++++ zproject/test_settings.py | 1 + 4 files changed, 29 insertions(+), 6 deletions(-) diff --git a/zerver/tests/test_auth_backends.py b/zerver/tests/test_auth_backends.py index 87c649201d..e377239214 100644 --- a/zerver/tests/test_auth_backends.py +++ b/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: diff --git a/zproject/backends.py b/zproject/backends.py index cc81643dd7..f241028b1e 100644 --- a/zproject/backends.py +++ b/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 diff --git a/zproject/settings.py b/zproject/settings.py index 6f48d02943..470ac54eab 100644 --- a/zproject/settings.py +++ b/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, diff --git a/zproject/test_settings.py b/zproject/test_settings.py index 85c71cdde4..35f9ae631f 100644 --- a/zproject/test_settings.py +++ b/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')