auth: Add logging of successful attempts to social codepath.

The previous commit introduced logging of attempts for username+password
backends. For completeness, we should log, in the same format,
successful attempts via social auth backends.

zerver/tests/test_auth_backends.py

@@ -547,6 +547,11 @@ class AuthBackendTest(ZulipTestCase):
 
             backend.strategy.request_data = return_email
 
+            if request is None:
+                request = mock.MagicMock()
+                request.META = dict(REMOTE_ADDR="127.0.0.1")
+            backend.strategy.request = request
+
             result = orig_authenticate(backend, request, **kwargs)
             return result
 
@@ -594,7 +599,12 @@ class AuthBackendTest(ZulipTestCase):
                     self.verify_backend(backend, good_kwargs=good_kwargs, bad_kwargs=bad_kwargs)
                 # Verify logging for deactivated users
                 self.assertEqual(
-                    info_log.output,
+                    # Filter out noisy logs:
+                    [
+                        output
+                        for output in info_log.output
+                        if "Authentication attempt from 127.0.0.1" not in output
+                    ],
                     [
                         f"INFO:{logger_name}:Failed login attempt for deactivated account: {user.id}@{user.realm.string_id}",
                         f"INFO:{logger_name}:Failed login attempt for deactivated account: {user.id}@{user.realm.string_id}",
@@ -1054,12 +1064,13 @@ class SocialAuthBase(DesktopFlowTestingLib, ZulipTestCase):
 
     def test_social_auth_success(self) -> None:
         account_data_dict = self.get_account_data_dict(email=self.email, name=self.name)
-        result = self.social_auth_test(
+        with self.assertLogs(self.logger_string, level="INFO") as m:
-            account_data_dict,
+            result = self.social_auth_test(
-            expect_choose_email_screen=False,
+                account_data_dict,
-            subdomain="zulip",
+                expect_choose_email_screen=False,
-            next="/user_uploads/image",
+                subdomain="zulip",
-        )
+                next="/user_uploads/image",
+            )
         data = load_subdomain_token(result)
         self.assertEqual(data["email"], self.example_email("hamlet"))
         self.assertEqual(data["full_name"], self.name)
@@ -1070,6 +1081,11 @@ class SocialAuthBase(DesktopFlowTestingLib, ZulipTestCase):
         uri = f"{parsed_url.scheme}://{parsed_url.netloc}{parsed_url.path}"
         self.assertTrue(uri.startswith("http://zulip.testserver/accounts/login/subdomain/"))
 
+        self.assertIn(
+            f"INFO:{self.logger_string}:Authentication attempt from 127.0.0.1: subdomain=zulip;username=hamlet@zulip.com;outcome=success",
+            m.output[0],
+        )
+
     @override_settings(SOCIAL_AUTH_SUBDOMAIN=None)
     def test_when_social_auth_subdomain_is_not_set(self) -> None:
         account_data_dict = self.get_account_data_dict(email=self.email, name=self.name)

zproject/backends.py

@@ -304,9 +304,29 @@ def log_auth_attempts(auth_func: AuthFuncT, *args: Any, **kwargs: Any) -> Option
     realm = kwargs["realm"]
     return_data = kwargs["return_data"]
 
+    log_auth_attempt(
+        backend_instance.logger,
+        request,
+        realm,
+        username,
+        succeeded=result is not None,
+        return_data=return_data,
+    )
+
+    return result
+
+
+def log_auth_attempt(
+    logger: logging.Logger,
+    request: HttpRequest,
+    realm: Realm,
+    username: str,
+    succeeded: bool,
+    return_data: Dict[str, Any],
+) -> None:
     ip_addr = request.META.get("REMOTE_ADDR")
-    outcome = "success" if result is not None else "failed"
+    outcome = "success" if succeeded else "failed"
-    backend_instance.logger.info(
+    logger.info(
         "Authentication attempt from %s: subdomain=%s;username=%s;outcome=%s;return_data=%s",
         ip_addr,
         realm.subdomain,
@@ -315,8 +335,6 @@ def log_auth_attempts(auth_func: AuthFuncT, *args: Any, **kwargs: Any) -> Option
         return_data,
     )
 
-    return result
-
 
 class ZulipAuthMixin:
     """This common mixin is used to override Django's default behavior for
@@ -1661,6 +1679,18 @@ def social_auth_finish(
     # The next step is to call login_or_register_remote_user, but
     # there are two code paths here because of an optimization to save
     # a redirect on mobile and desktop.
+
+    # Authentication failures happen on the external provider's side, so we don't get to log those,
+    # but we should log the successes at least.
+    log_auth_attempt(
+        backend.logger,
+        strategy.request,
+        realm,
+        username=email_address,
+        succeeded=True,
+        return_data={},
+    )
+
     data_dict = ExternalAuthDataDict(
         subdomain=realm.subdomain,
         is_signup=is_signup,