From fe3ebca1c550638879b81c51e907974887010dbe Mon Sep 17 00:00:00 2001 From: Chris Dodge Date: Fri, 21 Feb 2014 00:46:07 -0500 Subject: [PATCH] add new feature to make sure we aren't writing PII into the application logs. So far we're aware of doing so regarding Auth use-cases --- cms/envs/common.py | 3 + .../external_auth/tests/test_shib.py | 14 ++--- common/djangoapps/external_auth/views.py | 53 ++++++++++++---- common/djangoapps/student/models.py | 10 +++- common/djangoapps/student/tests/test_login.py | 60 +++++++++++++++++++ common/djangoapps/student/views.py | 16 ++++- lms/envs/common.py | 3 + 7 files changed, 134 insertions(+), 25 deletions(-) diff --git a/cms/envs/common.py b/cms/envs/common.py index 23b7de10a5..bfaf404815 100644 --- a/cms/envs/common.py +++ b/cms/envs/common.py @@ -76,6 +76,9 @@ FEATURES = { # Allow editing of short description in course settings in cms 'EDITABLE_SHORT_DESCRIPTION': True, + + # Hide any Personally Identifiable Information from application logs + 'SQUELCH_PII_IN_LOGS': False, } ENABLE_JASMINE = False diff --git a/common/djangoapps/external_auth/tests/test_shib.py b/common/djangoapps/external_auth/tests/test_shib.py index 01ef206cc9..c8f38563de 100644 --- a/common/djangoapps/external_auth/tests/test_shib.py +++ b/common/djangoapps/external_auth/tests/test_shib.py @@ -103,9 +103,9 @@ class ShibSPTest(ModuleStoreTestCase): """Asserts that shibboleth login attempt is being logged""" method_name, args, _kwargs = audit_log_call self.assertEquals(method_name, 'info') - self.assertEquals(len(args), 2) + self.assertEquals(len(args), 1) self.assertIn(u'logged in via Shibboleth', args[0]) - self.assertEquals(remote_user, args[1]) + self.assertIn(remote_user, args[0]) @unittest.skipUnless(settings.FEATURES.get('AUTH_USE_SHIB'), "AUTH_USE_SHIB not set") def test_shib_login(self): @@ -166,9 +166,9 @@ class ShibSPTest(ModuleStoreTestCase): self._assert_shib_login_is_logged(audit_log_calls[0], remote_user) method_name, args, _kwargs = audit_log_calls[1] self.assertEquals(method_name, 'info') - self.assertEquals(len(args), 3) + self.assertEquals(len(args), 1) self.assertIn(u'Login success', args[0]) - self.assertEquals(remote_user, args[2]) + self.assertIn(remote_user, args[0]) elif idp == "https://idp.stanford.edu/" and remote_user == 'inactive@stanford.edu': self.assertEqual(response.status_code, 403) self.assertIn("Account not yet activated: please look for link in your email", response.content) @@ -177,7 +177,7 @@ class ShibSPTest(ModuleStoreTestCase): self._assert_shib_login_is_logged(audit_log_calls[0], remote_user) method_name, args, _kwargs = audit_log_calls[1] self.assertEquals(method_name, 'warning') - self.assertEquals(len(args), 2) + self.assertEquals(len(args), 1) self.assertIn(u'is not active after external login', args[0]) # self.assertEquals(remote_user, args[1]) elif idp == "https://idp.stanford.edu/" and remote_user == 'womap@stanford.edu': @@ -190,9 +190,9 @@ class ShibSPTest(ModuleStoreTestCase): self._assert_shib_login_is_logged(audit_log_calls[0], remote_user) method_name, args, _kwargs = audit_log_calls[1] self.assertEquals(method_name, 'info') - self.assertEquals(len(args), 3) + self.assertEquals(len(args), 1) self.assertIn(u'Login success', args[0]) - self.assertEquals(remote_user, args[2]) + self.assertIn(remote_user, args[0]) elif idp == "https://someother.idp.com/" and remote_user in \ ['withmap@stanford.edu', 'womap@stanford.edu', 'inactive@stanford.edu']: self.assertEqual(response.status_code, 403) diff --git a/common/djangoapps/external_auth/views.py b/common/djangoapps/external_auth/views.py index 76455b8f89..0f3baf7b92 100644 --- a/common/djangoapps/external_auth/views.py +++ b/common/djangoapps/external_auth/views.py @@ -193,21 +193,33 @@ def _external_login_or_signup(request, else: auth_backend = 'django.contrib.auth.backends.ModelBackend' user.backend = auth_backend - AUDIT_LOG.info('Linked user "%s" logged in via Shibboleth', user.email) + if settings.FEATURES['SQUELCH_PII_IN_LOGS']: + AUDIT_LOG.info('Linked user.id: {0} logged in via Shibboleth'.format(user.id)) + else: + AUDIT_LOG.info('Linked user "{0}" logged in via Shibboleth'.format(user.email)) elif uses_certs: # Certificates are trusted, so just link the user and log the action user = internal_user user.backend = 'django.contrib.auth.backends.ModelBackend' - AUDIT_LOG.info('Linked user "%s" logged in via SSL certificate', user.email) + if settings.FEATURES['SQUELCH_PII_IN_LOGS']: + AUDIT_LOG.info('Linked user_id {0} logged in via SSL certificate'.format(user.id)) + else: + AUDIT_LOG.info('Linked user "{0}" logged in via SSL certificate'.format(user.email)) else: user = authenticate(username=uname, password=eamap.internal_password, request=request) if user is None: # we want to log the failure, but don't want to log the password attempted: - AUDIT_LOG.warning('External Auth Login failed for "%s"', uname) + if settings.FEATURES['SQUELCH_PII_IN_LOGS']: + AUDIT_LOG.warning('External Auth Login failed') + else: + AUDIT_LOG.warning('External Auth Login failed for "{0}"'.format(uname)) return _signup(request, eamap, retfun) if not user.is_active: - AUDIT_LOG.warning('User "%s" is not active after external login', uname) + if settings.FEATURES['SQUELCH_PII_IN_LOGS']: + AUDIT_LOG.warning('User {0} is not active after external login'.format(user.id)) + else: + AUDIT_LOG.warning('User "{0}" is not active after external login'.format(uname)) # TODO: improve error page msg = 'Account not yet activated: please look for link in your email' return default_render_failure(request, msg) @@ -223,7 +235,10 @@ def _external_login_or_signup(request, student.views.try_change_enrollment(enroll_request) else: student.views.try_change_enrollment(request) - AUDIT_LOG.info("Login success - %s (%s)", user.username, user.email) + if settings.FEATURES['SQUELCH_PII_IN_LOGS']: + AUDIT_LOG.info("Login success - user.id: {0}".format(user.id)) + else: + AUDIT_LOG.info("Login success - {0} ({1})".format(user.username, user.email)) if retfun is None: return redirect('/') return retfun() @@ -812,8 +827,11 @@ def provider_login(request): user = User.objects.get(email=email) except User.DoesNotExist: request.session['openid_error'] = True - msg = "OpenID login failed - Unknown user email: %s" - AUDIT_LOG.warning(msg, email) + if settings.FEATURES['SQUELCH_PII_IN_LOGS']: + AUDIT_LOG.warning("OpenID login failed - Unknown user email") + else: + msg = "OpenID login failed - Unknown user email: {0}".format(email) + AUDIT_LOG.warning(msg) return HttpResponseRedirect(openid_request_url) # attempt to authenticate user (but not actually log them in...) @@ -828,8 +846,11 @@ def provider_login(request): if user is None: request.session['openid_error'] = True - msg = "OpenID login failed - password for %s is invalid" - AUDIT_LOG.warning(msg, email) + if settings.FEATURES['SQUELCH_PII_IN_LOGS']: + AUDIT_LOG.warning("OpenID login failed - invalid password") + else: + msg = "OpenID login failed - password for {0} is invalid".format(email) + AUDIT_LOG.warning(msg) return HttpResponseRedirect(openid_request_url) # authentication succeeded, so fetch user information @@ -839,8 +860,11 @@ def provider_login(request): if 'openid_error' in request.session: del request.session['openid_error'] - AUDIT_LOG.info("OpenID login success - %s (%s)", - user.username, user.email) + if settings.FEATURES['SQUELCH_PII_IN_LOGS']: + AUDIT_LOG.info("OpenID login success - user.id: {0}".format(user.id)) + else: + AUDIT_LOG.info("OpenID login success - {0} ({1})".format( + user.username, user.email)) # redirect user to return_to location url = endpoint + urlquote(user.username) @@ -859,8 +883,11 @@ def provider_login(request): # the account is not active, so redirect back to the login page: request.session['openid_error'] = True - msg = "Login failed - Account not active for user %s" - AUDIT_LOG.warning(msg, username) + if settings.FEATURES['SQUELCH_PII_IN_LOGS']: + AUDIT_LOG.warning("Login failed - Account not active for user.id {0}".format(user.id)) + else: + msg = "Login failed - Account not active for user {0}".format(username) + AUDIT_LOG.warning(msg) return HttpResponseRedirect(openid_request_url) # determine consumer domain if applicable diff --git a/common/djangoapps/student/models.py b/common/djangoapps/student/models.py index ee9ec4ec88..c182ee34cd 100644 --- a/common/djangoapps/student/models.py +++ b/common/djangoapps/student/models.py @@ -845,10 +845,16 @@ def update_user_information(sender, instance, created, **kwargs): @receiver(user_logged_in) def log_successful_login(sender, request, user, **kwargs): """Handler to log when logins have occurred successfully.""" - AUDIT_LOG.info(u"Login success - {0} ({1})".format(user.username, user.email)) + if settings.FEATURES['SQUELCH_PII_IN_LOGS']: + AUDIT_LOG.info(u"Login success - user.id: {0}".format(user.id)) + else: + AUDIT_LOG.info(u"Login success - {0} ({1})".format(user.username, user.email)) @receiver(user_logged_out) def log_successful_logout(sender, request, user, **kwargs): """Handler to log when logouts have occurred successfully.""" - AUDIT_LOG.info(u"Logout - {0}".format(request.user)) + if settings.FEATURES['SQUELCH_PII_IN_LOGS']: + AUDIT_LOG.info(u"Logout - user.id: {0}".format(request.user.id)) + else: + AUDIT_LOG.info(u"Logout - {0}".format(request.user)) diff --git a/common/djangoapps/student/tests/test_login.py b/common/djangoapps/student/tests/test_login.py index ba080a6fff..d7f3cfad99 100644 --- a/common/djangoapps/student/tests/test_login.py +++ b/common/djangoapps/student/tests/test_login.py @@ -56,6 +56,13 @@ class LoginTest(TestCase): self._assert_response(response, success=True) self._assert_audit_log(mock_audit_log, 'info', [u'Login success', u'test@edx.org']) + @patch.dict("django.conf.settings.FEATURES", {'SQUELCH_PII_IN_LOGS': True}) + def test_login_success_no_pii(self): + response, mock_audit_log = self._login_response('test@edx.org', 'test_password', patched_audit_log='student.models.AUDIT_LOG') + self._assert_response(response, success=True) + self._assert_audit_log(mock_audit_log, 'info', [u'Login success']) + self._assert_not_in_audit_log(mock_audit_log, 'info', [u'test@edx.org']) + def test_login_success_unicode_email(self): unicode_email = u'test' + unichr(40960) + u'@edx.org' self.user.email = unicode_email @@ -72,12 +79,29 @@ class LoginTest(TestCase): value='Email or password is incorrect') self._assert_audit_log(mock_audit_log, 'warning', [u'Login failed', u'Unknown user email', nonexistent_email]) + @patch.dict("django.conf.settings.FEATURES", {'SQUELCH_PII_IN_LOGS': True}) + def test_login_fail_no_user_exists_no_pii(self): + nonexistent_email = u'not_a_user@edx.org' + response, mock_audit_log = self._login_response(nonexistent_email, 'test_password') + self._assert_response(response, success=False, + value='Email or password is incorrect') + self._assert_audit_log(mock_audit_log, 'warning', [u'Login failed', u'Unknown user email']) + self._assert_not_in_audit_log(mock_audit_log, 'warning', [nonexistent_email]) + def test_login_fail_wrong_password(self): response, mock_audit_log = self._login_response('test@edx.org', 'wrong_password') self._assert_response(response, success=False, value='Email or password is incorrect') self._assert_audit_log(mock_audit_log, 'warning', [u'Login failed', u'password for', u'test@edx.org', u'invalid']) + @patch.dict("django.conf.settings.FEATURES", {'SQUELCH_PII_IN_LOGS': True}) + def test_login_fail_wrong_password_no_pii(self): + response, mock_audit_log = self._login_response('test@edx.org', 'wrong_password') + self._assert_response(response, success=False, + value='Email or password is incorrect') + self._assert_audit_log(mock_audit_log, 'warning', [u'Login failed', u'password for', u'invalid']) + self._assert_not_in_audit_log(mock_audit_log, 'warning', [u'test@edx.org']) + def test_login_not_activated(self): # De-activate the user self.user.is_active = False @@ -89,6 +113,19 @@ class LoginTest(TestCase): value="This account has not been activated") self._assert_audit_log(mock_audit_log, 'warning', [u'Login failed', u'Account not active for user']) + @patch.dict("django.conf.settings.FEATURES", {'SQUELCH_PII_IN_LOGS': True}) + def test_login_not_activated_no_pii(self): + # De-activate the user + self.user.is_active = False + self.user.save() + + # Should now be unable to login + response, mock_audit_log = self._login_response('test@edx.org', 'test_password') + self._assert_response(response, success=False, + value="This account has not been activated") + self._assert_audit_log(mock_audit_log, 'warning', [u'Login failed', u'Account not active for user']) + self._assert_not_in_audit_log(mock_audit_log, 'warning', [u'test']) + def test_login_unicode_email(self): unicode_email = u'test@edx.org' + unichr(40960) response, mock_audit_log = self._login_response(unicode_email, 'test_password') @@ -110,6 +147,17 @@ class LoginTest(TestCase): self.assertEqual(response.status_code, 302) self._assert_audit_log(mock_audit_log, 'info', [u'Logout', u'test']) + @patch.dict("django.conf.settings.FEATURES", {'SQUELCH_PII_IN_LOGS': True}) + def test_logout_logging_no_pii(self): + response, _ = self._login_response('test@edx.org', 'test_password') + self._assert_response(response, success=True) + logout_url = reverse('logout') + with patch('student.models.AUDIT_LOG') as mock_audit_log: + response = self.client.post(logout_url) + self.assertEqual(response.status_code, 302) + self._assert_audit_log(mock_audit_log, 'info', [u'Logout']) + self._assert_not_in_audit_log(mock_audit_log, 'info', [u'test']) + def test_login_ratelimited_success(self): # Try (and fail) logging in with fewer attempts than the limit of 30 # and verify that you can still successfully log in afterwards. @@ -177,6 +225,18 @@ class LoginTest(TestCase): for log_string in log_strings: self.assertIn(log_string, format_string) + def _assert_not_in_audit_log(self, mock_audit_log, level, log_strings): + """ + Check that the audit log has received the expected call as its last call. + """ + method_calls = mock_audit_log.method_calls + name, args, _kwargs = method_calls[-1] + self.assertEquals(name, level) + self.assertEquals(len(args), 1) + format_string = args[0] + for log_string in log_strings: + self.assertNotIn(log_string, format_string) + class UtilFnTest(TestCase): """ diff --git a/common/djangoapps/student/views.py b/common/djangoapps/student/views.py index 29d4ee06df..06e506697d 100644 --- a/common/djangoapps/student/views.py +++ b/common/djangoapps/student/views.py @@ -700,7 +700,10 @@ def login_user(request, error=""): try: user = User.objects.get(email=email) except User.DoesNotExist: - AUDIT_LOG.warning(u"Login failed - Unknown user email: {0}".format(email)) + if settings.FEATURES['SQUELCH_PII_IN_LOGS']: + AUDIT_LOG.warning(u"Login failed - Unknown user email") + else: + AUDIT_LOG.warning(u"Login failed - Unknown user email: {0}".format(email)) user = None # check if the user has a linked shibboleth account, if so, redirect the user to shib-login @@ -747,7 +750,11 @@ def login_user(request, error=""): # if we didn't find this username earlier, the account for this email # doesn't exist, and doesn't have a corresponding password if username != "": - AUDIT_LOG.warning(u"Login failed - password for {0} is invalid".format(email)) + if settings.FEATURES['SQUELCH_PII_IN_LOGS']: + loggable_id = user_found_by_email_lookup.id if user_found_by_email_lookup else "" + AUDIT_LOG.warning(u"Login failed - password for user.id: {0} is invalid".format(loggable_id)) + else: + AUDIT_LOG.warning(u"Login failed - password for {0} is invalid".format(email)) return JsonResponse({ "success": False, "value": _('Email or password is incorrect.'), @@ -801,7 +808,10 @@ def login_user(request, error=""): return response - AUDIT_LOG.warning(u"Login failed - Account not active for user {0}, resending activation".format(username)) + if settings.FEATURES['SQUELCH_PII_IN_LOGS']: + AUDIT_LOG.warning(u"Login failed - Account not active for user.id: {0}, resending activation".format(user.id)) + else: + AUDIT_LOG.warning(u"Login failed - Account not active for user {0}, resending activation".format(username)) reactivation_email_for_user(user) not_activated_msg = _("This account has not been activated. We have sent another activation message. Please check your e-mail for the activation instructions.") diff --git a/lms/envs/common.py b/lms/envs/common.py index d8d571cf9b..09e07960bb 100644 --- a/lms/envs/common.py +++ b/lms/envs/common.py @@ -218,6 +218,9 @@ FEATURES = { # Turn off account locking if failed login attempts exceeds a limit 'ENABLE_MAX_FAILED_LOGIN_ATTEMPTS': False, + + # Hide any Personally Identifiable Information from application logs + 'SQUELCH_PII_IN_LOGS': False, } # Used for A/B testing