From d30f11888a009dea59711d24696e140d905488c6 Mon Sep 17 00:00:00 2001 From: Dinesh Date: Tue, 2 Jun 2020 23:50:53 +0530 Subject: [PATCH] logging: Set up a different logger for each backend. Adds a top-level logger in `settings.LOGGING` `zulip.auth` with the default handlers `DEFAULT_ZULIP_HANDLERS` and an extra hanlder that writes to `/var/log/zulip/auth.log`. Each auth backend uses it's own logger, `self.logger` which is in form 'zulip.auth.'. This way it's clear which auth backend generated the log and is easier to look for all authentication logs in one file. Besides the above mentioned changes, `name` attribute is added to `ZulipAuthMixin` so that these logging kind of calls wouldn't raise any issues when logging is tried in a class without `name` attribute. Also in the tests we use a new way to check if logger calls are made i.e. we use `assertLogs` to test if something is logged. Thanks to Mateusz Mandera for the idea of having a seperate logger for auth backends and suggestion of using `assertLogs`. --- zerver/tests/test_auth_backends.py | 164 +++++++++++++++-------------- zproject/backends.py | 51 +++++---- zproject/settings.py | 11 ++ 3 files changed, 127 insertions(+), 99 deletions(-) diff --git a/zerver/tests/test_auth_backends.py b/zerver/tests/test_auth_backends.py index cc889020b8..b7e0679656 100644 --- a/zerver/tests/test_auth_backends.py +++ b/zerver/tests/test_auth_backends.py @@ -658,6 +658,7 @@ class SocialAuthBase(DesktopFlowTestingLib, ZulipTestCase): self.backend = self.BACKEND_CLASS self.backend.strategy = DjangoStrategy(storage=BaseDjangoStorage()) self.user_profile.backend = self.backend + self.logger_string = f'zulip.auth.{self.backend.name}' # This is a workaround for the fact that Python social auth # caches the set of authentication backends that are enabled @@ -667,6 +668,9 @@ class SocialAuthBase(DesktopFlowTestingLib, ZulipTestCase): from social_core.backends.utils import load_backends load_backends(settings.AUTHENTICATION_BACKENDS, force_load=True) + def logger_output(self, output_string: str, type: str) -> str: + return f'{type.upper()}:zulip.auth.{self.backend.name}:{output_string}' + def register_extra_endpoints(self, requests_mock: responses.RequestsMock, account_data_dict: Dict[str, str], **extra_data: Any) -> None: @@ -887,14 +891,13 @@ class SocialAuthBase(DesktopFlowTestingLib, ZulipTestCase): # We expect to go through the "choose email" screen here, # because there won't be an existing user account we can # auto-select for the user. - with mock.patch('zproject.backends.logging.info') as m: + with self.assertLogs(self.logger_string, level='INFO') as m: result = self.social_auth_test(account_data_dict, expect_choose_email_screen=True, subdomain='zulip') self.assertEqual(result.status_code, 302) self.assertEqual(result.url, "/login/?is_deactivated=true") - m.assert_called_with("Failed login attempt for deactivated account: %s@%s", - user_profile.id, 'zulip') + self.assertEqual(m.output, [self.logger_output(f"Failed login attempt for deactivated account: {user_profile.id}@zulip", 'info')]) # TODO: verify whether we provide a clear error message def test_social_auth_invalid_realm(self) -> None: @@ -1367,7 +1370,7 @@ class SocialAuthBase(DesktopFlowTestingLib, ZulipTestCase): def test_social_auth_complete_when_base_exc_is_raised(self) -> None: with mock.patch('social_core.backends.oauth.BaseOAuth2.auth_complete', side_effect=AuthStateForbidden('State forbidden')), \ - mock.patch('zproject.backends.logging.warning'): + self.assertLogs(self.logger_string, level='WARNING'): result = self.client_get(reverse('social:complete', args=[self.backend.name])) self.assertEqual(result.status_code, 302) self.assertIn('login', result.url) @@ -1509,7 +1512,7 @@ class SAMLAuthBackendTest(SocialAuthBase): def test_social_auth_complete(self) -> None: with mock.patch.object(OneLogin_Saml2_Response, 'is_valid', return_value=True): with mock.patch.object(OneLogin_Saml2_Auth, 'is_authenticated', return_value=False), \ - mock.patch('zproject.backends.logging.info') as m: + self.assertLogs(self.logger_string, level='INFO') as m: # This mock causes AuthFailed to be raised. saml_response = self.generate_saml_response(self.email, self.name) relay_state = ujson.dumps(dict( @@ -1519,13 +1522,14 @@ class SAMLAuthBackendTest(SocialAuthBase): result = self.client_post('/complete/saml/', post_params) self.assertEqual(result.status_code, 302) self.assertIn('login', result.url) - m.assert_called_with("Authentication failed: SAML login failed: [] (None)") + self.assertEqual(m.output, [self.logger_output("AuthFailed: Authentication failed: SAML login failed: [] (None)", + 'info')]) def test_social_auth_complete_when_base_exc_is_raised(self) -> None: with mock.patch.object(OneLogin_Saml2_Response, 'is_valid', return_value=True): with mock.patch('social_core.backends.saml.SAMLAuth.auth_complete', side_effect=AuthStateForbidden('State forbidden')), \ - mock.patch('zproject.backends.logging.warning') as m: + self.assertLogs(self.logger_string, level='WARNING') as m: saml_response = self.generate_saml_response(self.email, self.name) relay_state = ujson.dumps(dict( state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"}) @@ -1534,21 +1538,21 @@ class SAMLAuthBackendTest(SocialAuthBase): result = self.client_post('/complete/saml/', post_params) self.assertEqual(result.status_code, 302) self.assertIn('login', result.url) - m.assert_called_with("Wrong state parameter given.") + self.assertEqual(m.output, [self.logger_output("Wrong state parameter given.", 'warning')]) def test_social_auth_complete_bad_params(self) -> None: # Simple GET for /complete/saml without the required parameters. # This tests the auth_complete wrapped in our SAMLAuthBackend, # ensuring it prevents this requests from causing an internal server error. - with mock.patch('zproject.backends.logging.info') as m: + with self.assertLogs(self.logger_string, level='INFO') as m: result = self.client_get('/complete/saml/') self.assertEqual(result.status_code, 302) self.assertIn('login', result.url) - m.assert_called_with("/complete/saml/: No SAMLResponse in request.") + self.assertEqual(m.output, [self.logger_output("/complete/saml/: No SAMLResponse in request.", 'info')]) # Check that POSTing the RelayState, but with missing SAMLResponse, # doesn't cause errors either: - with mock.patch('zproject.backends.logging.info') as m: + with self.assertLogs(self.logger_string, level='INFO') as m: relay_state = ujson.dumps(dict( state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"}) )) @@ -1556,10 +1560,10 @@ class SAMLAuthBackendTest(SocialAuthBase): result = self.client_post('/complete/saml/', post_params) self.assertEqual(result.status_code, 302) self.assertIn('login', result.url) - m.assert_called_once_with('/complete/saml/: No SAMLResponse in request.') + self.assertEqual(m.output, [self.logger_output("/complete/saml/: No SAMLResponse in request.", 'info')]) # Now test bad SAMLResponses. - with mock.patch('zproject.backends.logging.info') as m: + with self.assertLogs(self.logger_string, level='INFO') as m: relay_state = ujson.dumps(dict( state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"}) )) @@ -1567,9 +1571,9 @@ class SAMLAuthBackendTest(SocialAuthBase): result = self.client_post('/complete/saml/', post_params) self.assertEqual(result.status_code, 302) self.assertIn('login', result.url) - m.assert_called() + self.assertTrue(m.output != '') - with mock.patch('zproject.backends.logging.info') as m: + with self.assertLogs(self.logger_string, level='INFO') as m: relay_state = ujson.dumps(dict( state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"}) )) @@ -1577,9 +1581,9 @@ class SAMLAuthBackendTest(SocialAuthBase): result = self.client_post('/complete/saml/', post_params) self.assertEqual(result.status_code, 302) self.assertIn('login', result.url) - m.assert_called() + self.assertTrue(m.output != '') - with mock.patch('zproject.backends.logging.info') as m: + with self.assertLogs(self.logger_string, level='INFO') as m: relay_state = ujson.dumps(dict( state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"}) )) @@ -1587,10 +1591,10 @@ class SAMLAuthBackendTest(SocialAuthBase): result = self.client_post('/complete/saml/', post_params) self.assertEqual(result.status_code, 302) self.assertIn('login', result.url) - m.assert_called() + self.assertTrue(m.output != '') def test_social_auth_complete_no_subdomain(self) -> None: - with mock.patch('zproject.backends.logging.info') as m: + with self.assertLogs(self.logger_string, level='INFO') as m: post_params = {"RelayState": '', 'SAMLResponse': self.generate_saml_response(email=self.example_email("hamlet"), name="King Hamlet")} @@ -1598,10 +1602,10 @@ class SAMLAuthBackendTest(SocialAuthBase): result = self.client_post('/complete/saml/', post_params) self.assertEqual(result.status_code, 302) self.assertEqual('/login/', result.url) - m.assert_called_once_with( - "/complete/saml/: Can't figure out subdomain for this authentication request. relayed_params: %s", - {}, - ) + self.assertEqual(m.output, [self.logger_output( + "/complete/saml/: Can't figure out subdomain for this authentication request. relayed_params: %s" % ("{}",), + 'info' + )]) def test_social_auth_complete_wrong_issuing_idp(self) -> None: relay_state = ujson.dumps(dict( @@ -1615,15 +1619,13 @@ class SAMLAuthBackendTest(SocialAuthBase): idps_dict = copy.deepcopy(settings.SOCIAL_AUTH_SAML_ENABLED_IDPS) idps_dict['test_idp']['entity_id'] = 'https://different.idp.example.com/' with self.settings(SOCIAL_AUTH_SAML_ENABLED_IDPS=idps_dict): - with mock.patch('zproject.backends.logging.info') as m: + with self.assertLogs(self.logger_string, level='INFO') as m: post_params = {"RelayState": relay_state, "SAMLResponse": saml_response} result = self.client_post('/complete/saml/', post_params) self.assertEqual(result.status_code, 302) self.assertEqual('/login/', result.url) - m.assert_called_once_with( - "/complete/saml/: No valid IdP as issuer of the SAMLResponse.", - ) + self.assertEqual(m.output, [self.logger_output("/complete/saml/: No valid IdP as issuer of the SAMLResponse.", "info")]) def test_social_auth_complete_valid_get_idp_bad_samlresponse(self) -> None: """ @@ -1632,7 +1634,7 @@ class SAMLAuthBackendTest(SocialAuthBase): validation in the underlying libraries. """ - with mock.patch('zproject.backends.logging.info') as m, \ + with self.assertLogs(self.logger_string, level='INFO') as m, \ mock.patch.object(SAMLAuthBackend, 'get_issuing_idp', return_value='test_idp'): relay_state = ujson.dumps(dict( state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"}) @@ -1642,20 +1644,20 @@ class SAMLAuthBackendTest(SocialAuthBase): self.assertEqual(result.status_code, 302) self.assertIn('login', result.url) - m.assert_called_once() + self.assertTrue(m.output != '') def test_social_auth_saml_bad_idp_param_on_login_page(self) -> None: - with mock.patch('zproject.backends.logging.info') as m: + with self.assertLogs(self.logger_string, level='INFO') as m: result = self.client_get('/login/saml/') self.assertEqual(result.status_code, 302) self.assertEqual('/login/', result.url) - m.assert_called_with("/login/saml/ : Bad idp param: KeyError: %s.", "'idp'") + self.assertEqual(m.output, [self.logger_output("/login/saml/ : Bad idp param: KeyError: %s." % ("'idp'",), 'info')]) - with mock.patch('zproject.backends.logging.info') as m: + with self.assertLogs(self.logger_string, level='INFO') as m: result = self.client_get('/login/saml/?idp=bad_idp') self.assertEqual(result.status_code, 302) self.assertEqual('/login/', result.url) - m.assert_called_with("/login/saml/ : Bad idp param: KeyError: %s.", "'bad_idp'") + self.assertEqual(m.output, [self.logger_output("/login/saml/ : Bad idp param: KeyError: %s." % ("'bad_idp'",), 'info')]) def test_social_auth_invalid_email(self) -> None: """ @@ -1725,15 +1727,14 @@ class SAMLAuthBackendTest(SocialAuthBase): idps_dict['test_idp']['limit_to_subdomains'] = ['zulip', ] with self.settings(SOCIAL_AUTH_SAML_ENABLED_IDPS=idps_dict): account_data_dict = self.get_account_data_dict(email=self.email, name=self.name) - with mock.patch('zproject.backends.logging.info') as m: + with self.assertLogs(self.logger_string, level='INFO') as m: result = self.social_auth_test(account_data_dict, subdomain='zephyr') self.assertEqual(result.status_code, 302) self.assertEqual('/login/', result.url) - m.assert_called_with( - '/complete/saml/: Authentication request with IdP %s but this provider is not enabled ' + - 'for this subdomain %s.', - "test_idp", "zephyr", - ) + self.assertEqual(m.output, [self.logger_output( + '/complete/saml/: Authentication request with IdP %s but this provider is not enabled ' + 'for this subdomain %s.' % ("test_idp", "zephyr"), 'info' + )]) def test_social_auth_saml_login_bad_idp_arg(self) -> None: for action in ['login', 'register']: @@ -1760,17 +1761,18 @@ class SAMLAuthBackendTest(SocialAuthBase): with self.settings(SOCIAL_AUTH_SAML_ENABLED_IDPS=idps_dict, SAML_REQUIRE_LIMIT_TO_SUBDOMAINS=True): - with mock.patch('logging.error') as mock_error: + with self.assertLogs(self.logger_string, level="ERROR") as m: # Initialization of the backend should validate the configured IdPs # with respect to the SAML_REQUIRE_LIMIT_TO_SUBDOMAINS setting and remove # the non-compliant ones. SAMLAuthBackend() self.assertEqual(list(settings.SOCIAL_AUTH_SAML_ENABLED_IDPS.keys()), ['test_idp2', ]) - mock_error.assert_called_with( - "SAML_REQUIRE_LIMIT_TO_SUBDOMAINS is enabled and the following " + - "IdPs don't have limit_to_subdomains specified and will be ignored: " + - "['test_idp']") + self.assertEqual(m.output, [self.logger_output( + "SAML_REQUIRE_LIMIT_TO_SUBDOMAINS is enabled and the following " + "IdPs don't have limit_to_subdomains specified and will be ignored: " + "['test_idp']", 'error' + )]) def test_idp_initiated_signin_subdomain_specified(self) -> None: post_params = { @@ -1859,7 +1861,7 @@ class SAMLAuthBackendTest(SocialAuthBase): "SAMLResponse": self.generate_saml_response(email=self.email, name=self.name) } - with mock.patch("logging.info") as m: + with self.assertLogs(self.logger_string, level='INFO') as m: with mock.patch('zproject.backends.get_subdomain', return_value='invalid'): # Due to the quirks of our test setup, get_subdomain on all these `some_subdomain.testserver` # requests returns 'zulip', so we need to mock it here. @@ -1867,10 +1869,10 @@ class SAMLAuthBackendTest(SocialAuthBase): self.assertEqual(result.status_code, 302) self.assertEqual('/login/', result.url) - m.assert_called_once_with( - "/complete/saml/: Can't figure out subdomain for this authentication request. relayed_params: %s", - {}, - ) + self.assertEqual(m.output, [self.logger_output( + "/complete/saml/: Can't figure out subdomain for this authentication request. relayed_params: %s" % {}, + "info" + )]) class GitHubAuthBackendTest(SocialAuthBase): __unittest_skip__ = False @@ -1974,28 +1976,30 @@ class GitHubAuthBackendTest(SocialAuthBase): verified=False, primary=True), ] - with mock.patch('logging.warning') as mock_warning: + with self.assertLogs(self.logger_string, level='WARNING') as m: result = self.social_auth_test(account_data_dict, subdomain='zulip', email_data=email_data) self.assertEqual(result.status_code, 302) self.assertEqual(result.url, "/login/") - mock_warning.assert_called_once_with( - "Social auth (%s) failed because user has no verified emails", - "GitHub", - ) + self.assertEqual(m.output, [self.logger_output( + "Social auth (%s) failed because user has no verified emails" % ('GitHub',), + "warning" + )]) @override_settings(SOCIAL_AUTH_GITHUB_TEAM_ID='zulip-webapp') def test_social_auth_github_team_not_member_failed(self) -> None: account_data_dict = self.get_account_data_dict(email=self.email, name=self.name) with mock.patch('social_core.backends.github.GithubTeamOAuth2.user_data', side_effect=AuthFailed('Not found')), \ - mock.patch('logging.info') as mock_info: + self.assertLogs(self.logger_string, level='INFO') as mock_info: result = self.social_auth_test(account_data_dict, subdomain='zulip') self.assertEqual(result.status_code, 302) self.assertEqual(result.url, "/login/") - mock_info.assert_called_once_with("GitHub user is not member of required team") + self.assertEqual(mock_info.output, [self.logger_output( + "GitHub user is not member of required team", 'info' + )]) @override_settings(SOCIAL_AUTH_GITHUB_TEAM_ID='zulip-webapp') def test_social_auth_github_team_member_success(self) -> None: @@ -2015,12 +2019,14 @@ class GitHubAuthBackendTest(SocialAuthBase): account_data_dict = self.get_account_data_dict(email=self.email, name=self.name) with mock.patch('social_core.backends.github.GithubOrganizationOAuth2.user_data', side_effect=AuthFailed('Not found')), \ - mock.patch('logging.info') as mock_info: + self.assertLogs(self.logger_string, level='INFO') as mock_info: result = self.social_auth_test(account_data_dict, subdomain='zulip') self.assertEqual(result.status_code, 302) self.assertEqual(result.url, "/login/") - mock_info.assert_called_once_with("GitHub user is not member of required organization") + self.assertEqual(mock_info.output, [self.logger_output( + "GitHub user is not member of required organization", "info" + )]) @override_settings(SOCIAL_AUTH_GITHUB_ORG_NAME='Zulip') def test_social_auth_github_organization_member_success(self) -> None: @@ -2252,18 +2258,18 @@ class GitHubAuthBackendTest(SocialAuthBase): dict(email=account_data_dict["email"], verified=True), ] - with mock.patch('logging.warning') as mock_warning: + with self.assertLogs(self.logger_string, level='WARNING') as m: result = self.social_auth_test(account_data_dict, subdomain='zulip', expect_choose_email_screen=True, email_data=email_data) self.assertEqual(result.status_code, 302) self.assertEqual(result.url, "/login/") - mock_warning.assert_called_once_with( - "Social auth (%s) failed because user has no verified" - " emails associated with the account", - "GitHub", - ) + self.assertEqual(m.output, [self.logger_output( + "Social auth (%s) failed because user has no verified" + " emails associated with the account" % ("GitHub",), + "warning" + )]) def test_github_oauth2_email_not_associated(self) -> None: account_data_dict = dict(email='not-associated@zulip.com', name=self.name) @@ -2276,18 +2282,18 @@ class GitHubAuthBackendTest(SocialAuthBase): dict(email="aaron@zulip.com", verified=True), ] - with mock.patch('logging.warning') as mock_warning: + with self.assertLogs(self.logger_string, level='WARNING') as m: result = self.social_auth_test(account_data_dict, subdomain='zulip', expect_choose_email_screen=True, email_data=email_data) self.assertEqual(result.status_code, 302) self.assertEqual(result.url, "/login/") - mock_warning.assert_called_once_with( - "Social auth (%s) failed because user has no verified" - " emails associated with the account", - "GitHub", - ) + self.assertEqual(m.output, [self.logger_output( + "Social auth (%s) failed because user has no verified" + " emails associated with the account" % ("GitHub",), + "warning" + )]) def test_github_unverified_email_with_existing_account(self) -> None: # check if a user is denied to login if the user manages to @@ -2303,15 +2309,17 @@ class GitHubAuthBackendTest(SocialAuthBase): verified=True, primary=True) ] - with mock.patch('logging.warning') as mock_warning: + with self.assertLogs(self.logger_string, level='WARNING') as m: result = self.social_auth_test(account_data_dict, subdomain='zulip', expect_choose_email_screen=True, email_data=email_data) self.assertEqual(result.status_code, 302) self.assertEqual(result.url, "/login/") - mock_warning.assert_called_once_with("Social auth (%s) failed because user has no verified" - " emails associated with the account", "GitHub") + self.assertEqual(m.output, [self.logger_output( + "Social auth (%s) failed because user has no verified emails associated with the account" % ("GitHub",), + "warning" + )]) class GitLabAuthBackendTest(SocialAuthBase): __unittest_skip__ = False @@ -2353,15 +2361,15 @@ class GoogleAuthBackendTest(SocialAuthBase): def test_social_auth_email_not_verified(self) -> None: account_data_dict = dict(email=self.email, name=self.name) - with mock.patch('logging.warning') as mock_warning: + with self.assertLogs(self.logger_string, level='WARNING') as m: result = self.social_auth_test(account_data_dict, subdomain='zulip') self.assertEqual(result.status_code, 302) self.assertEqual(result.url, "/login/") - mock_warning.assert_called_once_with( - "Social auth (%s) failed because user has no verified emails", - "Google", - ) + self.assertEqual(m.output, [self.logger_output( + "Social auth (%s) failed because user has no verified emails" % ("Google",), + "warning" + )]) def test_social_auth_mobile_success_legacy_url(self) -> None: mobile_flow_otp = '1234abcd' * 8 diff --git a/zproject/backends.py b/zproject/backends.py index 7029c7c111..28f92afb52 100644 --- a/zproject/backends.py +++ b/zproject/backends.py @@ -244,6 +244,14 @@ class ZulipAuthMixin: from memcached before checking the database (avoiding a database query in most cases). """ + name = "undefined" + _logger = None + + @property + def logger(self) -> logging.Logger: + if self._logger is None: + self._logger = logging.getLogger(f"zulip.auth.{self.name}") + return self._logger def get_user(self, user_profile_id: int) -> Optional[UserProfile]: """Override the Django method for getting a UserProfile object from @@ -1081,8 +1089,8 @@ def social_associate_user_helper(backend: BaseAuth, return_data: Dict[str, Any], if verified_emails_length == 0: # TODO: Provide a nice error message screen to the user # for this case, rather than just logging a warning. - logging.warning("Social auth (%s) failed because user has no verified emails", - backend.auth_backend_name) + backend.logger.warning("Social auth (%s) failed because user has no verified emails", + backend.auth_backend_name) return_data["email_not_verified"] = True return None @@ -1124,9 +1132,9 @@ def social_associate_user_helper(backend: BaseAuth, return_data: Dict[str, Any], # If a user edits the submit value for the choose email form, we might # end up with a wrong email associated with the account. The below code # takes care of that. - logging.warning("Social auth (%s) failed because user has no verified" - " emails associated with the account", - backend.auth_backend_name) + backend.logger.warning("Social auth (%s) failed because user has no verified" + " emails associated with the account", + backend.auth_backend_name) return_data["email_not_associated"] = True return None @@ -1230,8 +1238,8 @@ def social_auth_finish(backend: Any, return HttpResponseRedirect(reverse('zerver.views.registration.find_account')) if inactive_user: - logging.info("Failed login attempt for deactivated account: %s@%s", - return_data['inactive_user_id'], return_data['realm_string_id']) + backend.logger.info("Failed login attempt for deactivated account: %s@%s", + return_data['inactive_user_id'], return_data['realm_string_id']) return redirect_deactivated_user_to_login() if auth_backend_disabled or inactive_realm or no_verified_email or email_not_associated: @@ -1242,13 +1250,13 @@ def social_auth_finish(backend: Any, if invalid_email: # In case of invalid email, we will end up on registration page. # This seems better than redirecting to login page. - logging.warning( + backend.logger.warning( "%s got invalid email argument.", backend.auth_backend_name, ) return None if auth_failed_reason: - logging.info(auth_failed_reason) + backend.logger.info(auth_failed_reason) return None # Structurally, all the cases where we don't have an authenticated @@ -1354,12 +1362,12 @@ class SocialAuthMixin(ZulipAuthMixin, ExternalAuthMethod): # the flow or the IdP is unreliable and returns a bad http response), # don't throw a 500, just send them back to the # login page and record the event at the info log level. - logging.info(str(e)) + self.logger.info(str(e)) return None except SocialAuthBaseException as e: # Other python-social-auth exceptions are likely # interesting enough that we should log a warning. - logging.warning(str(e)) + self.logger.warning(str(e)) return None @classmethod @@ -1512,9 +1520,9 @@ class SAMLAuthBackend(SocialAuthMixin, SAMLAuth): if 'limit_to_subdomains' not in idp_dict ] if idps_without_limit_to_subdomains: - logging.error("SAML_REQUIRE_LIMIT_TO_SUBDOMAINS is enabled and the following " + - "IdPs don't have limit_to_subdomains specified and will be ignored: " + - "%s" % (idps_without_limit_to_subdomains,)) + self.logger.error("SAML_REQUIRE_LIMIT_TO_SUBDOMAINS is enabled and the following " + + "IdPs don't have limit_to_subdomains specified and will be ignored: " + + "%s" % (idps_without_limit_to_subdomains,)) for idp_name in idps_without_limit_to_subdomains: del settings.SOCIAL_AUTH_SAML_ENABLED_IDPS[idp_name] super().__init__(*args, **kwargs) @@ -1529,7 +1537,7 @@ class SAMLAuthBackend(SocialAuthMixin, SAMLAuth): except KeyError as e: # If the above raise KeyError, it means invalid or no idp was specified, # we should log that and redirect to the login page. - logging.info("/login/saml/ : Bad idp param: KeyError: %s.", str(e)) + self.logger.info("/login/saml/ : Bad idp param: KeyError: %s.", str(e)) return reverse('zerver.views.auth.login_page', kwargs = {'template_name': 'zerver/login.html'}) @@ -1583,7 +1591,8 @@ class SAMLAuthBackend(SocialAuthMixin, SAMLAuth): resp = OneLogin_Saml2_Response(settings={}, response=SAMLResponse) issuers = resp.get_issuers() except cls.SAMLRESPONSE_PARSING_EXCEPTIONS as e: - logging.info("Error while parsing SAMLResponse: %s: %s", e.__class__.__name__, e) + logger = logging.getLogger(f"zulip.auth.{cls.name}") + logger.info("Error while parsing SAMLResponse: %s: %s", e.__class__.__name__, e) return None for idp_name, idp_config in settings.SOCIAL_AUTH_SAML_ENABLED_IDPS.items(): @@ -1648,7 +1657,7 @@ class SAMLAuthBackend(SocialAuthMixin, SAMLAuth): """ SAMLResponse = self.strategy.request_data().get('SAMLResponse') if SAMLResponse is None: - logging.info("/complete/saml/: No SAMLResponse in request.") + self.logger.info("/complete/saml/: No SAMLResponse in request.") return None relayed_params = self.get_relayed_params() @@ -1657,19 +1666,19 @@ class SAMLAuthBackend(SocialAuthMixin, SAMLAuth): if subdomain is None: error_msg = "/complete/saml/: Can't figure out subdomain for this authentication request. " + \ "relayed_params: %s" - logging.info(error_msg, relayed_params) + self.logger.info(error_msg, relayed_params) return None idp_name = self.get_issuing_idp(SAMLResponse) if idp_name is None: - logging.info("/complete/saml/: No valid IdP as issuer of the SAMLResponse.") + self.logger.info("/complete/saml/: No valid IdP as issuer of the SAMLResponse.") return None idp_valid = self.validate_idp_for_subdomain(idp_name, subdomain) if not idp_valid: error_msg = "/complete/saml/: Authentication request with IdP %s but this provider is not " + \ "enabled for this subdomain %s." - logging.info(error_msg, idp_name, subdomain) + self.logger.info(error_msg, idp_name, subdomain) return None result = None @@ -1690,7 +1699,7 @@ class SAMLAuthBackend(SocialAuthMixin, SAMLAuth): result = super().auth_complete(*args, **kwargs) except self.SAMLRESPONSE_PARSING_EXCEPTIONS as e: # These can be raised if SAMLResponse is missing or badly formatted. - logging.info("/complete/saml/: %s: %s", e.__class__.__name__, e) + self.logger.info("/complete/saml/: %s: %s", e.__class__.__name__, e) # Fall through to returning None. finally: if result is None: diff --git a/zproject/settings.py b/zproject/settings.py index 0a4d33e830..d571eb9004 100644 --- a/zproject/settings.py +++ b/zproject/settings.py @@ -680,6 +680,7 @@ SOFT_DEACTIVATION_LOG_PATH = zulip_path("/var/log/zulip/soft_deactivation.log") TRACEMALLOC_DUMP_DIR = zulip_path("/var/log/zulip/tracemalloc") SCHEDULED_MESSAGE_DELIVERER_LOG_PATH = zulip_path("/var/log/zulip/scheduled_message_deliverer.log") RETENTION_LOG_PATH = zulip_path("/var/log/zulip/message_retention.log") +AUTH_LOG_PATH = zulip_path("/var/log/zulip/auth.log") # The EVENT_LOGS feature is an ultra-legacy piece of code, which # originally logged all significant database changes for debugging. @@ -753,6 +754,12 @@ LOGGING: Dict[str, Any] = { if not DEBUG_ERROR_REPORTING else []), 'formatter': 'default' }, + 'auth_file': { + 'level': 'DEBUG', + 'class': 'logging.handlers.WatchedFileHandler', + 'formatter': 'default', + 'filename': AUTH_LOG_PATH, + }, 'console': { 'level': 'DEBUG', 'class': 'logging.StreamHandler', @@ -890,6 +897,10 @@ LOGGING: Dict[str, Any] = { 'zerver.management.commands.deliver_scheduled_messages': { 'level': 'DEBUG', }, + 'zulip.auth': { + 'level': 'DEBUG', + 'handlers': DEFAULT_ZULIP_HANDLERS + ['auth_file'] + }, 'zulip.ldap': { 'level': 'DEBUG', 'handlers': ['console', 'ldap_file', 'errors_file'],