Skip to content

E
edx-platform
Commit 635d36fc by Brian Wilson
Options

Add audit log definition, and use for logging of logins in external_auth and… 

Add audit log definition, and use for logging of logins in external_auth and student apps.  Move test_login to student app. Improve conditional tests for Shibboleth login logic.  (Does not include reconfiguring log settings.)
parent 50ef0d1c
Showing with 103 additions and 35 deletions
CHANGELOG.rst
...@@ -5,6 +5,8 @@ These are notable changes in edx-platform. This is a rolling list of changes, ...@@ -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 in roughly chronological order, most recent first. Add your entries at or near
the top. Include a label indicating the component affected. 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 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 status has changed. This will not be in use until the course creator table
is enabled. is enabled.
......
common/djangoapps/student/models.py
...@@ -20,6 +20,7 @@ from random import randint ...@@ -20,6 +20,7 @@ from random import randint
from django.conf import settings from django.conf import settings
from django.contrib.auth.models import User 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 import models
from django.db.models.signals import post_save from django.db.models.signals import post_save
from django.dispatch import receiver from django.dispatch import receiver
...@@ -30,6 +31,7 @@ from pytz import UTC ...@@ -30,6 +31,7 @@ from pytz import UTC
log = logging.getLogger(__name__) log = logging.getLogger(__name__)
AUDIT_LOG = logging.getLogger("audit")
class UserProfile(models.Model): class UserProfile(models.Model):
...@@ -779,3 +781,20 @@ def update_user_information(sender, instance, created, **kwargs): ...@@ -779,3 +781,20 @@ def update_user_information(sender, instance, created, **kwargs):
log = logging.getLogger("mitx.discussion") log = logging.getLogger("mitx.discussion")
log.error(unicode(e)) log.error(unicode(e))
log.error("update user info to discussion failed for user with id: " + str(instance.id)) 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 Tests for student activation and login
''' '''
import json
from mock import patch
from django.test import TestCase from django.test import TestCase
from django.test.client import Client from django.test.client import Client
from django.core.urlresolvers import reverse from django.core.urlresolvers import reverse, NoReverseMatch
from courseware.tests.factories import UserFactory, RegistrationFactory, UserProfileFactory from student.tests.factories import UserFactory, RegistrationFactory, UserProfileFactory
import json
class LoginTest(TestCase): class LoginTest(TestCase):
...@@ -29,30 +31,37 @@ class LoginTest(TestCase): ...@@ -29,30 +31,37 @@ class LoginTest(TestCase):
self.client = Client() self.client = Client()
# Store the login url # Store the login url
try:
self.url = reverse('login_post')
except NoReverseMatch:
self.url = reverse('login') self.url = reverse('login')
def test_login_success(self): 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_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): 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.email = unicode_email
self.user.save() 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_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): 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, self._assert_response(response, success=False,
value='Email or password is incorrect') 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): 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, self._assert_response(response, success=False,
value='Email or password is incorrect') 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): def test_login_not_activated(self):
# De-activate the user # De-activate the user
...@@ -60,24 +69,38 @@ class LoginTest(TestCase): ...@@ -60,24 +69,38 @@ class LoginTest(TestCase):
self.user.save() self.user.save()
# Should now be unable to login # 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, self._assert_response(response, success=False,
value="This account has not been activated") 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): def test_login_unicode_email(self):
unicode_email = u'test@edx.org' + unichr(40960) 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_response(response, success=False)
self._assert_audit_log(mock_audit_log, 'warning', [u'Login failed', unicode_email])
def test_login_unicode_password(self): def test_login_unicode_password(self):
unicode_password = u'test_password' + unichr(1972) 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_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 the login info '''
post_params = {'email': email, 'password': password} 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): def _assert_response(self, response, success=None, value=None):
''' '''
...@@ -105,3 +128,16 @@ class LoginTest(TestCase): ...@@ -105,3 +128,16 @@ class LoginTest(TestCase):
msg = ("'%s' did not contain '%s'" % msg = ("'%s' did not contain '%s'" %
(str(response_dict['value']), str(value))) (str(response_dict['value']), str(value)))
self.assertTrue(value in response_dict['value'], msg) 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)
common/djangoapps/student/views.py
...@@ -56,6 +56,8 @@ from statsd import statsd ...@@ -56,6 +56,8 @@ from statsd import statsd
from pytz import UTC from pytz import UTC
log = logging.getLogger("mitx.student") log = logging.getLogger("mitx.student")
AUDIT_LOG = logging.getLogger("audit")
Article = namedtuple('Article', 'title url author image deck publication publish_date') Article = namedtuple('Article', 'title url author image deck publication publish_date')
...@@ -107,8 +109,7 @@ day_pattern = re.compile(r'\s\d+,\s') ...@@ -107,8 +109,7 @@ day_pattern = re.compile(r'\s\d+,\s')
multimonth_pattern = re.compile(r'\s?\-\s?\S+\s') multimonth_pattern = re.compile(r'\s?\-\s?\S+\s')
def get_date_for_press(publish_date): def _get_date_for_press(publish_date):
import datetime
# strip off extra months, and just use the first: # strip off extra months, and just use the first:
date = re.sub(multimonth_pattern, ", ", publish_date) date = re.sub(multimonth_pattern, ", ", publish_date)
if re.search(day_pattern, date): if re.search(day_pattern, date):
...@@ -129,7 +130,7 @@ def press(request): ...@@ -129,7 +130,7 @@ def press(request):
json_articles = json.loads(content) json_articles = json.loads(content)
cache.set("student_press_json_articles", json_articles) cache.set("student_press_json_articles", json_articles)
articles = [Article(**article) for article in json_articles] articles = [Article(**article) for article in json_articles]
articles.sort(key=lambda item: get_date_for_press(item.publish_date), reverse=True) articles.sort(key=lambda item: _get_date_for_press(item.publish_date), reverse=True)
return render_to_response('static_templates/press.html', {'articles': articles}) return render_to_response('static_templates/press.html', {'articles': articles})
...@@ -233,7 +234,7 @@ def signin_user(request): ...@@ -233,7 +234,7 @@ def signin_user(request):
@ensure_csrf_cookie @ensure_csrf_cookie
def register_user(request, extra_context={}): def register_user(request, extra_context=None):
""" """
This view will display the non-modal registration form This view will display the non-modal registration form
""" """
...@@ -244,6 +245,7 @@ def register_user(request, extra_context={}): ...@@ -244,6 +245,7 @@ def register_user(request, extra_context={}):
'course_id': request.GET.get('course_id'), 'course_id': request.GET.get('course_id'),
'enrollment_action': request.GET.get('enrollment_action') 'enrollment_action': request.GET.get('enrollment_action')
} }
if extra_context is not None:
context.update(extra_context) context.update(extra_context)
return render_to_response('register.html', context) return render_to_response('register.html', context)
...@@ -381,7 +383,7 @@ def change_enrollment(request): ...@@ -381,7 +383,7 @@ def change_enrollment(request):
"run:{0}".format(run)]) "run:{0}".format(run)])
try: try:
enrollment, created = CourseEnrollment.objects.get_or_create(user=user, course_id=course.id) enrollment, _created = CourseEnrollment.objects.get_or_create(user=user, course_id=course.id)
except IntegrityError: except IntegrityError:
# If we've already created this enrollment in a separate transaction, # If we've already created this enrollment in a separate transaction,
# then just continue # then just continue
...@@ -425,19 +427,21 @@ def login_user(request, error=""): ...@@ -425,19 +427,21 @@ def login_user(request, error=""):
try: try:
user = User.objects.get(email=email) user = User.objects.get(email=email)
except User.DoesNotExist: except User.DoesNotExist:
log.warning(u"Login failed - Unknown user email: {0}".format(email)) AUDIT_LOG.warning(u"Login failed - Unknown user email: {0}".format(email))
return HttpResponse(json.dumps({'success': False, return HttpResponse(json.dumps({'success': False,
'value': _('Email or password is incorrect.')})) # TODO: User error message 'value': _('Email or password is incorrect.')})) # TODO: User error message
username = user.username username = user.username
user = authenticate(username=username, password=password) user = authenticate(username=username, password=password)
if user is None: if user is None:
log.warning(u"Login failed - password for {0} is invalid".format(email)) AUDIT_LOG.warning(u"Login failed - password for {0} is invalid".format(email))
return HttpResponse(json.dumps({'success': False, return HttpResponse(json.dumps({'success': False,
'value': _('Email or password is incorrect.')})) 'value': _('Email or password is incorrect.')}))
if user is not None and user.is_active: if user is not None and user.is_active:
try: try:
# We do not log here, because we have a handler registered
# to perform logging on successful logins.
login(request, user) login(request, user)
if request.POST.get('remember') == 'true': if request.POST.get('remember') == 'true':
request.session.set_expiry(604800) request.session.set_expiry(604800)
...@@ -445,14 +449,14 @@ def login_user(request, error=""): ...@@ -445,14 +449,14 @@ def login_user(request, error=""):
else: else:
request.session.set_expiry(0) request.session.set_expiry(0)
except Exception as e: except Exception as e:
AUDIT_LOG.critical("Login failed - Could not create session. Is memcached running?")
log.critical("Login failed - Could not create session. Is memcached running?") log.critical("Login failed - Could not create session. Is memcached running?")
log.exception(e) log.exception(e)
raise
log.info(u"Login success - {0} ({1})".format(username, email))
try_change_enrollment(request) try_change_enrollment(request)
statsd.increment(_("common.student.successful_login")) statsd.increment("common.student.successful_login")
response = HttpResponse(json.dumps({'success': True})) response = HttpResponse(json.dumps({'success': True}))
# set the login cookie for the edx marketing site # set the login cookie for the edx marketing site
...@@ -476,7 +480,7 @@ def login_user(request, error=""): ...@@ -476,7 +480,7 @@ def login_user(request, error=""):
return response return response
log.warning(u"Login failed - Account not active for user {0}, resending activation".format(username)) AUDIT_LOG.warning(u"Login failed - Account not active for user {0}, resending activation".format(username))
reactivation_email_for_user(user) 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.") not_activated_msg = _("This account has not been activated. We have sent another activation message. Please check your e-mail for the activation instructions.")
...@@ -491,7 +495,8 @@ def logout_user(request): ...@@ -491,7 +495,8 @@ def logout_user(request):
Deletes both the CSRF and sessionid cookies so the marketing Deletes both the CSRF and sessionid cookies so the marketing
site can determine the logged in state of the user site can determine the logged in state of the user
''' '''
# We do not log here, because we have a handler registered
# to perform logging on successful logouts.
logout(request) logout(request)
response = redirect('/') response = redirect('/')
response.delete_cookie(settings.EDXMKTG_COOKIE_NAME, response.delete_cookie(settings.EDXMKTG_COOKIE_NAME,
...@@ -598,7 +603,7 @@ def create_account(request, post_override=None): ...@@ -598,7 +603,7 @@ def create_account(request, post_override=None):
password = eamap.internal_password password = eamap.internal_password
post_vars = dict(post_vars.items()) post_vars = dict(post_vars.items())
post_vars.update(dict(email=email, name=name, password=password)) post_vars.update(dict(email=email, name=name, password=password))
log.info('In create_account with external_auth: post_vars = %s' % post_vars) log.debug(u'In create_account with external_auth: user = %s, email=%s', name, email)
# Confirm we have a properly formed request # Confirm we have a properly formed request
for a in ['username', 'email', 'password', 'name']: for a in ['username', 'email', 'password', 'name']:
...@@ -684,7 +689,7 @@ def create_account(request, post_override=None): ...@@ -684,7 +689,7 @@ def create_account(request, post_override=None):
'-' * 80 + '\n\n' + message) '-' * 80 + '\n\n' + message)
send_mail(subject, message, settings.DEFAULT_FROM_EMAIL, [dest_addr], fail_silently=False) send_mail(subject, message, settings.DEFAULT_FROM_EMAIL, [dest_addr], fail_silently=False)
else: else:
res = user.email_user(subject, message, settings.DEFAULT_FROM_EMAIL) _res = user.email_user(subject, message, settings.DEFAULT_FROM_EMAIL)
except: except:
log.warning('Unable to send activation email to user', exc_info=True) log.warning('Unable to send activation email to user', exc_info=True)
js['value'] = _('Could not send activation e-mail.') js['value'] = _('Could not send activation e-mail.')
...@@ -697,17 +702,23 @@ def create_account(request, post_override=None): ...@@ -697,17 +702,23 @@ def create_account(request, post_override=None):
login(request, login_user) login(request, login_user)
request.session.set_expiry(0) request.session.set_expiry(0)
# TODO: there is no error checking here to see that the user actually logged in successfully,
# and is not yet an active user.
if login_user is not None:
AUDIT_LOG.info(u"Login success on new account creation - {0}".format(login_user.username))
if DoExternalAuth: if DoExternalAuth:
eamap.user = login_user eamap.user = login_user
eamap.dtsignup = datetime.datetime.now(UTC) eamap.dtsignup = datetime.datetime.now(UTC)
eamap.save() eamap.save()
log.info("User registered with external_auth %s" % post_vars['username']) AUDIT_LOG.info("User registered with external_auth %s", post_vars['username'])
log.info('Updated ExternalAuthMap for %s to be %s' % (post_vars['username'], eamap)) AUDIT_LOG.info('Updated ExternalAuthMap for %s to be %s', post_vars['username'], eamap)
if settings.MITX_FEATURES.get('BYPASS_ACTIVATION_EMAIL_FOR_EXTAUTH'): if settings.MITX_FEATURES.get('BYPASS_ACTIVATION_EMAIL_FOR_EXTAUTH'):
log.info('bypassing activation email') log.info('bypassing activation email')
login_user.is_active = True login_user.is_active = True
login_user.save() login_user.save()
AUDIT_LOG.info(u"Login activated on extauth account - {0} ({1})".format(login_user.username, login_user.email))
try_change_enrollment(request) try_change_enrollment(request)
...@@ -964,14 +975,14 @@ def activate_account(request, key): ...@@ -964,14 +975,14 @@ def activate_account(request, key):
r[0].activate() r[0].activate()
already_active = False already_active = False
#Enroll student in any pending courses he/she may have if auto_enroll flag is set # Enroll student in any pending courses he/she may have if auto_enroll flag is set
student = User.objects.filter(id=r[0].user_id) student = User.objects.filter(id=r[0].user_id)
if student: if student:
ceas = CourseEnrollmentAllowed.objects.filter(email=student[0].email) ceas = CourseEnrollmentAllowed.objects.filter(email=student[0].email)
for cea in ceas: for cea in ceas:
if cea.auto_enroll: if cea.auto_enroll:
course_id = cea.course_id course_id = cea.course_id
enrollment, created = CourseEnrollment.objects.get_or_create(user_id=student[0].id, course_id=course_id) _enrollment, _created = CourseEnrollment.objects.get_or_create(user_id=student[0].id, course_id=course_id)
resp = render_to_response("registration/activation_complete.html", {'user_logged_in': user_logged_in, 'already_active': already_active}) resp = render_to_response("registration/activation_complete.html", {'user_logged_in': user_logged_in, 'already_active': already_active})
return resp return resp
...@@ -1003,7 +1014,7 @@ def password_reset_confirm_wrapper(request, uidb36=None, token=None): ...@@ -1003,7 +1014,7 @@ def password_reset_confirm_wrapper(request, uidb36=None, token=None):
''' A wrapper around django.contrib.auth.views.password_reset_confirm. ''' A wrapper around django.contrib.auth.views.password_reset_confirm.
Needed because we want to set the user as active at this step. Needed because we want to set the user as active at this step.
''' '''
#cribbed from django.contrib.auth.views.password_reset_confirm # cribbed from django.contrib.auth.views.password_reset_confirm
try: try:
uid_int = base36_to_int(uidb36) uid_int = base36_to_int(uidb36)
user = User.objects.get(id=uid_int) user = User.objects.get(id=uid_int)
...@@ -1029,7 +1040,7 @@ def reactivation_email_for_user(user): ...@@ -1029,7 +1040,7 @@ def reactivation_email_for_user(user):
message = render_to_string('emails/activation_email.txt', d) message = render_to_string('emails/activation_email.txt', d)
try: try:
res = user.email_user(subject, message, settings.DEFAULT_FROM_EMAIL) _res = user.email_user(subject, message, settings.DEFAULT_FROM_EMAIL)
except: except:
log.warning('Unable to send reactivation email', exc_info=True) log.warning('Unable to send reactivation email', exc_info=True)
return HttpResponse(json.dumps({'success': False, 'error': _('Unable to send reactivation email')})) return HttpResponse(json.dumps({'success': False, 'error': _('Unable to send reactivation email')}))
...@@ -1087,7 +1098,7 @@ def change_email_request(request): ...@@ -1087,7 +1098,7 @@ def change_email_request(request):
subject = ''.join(subject.splitlines()) subject = ''.join(subject.splitlines())
message = render_to_string('emails/email_change.txt', d) message = render_to_string('emails/email_change.txt', d)
res = send_mail(subject, message, settings.DEFAULT_FROM_EMAIL, [pec.new_email]) _res = send_mail(subject, message, settings.DEFAULT_FROM_EMAIL, [pec.new_email])
return HttpResponse(json.dumps({'success': True})) return HttpResponse(json.dumps({'success': True}))
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment