From df1c7f553ab821ebc65e8b744d174c688159f0f5 Mon Sep 17 00:00:00 2001 From: irfanuddinahmad Date: Thu, 25 Jul 2019 14:27:30 +0500 Subject: [PATCH] reformatted logging --- .../djangoapps/third_party_auth/pipeline.py | 32 ++++++++++++------- common/djangoapps/third_party_auth/saml.py | 25 +++++++++------ .../third_party_auth/tests/test_saml.py | 4 +-- 3 files changed, 38 insertions(+), 23 deletions(-) diff --git a/common/djangoapps/third_party_auth/pipeline.py b/common/djangoapps/third_party_auth/pipeline.py index 4a06c9b2cb..18a1967b03 100644 --- a/common/djangoapps/third_party_auth/pipeline.py +++ b/common/djangoapps/third_party_auth/pipeline.py @@ -554,6 +554,7 @@ def ensure_user_information(strategy, auth_entry, backend=None, user=None, socia (current_provider.skip_email_verification or current_provider.send_to_registration_first)) def is_provider_saml(): + """ Verify that the third party provider uses SAML """ current_provider = provider.Registry.get_from_pipeline({'backend': current_partial.backend, 'kwargs': kwargs}) saml_providers_list = list(provider.Registry.get_enabled_by_backend_name('tpa-saml')) return (current_provider and @@ -614,8 +615,8 @@ def ensure_user_information(strategy, auth_entry, backend=None, user=None, socia # register anew via SSO. See SOL-1324 in JIRA. # However, we will log a warning for this case: logger.warning( - u'User "%s" is using third_party_auth to login but has not yet activated their account. ', - user.username + u'[THIRD_PARTY_AUTH] User is using third_party_auth to login but has not yet activated their account. ' + u'Username: {username}'.format(username=user.username) ) @@ -751,17 +752,25 @@ def user_details_force_sync(auth_entry, strategy, details, user=None, *args, **k current_value = getattr(model, field) if provider_value is not None and current_value != provider_value: if field in integrity_conflict_fields and User.objects.filter(**{field: provider_value}).exists(): - logger.warning(u'User with ID [%s] tried to synchronize profile data through [%s] ' - u'but there was a conflict with an existing [%s]: [%s].', - user.id, current_provider.name, field, provider_value) + logger.warning(u'[THIRD_PARTY_AUTH] Profile data synchronization conflict. ' + u'UserId: {user_id}, Provider: {provider}, ConflictField: {conflict_field}, ' + u'ConflictValue: {conflict_value}'.format( + user_id=user.id, + provider=current_provider.name, + conflict_field=field, + conflict_value=provider_value)) continue changed[provider_field] = current_value setattr(model, field, provider_value) if changed: logger.info( - u"User [%s] performed SSO through [%s] who synchronizes profile data, and the " - u"following fields were changed: %s", user.username, current_provider.name, list(changed.keys()), + u'[THIRD_PARTY_AUTH] User performed SSO and data was synchronized. ' + u'Username: {username}, Provider: {provider}, UpdatedKeys: {updated_keys}'.format( + username=user.username, + provider=current_provider.name, + updated_keys=list(changed.keys()) + ) ) # Save changes to user and user.profile models. @@ -786,8 +795,8 @@ def user_details_force_sync(auth_entry, strategy, details, user=None, *args, **k try: email.send() except SMTPException: - logger.exception('Error sending IdP learner data sync-initiated email change ' - u'notification email for user [%s].', user.username) + logger.exception('[THIRD_PARTY_AUTH] Error sending IdP learner data sync-initiated email change ' + u'notification email. Username {username}'.format(username=user.username)) def set_id_verification_status(auth_entry, strategy, details, user=None, *args, **kwargs): @@ -867,11 +876,10 @@ def get_username(strategy, details, backend, user=None, *args, **kwargs): # The final_username may be empty and will skip the loop. # We are using our own version of user_exists to avoid possible case sensitivity issues. while not final_username or user_exists({'username': final_username}): - # These log statements are here for debugging purposes and should be removed when ENT-1500 is resolved. - logger.info(u'Username %s is either empty or already in use, generating a new username!', final_username) username = short_username + uuid4().hex[:uuid_length] final_username = slug_func(clean_func(username[:max_length])) - logger.info(u'Generated username %s.', final_username) + logger.info(u'[THIRD_PARTY_AUTH] New username generated. Username {username}'.format( + username=final_username)) else: final_username = storage.user.get_username(user) return {'username': final_username} diff --git a/common/djangoapps/third_party_auth/saml.py b/common/djangoapps/third_party_auth/saml.py index 8fe3194559..6cb31ab42e 100644 --- a/common/djangoapps/third_party_auth/saml.py +++ b/common/djangoapps/third_party_auth/saml.py @@ -94,7 +94,8 @@ class SAMLAuthBackend(SAMLAuth): # pylint: disable=abstract-method return super(SAMLAuthBackend, self).get_user_id(details, response) except KeyError as ex: log.warning( - u"Error in SAML authentication flow of IdP '{idp_name}': {message}".format( + u'[THIRD_PARTY_AUTH] Error in SAML authentication flow. ' + u'Provider: {idp_name}, Message: {message}'.format( message=ex.message, idp_name=response.get('idp_name') ) @@ -124,7 +125,7 @@ class SAMLAuthBackend(SAMLAuth): # pylint: disable=abstract-method raise Http404 if SAML authentication is disabled. """ if not self._config.enabled: - log.error('SAML authentication is not enabled') + log.error('[THIRD_PARTY_AUTH] SAML authentication is not enabled') raise Http404 return super(SAMLAuthBackend, self).auth_url() @@ -169,7 +170,11 @@ class SAMLAuthBackend(SAMLAuth): # pylint: disable=abstract-method for expected in idp.conf['requiredEntitlements']: if expected not in entitlements: log.warning( - u"SAML user from IdP %s rejected due to missing eduPersonEntitlement %s", idp.name, expected) + u'[THIRD_PARTY_AUTH] SAML user rejected due to missing eduPersonEntitlement. ' + u'Provider: {provider}, Entitlement: {entitlement}'.format( + provider=idp.name, + entitlement=expected) + ) raise AuthForbidden(self) def _create_saml_auth(self, idp): @@ -237,7 +242,8 @@ class EdXSAMLIdentityProvider(SAMLIdentityProvider): try: return attributes[key][0] except IndexError: - log.warning(u'SAML attribute "%s" value not found.', key) + log.warning(u'[THIRD_PARTY_AUTH] SAML attribute value not found. ' + u'SamlAttribute: {attribute}'.format(attribute=key)) return self.conf['attr_defaults'].get(conf_key) or None @property @@ -381,9 +387,10 @@ class SapSuccessFactorsIdentityProvider(EdXSAMLIdentityProvider): if not all(var in self.conf for var in self.required_variables): missing = [var for var in self.required_variables if var not in self.conf] log.warning( - u"To retrieve rich user data for an SAP SuccessFactors identity provider, the following keys in " - u"'other_settings' are required, but were missing: %s", - missing + u'[THIRD_PARTY_AUTH] To retrieve rich user data for a SAP SuccessFactors identity provider, ' + u'the following keys in other_settings are required, but were missing. MissingKeys: {keys}'.format( + keys=missing + ) ) return missing @@ -562,7 +569,7 @@ def get_saml_idp_class(idp_identifier_string): } if idp_identifier_string not in choices: log.error( - u'%s is not a valid EdXSAMLIdentityProvider subclass; using EdXSAMLIdentityProvider base class.', - idp_identifier_string + u'[THIRD_PARTY_AUTH] Invalid EdXSAMLIdentityProvider subclass--' + u'using EdXSAMLIdentityProvider base class. Provider: {provider}'.format(provider=idp_identifier_string) ) return choices.get(idp_identifier_string, EdXSAMLIdentityProvider) diff --git a/common/djangoapps/third_party_auth/tests/test_saml.py b/common/djangoapps/third_party_auth/tests/test_saml.py index c956f8fa20..69fc7ad587 100644 --- a/common/djangoapps/third_party_auth/tests/test_saml.py +++ b/common/djangoapps/third_party_auth/tests/test_saml.py @@ -24,8 +24,8 @@ class TestEdXSAMLIdentityProvider(SAMLTestCase): error_mock = log_mock.error idp_class = get_saml_idp_class('fake_idp_class_option') error_mock.assert_called_once_with( - u'%s is not a valid EdXSAMLIdentityProvider subclass; using EdXSAMLIdentityProvider base class.', - 'fake_idp_class_option' + u'[THIRD_PARTY_AUTH] Invalid EdXSAMLIdentityProvider subclass--' + u'using EdXSAMLIdentityProvider base class. Provider: {provider}'.format(provider='fake_idp_class_option') ) self.assertIs(idp_class, EdXSAMLIdentityProvider)