ldap: Fix logging of warning for deactivated users.

Also cleans up the interface between the management command and the
LDAP backends code to not guess/recompute under what circumstances
what should be logged.

Co-authored-by: mateuszmandera <mateusz.mandera@protonmail.com>

zerver/management/commands/sync_ldap_user_data.py

@@ -22,12 +22,7 @@ def sync_ldap_user_data(user_profiles: List[UserProfile]) -> None:
         # This will save the user if relevant, and will do nothing if the user
         # does not exist.
         try:
-            if sync_user_from_ldap(u):
+            sync_user_from_ldap(u, logger)
-                logger.info("Updated %s." % (u.email,))
-            else:
-                logger.warning("Did not find %s in LDAP." % (u.email,))
-                if settings.LDAP_DEACTIVATE_NON_MATCHING_USERS:
-                    logger.info("Deactivated non-matching user: %s" % (u.email,))
         except ZulipLDAPException as e:
             logger.error("Error attempting to update user %s:" % (u.email,))
             logger.error(e)

zerver/tests/test_auth_backends.py

@@ -2599,7 +2599,7 @@ class TestZulipLDAPUserPopulator(ZulipLDAPTestCase):
                 LDAP_APPEND_DOMAIN='zulip.com',
                 AUTH_LDAP_BIND_PASSWORD='',
                 AUTH_LDAP_USER_DN_TEMPLATE='uid=%(user)s,ou=users,dc=zulip,dc=com'):
-            result = sync_user_from_ldap(user_profile)
+            result = sync_user_from_ldap(user_profile, mock.Mock())
             self.assertTrue(result)
 
     @mock.patch("zproject.backends.do_deactivate_user")
@@ -2615,7 +2615,7 @@ class TestZulipLDAPUserPopulator(ZulipLDAPTestCase):
                 LDAP_APPEND_DOMAIN='zulip.com',
                 AUTH_LDAP_BIND_PASSWORD='wrongpass'):
             with self.assertRaises(PopulateUserLDAPError):
-                sync_user_from_ldap(self.example_user('hamlet'))
+                sync_user_from_ldap(self.example_user('hamlet'), mock.Mock())
             mock_deactivate.assert_not_called()
 
     def test_update_full_name(self) -> None:
@@ -2707,6 +2707,24 @@ class TestZulipLDAPUserPopulator(ZulipLDAPTestCase):
         hamlet = self.example_user('hamlet')
         self.assertTrue(hamlet.is_active)
 
+    def test_user_not_found_in_ldap(self) -> None:
+        with self.settings(
+                LDAP_DEACTIVATE_NON_MATCHING_USERS=False,
+                LDAP_APPEND_DOMAIN='zulip.com',
+                AUTH_LDAP_BIND_PASSWORD='',
+                AUTH_LDAP_USER_DN_TEMPLATE='uid=%(user)s,ou=users,dc=zulip,dc=com'):
+            hamlet = self.example_user("hamlet")
+            mock_logger = mock.MagicMock()
+            result = sync_user_from_ldap(hamlet, mock_logger)
+            mock_logger.warning.assert_called_once_with("Did not find %s in LDAP." % (hamlet.email,))
+            self.assertFalse(result)
+
+            do_deactivate_user(hamlet)
+            mock_logger = mock.MagicMock()
+            result = sync_user_from_ldap(hamlet, mock_logger)
+            self.assertEqual(mock_logger.method_calls, [])  # In this case the logger shouldn't be used.
+            self.assertFalse(result)
+
     def test_update_user_avatar(self) -> None:
         self.mock_ldap.directory = {
             'uid=hamlet,ou=users,dc=zulip,dc=com': {
@@ -2796,9 +2814,9 @@ class TestZulipLDAPUserPopulator(ZulipLDAPTestCase):
                            AUTH_LDAP_BIND_PASSWORD='',
                            AUTH_LDAP_USER_DN_TEMPLATE='uid=%(user)s,ou=users,dc=zulip,dc=com',
                            LDAP_DEACTIVATE_NON_MATCHING_USERS=True):
-            result = sync_user_from_ldap(self.example_user('hamlet'))
+            result = sync_user_from_ldap(self.example_user('hamlet'), mock.Mock())
 
-            self.assertFalse(result)
+            self.assertTrue(result)
             hamlet = self.example_user('hamlet')
             self.assertFalse(hamlet.is_active)
 

zproject/backends.py

@@ -588,14 +588,20 @@ def catch_ldap_error(signal: Signal, **kwargs: Any) -> None:
         # so it seems better not to log that, and only use the original exception's name here.
         raise PopulateUserLDAPError(kwargs['exception'].__class__.__name__)
 
-def sync_user_from_ldap(user_profile: UserProfile) -> bool:
+def sync_user_from_ldap(user_profile: UserProfile, logger: logging.Logger) -> bool:
     backend = ZulipLDAPUserPopulator()
     updated_user = backend.populate_user(backend.django_to_ldap_username(user_profile.email))
-    if not updated_user:
+    if updated_user:
+        logger.info("Updated %s." % (user_profile.email,))
+        return True
+
     if settings.LDAP_DEACTIVATE_NON_MATCHING_USERS:
         do_deactivate_user(user_profile)
-        return False
+        logger.info("Deactivated non-matching user: %s" % (user_profile.email,))
         return True
+    elif user_profile.is_active:
+        logger.warning("Did not find %s in LDAP." % (user_profile.email,))
+    return False
 
 # Quick tool to test whether you're correctly authenticating to LDAP
 def query_ldap(email: str) -> List[str]: