Merge pull request #511 from edx/feature/brian/audit-log

Use audit logger for logging of logins in external_auth...

CHANGELOG.rst

@@ -5,6 +5,8 @@ These are notable changes in edx-platform.  This is a rolling list of changes,
 in roughly chronological order, most recent first.  Add your entries at or near
 the top.  Include a label indicating the component affected.
 
+Common: Add additional logging to cover login attempts and logouts.
+
 Studio: Send e-mails to new Studio users (on edge only) when their course creator
 status has changed. This will not be in use until the course creator table
 is enabled.

common/djangoapps/student/models.py

@@ -20,6 +20,7 @@ from random import randint
 
 from django.conf import settings
 from django.contrib.auth.models import User
+from django.contrib.auth.signals import user_logged_in, user_logged_out
 from django.db import models
 from django.db.models.signals import post_save
 from django.dispatch import receiver
@@ -30,6 +31,7 @@ from pytz import UTC
 
 
 log = logging.getLogger(__name__)
+AUDIT_LOG = logging.getLogger("audit")
 
 
 class UserProfile(models.Model):
@@ -779,3 +781,20 @@ def update_user_information(sender, instance, created, **kwargs):
         log = logging.getLogger("mitx.discussion")
         log.error(unicode(e))
         log.error("update user info to discussion failed for user with id: " + str(instance.id))
+
+# Define login and logout handlers here in the models file, instead of the views file,
+# so that they are more likely to be loaded when a Studio user brings up the Studio admin
+# page to login.  These are currently the only signals available, so we need to continue
+# identifying and logging failures separately (in views).
+
+
+@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))
+
+
+@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))

lms/djangoapps/courseware/tests/test_login.py → common/djangoapps/student/tests/test_login.py

 '''
 Tests for student activation and login
 '''
+import json
+from mock import patch
+
 from django.test import TestCase
 from django.test.client import Client
-from django.core.urlresolvers import reverse
-from courseware.tests.factories import UserFactory, RegistrationFactory, UserProfileFactory
-import json
+from django.core.urlresolvers import reverse, NoReverseMatch
+from student.tests.factories import UserFactory, RegistrationFactory, UserProfileFactory
 
 
 class LoginTest(TestCase):
@@ -29,30 +31,37 @@ class LoginTest(TestCase):
         self.client = Client()
 
         # Store the login url
-        self.url = reverse('login')
+        try:
+            self.url = reverse('login_post')
+        except NoReverseMatch:
+            self.url = reverse('login')
 
     def test_login_success(self):
-        response = self._login_response('test@edx.org', 'test_password')
+        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', u'test@edx.org'])
 
     def test_login_success_unicode_email(self):
-        unicode_email = u'test@edx.org' + unichr(40960)
-
+        unicode_email = u'test' + unichr(40960) + u'@edx.org'
         self.user.email = unicode_email
         self.user.save()
 
-        response = self._login_response(unicode_email, 'test_password')
+        response, mock_audit_log = self._login_response(unicode_email, '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', unicode_email])
 
     def test_login_fail_no_user_exists(self):
-        response = self._login_response('not_a_user@edx.org', 'test_password')
+        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', nonexistent_email])
 
     def test_login_fail_wrong_password(self):
-        response = self._login_response('test@edx.org', 'wrong_password')
+        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'])
 
     def test_login_not_activated(self):
         # De-activate the user
@@ -60,24 +69,38 @@ class LoginTest(TestCase):
         self.user.save()
 
         # Should now be unable to login
-        response = self._login_response('test@edx.org', 'test_password')
+        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'])
 
     def test_login_unicode_email(self):
         unicode_email = u'test@edx.org' + unichr(40960)
-        response = self._login_response(unicode_email, 'test_password')
+        response, mock_audit_log = self._login_response(unicode_email, 'test_password')
         self._assert_response(response, success=False)
+        self._assert_audit_log(mock_audit_log, 'warning', [u'Login failed', unicode_email])
 
     def test_login_unicode_password(self):
         unicode_password = u'test_password' + unichr(1972)
-        response = self._login_response('test@edx.org', unicode_password)
+        response, mock_audit_log = self._login_response('test@edx.org', unicode_password)
         self._assert_response(response, success=False)
+        self._assert_audit_log(mock_audit_log, 'warning', [u'Login failed', u'password for', u'test@edx.org', u'invalid'])
+
+    def test_logout_logging(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', u'test'])
 
-    def _login_response(self, email, password):
+    def _login_response(self, email, password, patched_audit_log='student.views.AUDIT_LOG'):
         ''' Post the login info '''
         post_params = {'email': email, 'password': password}
-        return self.client.post(self.url, post_params)
+        with patch(patched_audit_log) as mock_audit_log:
+            result = self.client.post(self.url, post_params)
+        return result, mock_audit_log
 
     def _assert_response(self, response, success=None, value=None):
         '''
@@ -105,3 +128,16 @@ class LoginTest(TestCase):
             msg = ("'%s' did not contain '%s'" %
                    (str(response_dict['value']), str(value)))
             self.assertTrue(value in response_dict['value'], msg)
+
+    def _assert_audit_log(self, mock_audit_log, level, log_strings):
+        """
+        Check that the audit log has received the expected call.
+        """
+        method_calls = mock_audit_log.method_calls
+        self.assertEquals(len(method_calls), 1)
+        name, args, _kwargs = method_calls[0]
+        self.assertEquals(name, level)
+        self.assertEquals(len(args), 1)
+        format_string = args[0]
+        for log_string in log_strings:
+            self.assertIn(log_string, format_string)