paulmataruso/zulip
1
0
Fork 0
mirror of https://github.com/zulip/zulip.git synced 2025-10-28 10:33:54 +00:00
Code Issues Packages Projects Releases Wiki Activity

logging: Set up a different logger for each backend.

Browse Source 
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.<backend name>'.

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`.
This commit is contained in:
Dinesh
2020-06-02 23:50:53 +05:30
committed by Tim Abbott
parent b1b34b6f6a
commit d30f11888a
3 changed files with 127 additions and 99 deletions
Download Patch File Download Diff File Expand all files Collapse all files

164
zerver/tests/test_auth_backends.py
View File

@@ -658,6 +658,7 @@ class SocialAuthBase(DesktopFlowTestingLib, ZulipTestCase):
self.backend = self.BACKEND_CLASS self.backend = self.BACKEND_CLASS
self.backend.strategy = DjangoStrategy(storage=BaseDjangoStorage()) self.backend.strategy = DjangoStrategy(storage=BaseDjangoStorage())
self.user_profile.backend = self.backend 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 # This is a workaround for the fact that Python social auth
# caches the set of authentication backends that are enabled # 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 from social_core.backends.utils import load_backends
load_backends(settings.AUTHENTICATION_BACKENDS, force_load=True) 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, def register_extra_endpoints(self, requests_mock: responses.RequestsMock,
account_data_dict: Dict[str, str], account_data_dict: Dict[str, str],
**extra_data: Any) -> None: **extra_data: Any) -> None:
@@ -887,14 +891,13 @@ class SocialAuthBase(DesktopFlowTestingLib, ZulipTestCase):
# We expect to go through the "choose email" screen here, # We expect to go through the "choose email" screen here,
# because there won't be an existing user account we can # because there won't be an existing user account we can
# auto-select for the user. # 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, result = self.social_auth_test(account_data_dict,
expect_choose_email_screen=True, expect_choose_email_screen=True,
subdomain='zulip') subdomain='zulip')
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertEqual(result.url, "/login/?is_deactivated=true") self.assertEqual(result.url, "/login/?is_deactivated=true")
m.assert_called_with("Failed login attempt for deactivated account: %s@%s", self.assertEqual(m.output, [self.logger_output(f"Failed login attempt for deactivated account: {user_profile.id}@zulip", 'info')])
user_profile.id, 'zulip')
# TODO: verify whether we provide a clear error message # TODO: verify whether we provide a clear error message
def test_social_auth_invalid_realm(self) -> None: 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: def test_social_auth_complete_when_base_exc_is_raised(self) -> None:
with mock.patch('social_core.backends.oauth.BaseOAuth2.auth_complete', with mock.patch('social_core.backends.oauth.BaseOAuth2.auth_complete',
side_effect=AuthStateForbidden('State forbidden')), \ 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])) result = self.client_get(reverse('social:complete', args=[self.backend.name]))
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertIn('login', result.url) self.assertIn('login', result.url)
@@ -1509,7 +1512,7 @@ class SAMLAuthBackendTest(SocialAuthBase):
def test_social_auth_complete(self) -> None: 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_Response, 'is_valid', return_value=True):
with mock.patch.object(OneLogin_Saml2_Auth, 'is_authenticated', return_value=False), \ 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. # This mock causes AuthFailed to be raised.
saml_response = self.generate_saml_response(self.email, self.name) saml_response = self.generate_saml_response(self.email, self.name)
relay_state = ujson.dumps(dict( relay_state = ujson.dumps(dict(
@@ -1519,13 +1522,14 @@ class SAMLAuthBackendTest(SocialAuthBase):
result = self.client_post('/complete/saml/', post_params) result = self.client_post('/complete/saml/', post_params)
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertIn('login', result.url) 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: 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.object(OneLogin_Saml2_Response, 'is_valid', return_value=True):
with mock.patch('social_core.backends.saml.SAMLAuth.auth_complete', with mock.patch('social_core.backends.saml.SAMLAuth.auth_complete',
side_effect=AuthStateForbidden('State forbidden')), \ 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) saml_response = self.generate_saml_response(self.email, self.name)
relay_state = ujson.dumps(dict( relay_state = ujson.dumps(dict(
state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"}) state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"})
@@ -1534,21 +1538,21 @@ class SAMLAuthBackendTest(SocialAuthBase):
result = self.client_post('/complete/saml/', post_params) result = self.client_post('/complete/saml/', post_params)
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertIn('login', result.url) 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: def test_social_auth_complete_bad_params(self) -> None:
# Simple GET for /complete/saml without the required parameters. # Simple GET for /complete/saml without the required parameters.
# This tests the auth_complete wrapped in our SAMLAuthBackend, # This tests the auth_complete wrapped in our SAMLAuthBackend,
# ensuring it prevents this requests from causing an internal server error. # 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/') result = self.client_get('/complete/saml/')
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertIn('login', result.url) 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, # Check that POSTing the RelayState, but with missing SAMLResponse,
# doesn't cause errors either: # 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( relay_state = ujson.dumps(dict(
state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"}) state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"})
)) ))
@@ -1556,10 +1560,10 @@ class SAMLAuthBackendTest(SocialAuthBase):
result = self.client_post('/complete/saml/', post_params) result = self.client_post('/complete/saml/', post_params)
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertIn('login', result.url) 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. # 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( relay_state = ujson.dumps(dict(
state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"}) state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"})
)) ))
@@ -1567,9 +1571,9 @@ class SAMLAuthBackendTest(SocialAuthBase):
result = self.client_post('/complete/saml/', post_params) result = self.client_post('/complete/saml/', post_params)
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertIn('login', result.url) 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( relay_state = ujson.dumps(dict(
state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"}) state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"})
)) ))
@@ -1577,9 +1581,9 @@ class SAMLAuthBackendTest(SocialAuthBase):
result = self.client_post('/complete/saml/', post_params) result = self.client_post('/complete/saml/', post_params)
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertIn('login', result.url) 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( relay_state = ujson.dumps(dict(
state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"}) state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"})
)) ))
@@ -1587,10 +1591,10 @@ class SAMLAuthBackendTest(SocialAuthBase):
result = self.client_post('/complete/saml/', post_params) result = self.client_post('/complete/saml/', post_params)
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertIn('login', result.url) self.assertIn('login', result.url)
m.assert_called() self.assertTrue(m.output != '')
def test_social_auth_complete_no_subdomain(self) -> None: 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": '', post_params = {"RelayState": '',
'SAMLResponse': self.generate_saml_response(email=self.example_email("hamlet"), 'SAMLResponse': self.generate_saml_response(email=self.example_email("hamlet"),
name="King Hamlet")} name="King Hamlet")}
@@ -1598,10 +1602,10 @@ class SAMLAuthBackendTest(SocialAuthBase):
result = self.client_post('/complete/saml/', post_params) result = self.client_post('/complete/saml/', post_params)
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertEqual('/login/', result.url) self.assertEqual('/login/', result.url)
m.assert_called_once_with( self.assertEqual(m.output, [self.logger_output(
"/complete/saml/: Can't figure out subdomain for this authentication request. relayed_params: %s", "/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: def test_social_auth_complete_wrong_issuing_idp(self) -> None:
relay_state = ujson.dumps(dict( relay_state = ujson.dumps(dict(
@@ -1615,15 +1619,13 @@ class SAMLAuthBackendTest(SocialAuthBase):
idps_dict = copy.deepcopy(settings.SOCIAL_AUTH_SAML_ENABLED_IDPS) idps_dict = copy.deepcopy(settings.SOCIAL_AUTH_SAML_ENABLED_IDPS)
idps_dict['test_idp']['entity_id'] = 'https://different.idp.example.com/' idps_dict['test_idp']['entity_id'] = 'https://different.idp.example.com/'
with self.settings(SOCIAL_AUTH_SAML_ENABLED_IDPS=idps_dict): 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, post_params = {"RelayState": relay_state,
"SAMLResponse": saml_response} "SAMLResponse": saml_response}
result = self.client_post('/complete/saml/', post_params) result = self.client_post('/complete/saml/', post_params)
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertEqual('/login/', result.url) self.assertEqual('/login/', result.url)
m.assert_called_once_with( self.assertEqual(m.output, [self.logger_output("/complete/saml/: No valid IdP as issuer of the SAMLResponse.", "info")])
"/complete/saml/: No valid IdP as issuer of the SAMLResponse.",
)
def test_social_auth_complete_valid_get_idp_bad_samlresponse(self) -> None: def test_social_auth_complete_valid_get_idp_bad_samlresponse(self) -> None:
""" """
@@ -1632,7 +1634,7 @@ class SAMLAuthBackendTest(SocialAuthBase):
validation in the underlying libraries. 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'): mock.patch.object(SAMLAuthBackend, 'get_issuing_idp', return_value='test_idp'):
relay_state = ujson.dumps(dict( relay_state = ujson.dumps(dict(
state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"}) state_token=SAMLAuthBackend.put_data_in_redis({"subdomain": "zulip"})
@@ -1642,20 +1644,20 @@ class SAMLAuthBackendTest(SocialAuthBase):
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertIn('login', result.url) 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: 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/') result = self.client_get('/login/saml/')
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertEqual('/login/', result.url) 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') result = self.client_get('/login/saml/?idp=bad_idp')
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertEqual('/login/', result.url) 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: def test_social_auth_invalid_email(self) -> None:
""" """
@@ -1725,15 +1727,14 @@ class SAMLAuthBackendTest(SocialAuthBase):
idps_dict['test_idp']['limit_to_subdomains'] = ['zulip', ] idps_dict['test_idp']['limit_to_subdomains'] = ['zulip', ]
with self.settings(SOCIAL_AUTH_SAML_ENABLED_IDPS=idps_dict): with self.settings(SOCIAL_AUTH_SAML_ENABLED_IDPS=idps_dict):
account_data_dict = self.get_account_data_dict(email=self.email, name=self.name) 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') result = self.social_auth_test(account_data_dict, subdomain='zephyr')
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertEqual('/login/', result.url) self.assertEqual('/login/', result.url)
m.assert_called_with( self.assertEqual(m.output, [self.logger_output(
'/complete/saml/: Authentication request with IdP %s but this provider is not enabled ' + '/complete/saml/: Authentication request with IdP %s but this provider is not enabled '
'for this subdomain %s.', 'for this subdomain %s.' % ("test_idp", "zephyr"), 'info'
"test_idp", "zephyr", )])
)
def test_social_auth_saml_login_bad_idp_arg(self) -> None: def test_social_auth_saml_login_bad_idp_arg(self) -> None:
for action in ['login', 'register']: for action in ['login', 'register']:
@@ -1760,17 +1761,18 @@ class SAMLAuthBackendTest(SocialAuthBase):
with self.settings(SOCIAL_AUTH_SAML_ENABLED_IDPS=idps_dict, with self.settings(SOCIAL_AUTH_SAML_ENABLED_IDPS=idps_dict,
SAML_REQUIRE_LIMIT_TO_SUBDOMAINS=True): 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 # Initialization of the backend should validate the configured IdPs
# with respect to the SAML_REQUIRE_LIMIT_TO_SUBDOMAINS setting and remove # with respect to the SAML_REQUIRE_LIMIT_TO_SUBDOMAINS setting and remove
# the non-compliant ones. # the non-compliant ones.
SAMLAuthBackend() SAMLAuthBackend()
self.assertEqual(list(settings.SOCIAL_AUTH_SAML_ENABLED_IDPS.keys()), self.assertEqual(list(settings.SOCIAL_AUTH_SAML_ENABLED_IDPS.keys()),
['test_idp2', ]) ['test_idp2', ])
mock_error.assert_called_with( self.assertEqual(m.output, [self.logger_output(
"SAML_REQUIRE_LIMIT_TO_SUBDOMAINS is enabled and the following " + "SAML_REQUIRE_LIMIT_TO_SUBDOMAINS is enabled and the following "
"IdPs don't have limit_to_subdomains specified and will be ignored: " + "IdPs don't have limit_to_subdomains specified and will be ignored: "
"['test_idp']") "['test_idp']", 'error'
)])
def test_idp_initiated_signin_subdomain_specified(self) -> None: def test_idp_initiated_signin_subdomain_specified(self) -> None:
post_params = { post_params = {
@@ -1859,7 +1861,7 @@ class SAMLAuthBackendTest(SocialAuthBase):
"SAMLResponse": self.generate_saml_response(email=self.email, name=self.name) "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'): 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` # 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. # 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(result.status_code, 302)
self.assertEqual('/login/', result.url) self.assertEqual('/login/', result.url)
m.assert_called_once_with( self.assertEqual(m.output, [self.logger_output(
"/complete/saml/: Can't figure out subdomain for this authentication request. relayed_params: %s", "/complete/saml/: Can't figure out subdomain for this authentication request. relayed_params: %s" % {},
{}, "info"
) )])
class GitHubAuthBackendTest(SocialAuthBase): class GitHubAuthBackendTest(SocialAuthBase):
__unittest_skip__ = False __unittest_skip__ = False
@@ -1974,28 +1976,30 @@ class GitHubAuthBackendTest(SocialAuthBase):
verified=False, verified=False,
primary=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, result = self.social_auth_test(account_data_dict,
subdomain='zulip', subdomain='zulip',
email_data=email_data) email_data=email_data)
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertEqual(result.url, "/login/") self.assertEqual(result.url, "/login/")
mock_warning.assert_called_once_with( self.assertEqual(m.output, [self.logger_output(
"Social auth (%s) failed because user has no verified emails", "Social auth (%s) failed because user has no verified emails" % ('GitHub',),
"GitHub", "warning"
) )])
@override_settings(SOCIAL_AUTH_GITHUB_TEAM_ID='zulip-webapp') @override_settings(SOCIAL_AUTH_GITHUB_TEAM_ID='zulip-webapp')
def test_social_auth_github_team_not_member_failed(self) -> None: 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) account_data_dict = self.get_account_data_dict(email=self.email, name=self.name)
with mock.patch('social_core.backends.github.GithubTeamOAuth2.user_data', with mock.patch('social_core.backends.github.GithubTeamOAuth2.user_data',
side_effect=AuthFailed('Not found')), \ 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, result = self.social_auth_test(account_data_dict,
subdomain='zulip') subdomain='zulip')
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertEqual(result.url, "/login/") 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') @override_settings(SOCIAL_AUTH_GITHUB_TEAM_ID='zulip-webapp')
def test_social_auth_github_team_member_success(self) -> None: 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) account_data_dict = self.get_account_data_dict(email=self.email, name=self.name)
with mock.patch('social_core.backends.github.GithubOrganizationOAuth2.user_data', with mock.patch('social_core.backends.github.GithubOrganizationOAuth2.user_data',
side_effect=AuthFailed('Not found')), \ 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, result = self.social_auth_test(account_data_dict,
subdomain='zulip') subdomain='zulip')
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertEqual(result.url, "/login/") 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') @override_settings(SOCIAL_AUTH_GITHUB_ORG_NAME='Zulip')
def test_social_auth_github_organization_member_success(self) -> None: def test_social_auth_github_organization_member_success(self) -> None:
@@ -2252,18 +2258,18 @@ class GitHubAuthBackendTest(SocialAuthBase):
dict(email=account_data_dict["email"], dict(email=account_data_dict["email"],
verified=True), 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, result = self.social_auth_test(account_data_dict,
subdomain='zulip', subdomain='zulip',
expect_choose_email_screen=True, expect_choose_email_screen=True,
email_data=email_data) email_data=email_data)
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertEqual(result.url, "/login/") self.assertEqual(result.url, "/login/")
mock_warning.assert_called_once_with( self.assertEqual(m.output, [self.logger_output(
"Social auth (%s) failed because user has no verified" "Social auth (%s) failed because user has no verified"
" emails associated with the account", " emails associated with the account" % ("GitHub",),
"GitHub", "warning"
) )])
def test_github_oauth2_email_not_associated(self) -> None: def test_github_oauth2_email_not_associated(self) -> None:
account_data_dict = dict(email='not-associated@zulip.com', name=self.name) account_data_dict = dict(email='not-associated@zulip.com', name=self.name)
@@ -2276,18 +2282,18 @@ class GitHubAuthBackendTest(SocialAuthBase):
dict(email="aaron@zulip.com", dict(email="aaron@zulip.com",
verified=True), 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, result = self.social_auth_test(account_data_dict,
subdomain='zulip', subdomain='zulip',
expect_choose_email_screen=True, expect_choose_email_screen=True,
email_data=email_data) email_data=email_data)
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertEqual(result.url, "/login/") self.assertEqual(result.url, "/login/")
mock_warning.assert_called_once_with( self.assertEqual(m.output, [self.logger_output(
"Social auth (%s) failed because user has no verified" "Social auth (%s) failed because user has no verified"
" emails associated with the account", " emails associated with the account" % ("GitHub",),
"GitHub", "warning"
) )])
def test_github_unverified_email_with_existing_account(self) -> None: def test_github_unverified_email_with_existing_account(self) -> None:
# check if a user is denied to login if the user manages to # check if a user is denied to login if the user manages to
@@ -2303,15 +2309,17 @@ class GitHubAuthBackendTest(SocialAuthBase):
verified=True, verified=True,
primary=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, result = self.social_auth_test(account_data_dict,
subdomain='zulip', subdomain='zulip',
expect_choose_email_screen=True, expect_choose_email_screen=True,
email_data=email_data) email_data=email_data)
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertEqual(result.url, "/login/") self.assertEqual(result.url, "/login/")
mock_warning.assert_called_once_with("Social auth (%s) failed because user has no verified" self.assertEqual(m.output, [self.logger_output(
" emails associated with the account", "GitHub") "Social auth (%s) failed because user has no verified emails associated with the account" % ("GitHub",),
"warning"
)])
class GitLabAuthBackendTest(SocialAuthBase): class GitLabAuthBackendTest(SocialAuthBase):
__unittest_skip__ = False __unittest_skip__ = False
@@ -2353,15 +2361,15 @@ class GoogleAuthBackendTest(SocialAuthBase):
def test_social_auth_email_not_verified(self) -> None: def test_social_auth_email_not_verified(self) -> None:
account_data_dict = dict(email=self.email, name=self.name) 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, result = self.social_auth_test(account_data_dict,
subdomain='zulip') subdomain='zulip')
self.assertEqual(result.status_code, 302) self.assertEqual(result.status_code, 302)
self.assertEqual(result.url, "/login/") self.assertEqual(result.url, "/login/")
mock_warning.assert_called_once_with( self.assertEqual(m.output, [self.logger_output(
"Social auth (%s) failed because user has no verified emails", "Social auth (%s) failed because user has no verified emails" % ("Google",),
"Google", "warning"
) )])
def test_social_auth_mobile_success_legacy_url(self) -> None: def test_social_auth_mobile_success_legacy_url(self) -> None:
mobile_flow_otp = '1234abcd' * 8 mobile_flow_otp = '1234abcd' * 8

51
zproject/backends.py
View File

@@ -244,6 +244,14 @@ class ZulipAuthMixin:
from memcached before checking the database (avoiding a database from memcached before checking the database (avoiding a database
query in most cases). 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]: def get_user(self, user_profile_id: int) -> Optional[UserProfile]:
"""Override the Django method for getting a UserProfile object from """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: if verified_emails_length == 0:
# TODO: Provide a nice error message screen to the user # TODO: Provide a nice error message screen to the user
# for this case, rather than just logging a warning. # for this case, rather than just logging a warning.
logging.warning("Social auth (%s) failed because user has no verified emails", backend.logger.warning("Social auth (%s) failed because user has no verified emails",
backend.auth_backend_name) backend.auth_backend_name)
return_data["email_not_verified"] = True return_data["email_not_verified"] = True
return None 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 # 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 # end up with a wrong email associated with the account. The below code
# takes care of that. # takes care of that.
logging.warning("Social auth (%s) failed because user has no verified" backend.logger.warning("Social auth (%s) failed because user has no verified"
" emails associated with the account", " emails associated with the account",
backend.auth_backend_name) backend.auth_backend_name)
return_data["email_not_associated"] = True return_data["email_not_associated"] = True
return None return None
@@ -1230,8 +1238,8 @@ def social_auth_finish(backend: Any,
return HttpResponseRedirect(reverse('zerver.views.registration.find_account')) return HttpResponseRedirect(reverse('zerver.views.registration.find_account'))
if inactive_user: if inactive_user:
logging.info("Failed login attempt for deactivated account: %s@%s", backend.logger.info("Failed login attempt for deactivated account: %s@%s",
return_data['inactive_user_id'], return_data['realm_string_id']) return_data['inactive_user_id'], return_data['realm_string_id'])
return redirect_deactivated_user_to_login() return redirect_deactivated_user_to_login()
if auth_backend_disabled or inactive_realm or no_verified_email or email_not_associated: 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: if invalid_email:
# In case of invalid email, we will end up on registration page. # In case of invalid email, we will end up on registration page.
# This seems better than redirecting to login page. # This seems better than redirecting to login page.
logging.warning( backend.logger.warning(
"%s got invalid email argument.", backend.auth_backend_name, "%s got invalid email argument.", backend.auth_backend_name,
) )
return None return None
if auth_failed_reason: if auth_failed_reason:
logging.info(auth_failed_reason) backend.logger.info(auth_failed_reason)
return None return None
# Structurally, all the cases where we don't have an authenticated # 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), # the flow or the IdP is unreliable and returns a bad http response),
# don't throw a 500, just send them back to the # don't throw a 500, just send them back to the
# login page and record the event at the info log level. # login page and record the event at the info log level.
logging.info(str(e)) self.logger.info(str(e))
return None return None
except SocialAuthBaseException as e: except SocialAuthBaseException as e:
# Other python-social-auth exceptions are likely # Other python-social-auth exceptions are likely
# interesting enough that we should log a warning. # interesting enough that we should log a warning.
logging.warning(str(e)) self.logger.warning(str(e))
return None return None
@classmethod @classmethod
@@ -1512,9 +1520,9 @@ class SAMLAuthBackend(SocialAuthMixin, SAMLAuth):
if 'limit_to_subdomains' not in idp_dict if 'limit_to_subdomains' not in idp_dict
] ]
if idps_without_limit_to_subdomains: if idps_without_limit_to_subdomains:
logging.error("SAML_REQUIRE_LIMIT_TO_SUBDOMAINS is enabled and the following " + 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: " + "IdPs don't have limit_to_subdomains specified and will be ignored: " +
"%s" % (idps_without_limit_to_subdomains,)) "%s" % (idps_without_limit_to_subdomains,))
for idp_name in idps_without_limit_to_subdomains: for idp_name in idps_without_limit_to_subdomains:
del settings.SOCIAL_AUTH_SAML_ENABLED_IDPS[idp_name] del settings.SOCIAL_AUTH_SAML_ENABLED_IDPS[idp_name]
super().__init__(*args, **kwargs) super().__init__(*args, **kwargs)
@@ -1529,7 +1537,7 @@ class SAMLAuthBackend(SocialAuthMixin, SAMLAuth):
except KeyError as e: except KeyError as e:
# If the above raise KeyError, it means invalid or no idp was specified, # If the above raise KeyError, it means invalid or no idp was specified,
# we should log that and redirect to the login page. # 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', return reverse('zerver.views.auth.login_page',
kwargs = {'template_name': 'zerver/login.html'}) kwargs = {'template_name': 'zerver/login.html'})
@@ -1583,7 +1591,8 @@ class SAMLAuthBackend(SocialAuthMixin, SAMLAuth):
resp = OneLogin_Saml2_Response(settings={}, response=SAMLResponse) resp = OneLogin_Saml2_Response(settings={}, response=SAMLResponse)
issuers = resp.get_issuers() issuers = resp.get_issuers()
except cls.SAMLRESPONSE_PARSING_EXCEPTIONS as e: 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 return None
for idp_name, idp_config in settings.SOCIAL_AUTH_SAML_ENABLED_IDPS.items(): 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') SAMLResponse = self.strategy.request_data().get('SAMLResponse')
if SAMLResponse is None: if SAMLResponse is None:
logging.info("/complete/saml/: No SAMLResponse in request.") self.logger.info("/complete/saml/: No SAMLResponse in request.")
return None return None
relayed_params = self.get_relayed_params() relayed_params = self.get_relayed_params()
@@ -1657,19 +1666,19 @@ class SAMLAuthBackend(SocialAuthMixin, SAMLAuth):
if subdomain is None: if subdomain is None:
error_msg = "/complete/saml/: Can't figure out subdomain for this authentication request. " + \ error_msg = "/complete/saml/: Can't figure out subdomain for this authentication request. " + \
"relayed_params: %s" "relayed_params: %s"
logging.info(error_msg, relayed_params) self.logger.info(error_msg, relayed_params)
return None return None
idp_name = self.get_issuing_idp(SAMLResponse) idp_name = self.get_issuing_idp(SAMLResponse)
if idp_name is None: 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 return None
idp_valid = self.validate_idp_for_subdomain(idp_name, subdomain) idp_valid = self.validate_idp_for_subdomain(idp_name, subdomain)
if not idp_valid: if not idp_valid:
error_msg = "/complete/saml/: Authentication request with IdP %s but this provider is not " + \ error_msg = "/complete/saml/: Authentication request with IdP %s but this provider is not " + \
"enabled for this subdomain %s." "enabled for this subdomain %s."
logging.info(error_msg, idp_name, subdomain) self.logger.info(error_msg, idp_name, subdomain)
return None return None
result = None result = None
@@ -1690,7 +1699,7 @@ class SAMLAuthBackend(SocialAuthMixin, SAMLAuth):
result = super().auth_complete(*args, **kwargs) result = super().auth_complete(*args, **kwargs)
except self.SAMLRESPONSE_PARSING_EXCEPTIONS as e: except self.SAMLRESPONSE_PARSING_EXCEPTIONS as e:
# These can be raised if SAMLResponse is missing or badly formatted. # 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. # Fall through to returning None.
finally: finally:
if result is None: if result is None:

11
zproject/settings.py
View File

@@ -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") TRACEMALLOC_DUMP_DIR = zulip_path("/var/log/zulip/tracemalloc")
SCHEDULED_MESSAGE_DELIVERER_LOG_PATH = zulip_path("/var/log/zulip/scheduled_message_deliverer.log") 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") 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 # The EVENT_LOGS feature is an ultra-legacy piece of code, which
# originally logged all significant database changes for debugging. # originally logged all significant database changes for debugging.
@@ -753,6 +754,12 @@ LOGGING: Dict[str, Any] = {
if not DEBUG_ERROR_REPORTING else []), if not DEBUG_ERROR_REPORTING else []),
'formatter': 'default' 'formatter': 'default'
}, },
'auth_file': {
'level': 'DEBUG',
'class': 'logging.handlers.WatchedFileHandler',
'formatter': 'default',
'filename': AUTH_LOG_PATH,
},
'console': { 'console': {
'level': 'DEBUG', 'level': 'DEBUG',
'class': 'logging.StreamHandler', 'class': 'logging.StreamHandler',
@@ -890,6 +897,10 @@ LOGGING: Dict[str, Any] = {
'zerver.management.commands.deliver_scheduled_messages': { 'zerver.management.commands.deliver_scheduled_messages': {
'level': 'DEBUG', 'level': 'DEBUG',
}, },
'zulip.auth': {
'level': 'DEBUG',
'handlers': DEFAULT_ZULIP_HANDLERS + ['auth_file']
},
'zulip.ldap': { 'zulip.ldap': {
'level': 'DEBUG', 'level': 'DEBUG',
'handlers': ['console', 'ldap_file', 'errors_file'], 'handlers': ['console', 'ldap_file', 'errors_file'],