"""Security event logging. OBS-001. logging_config.py configured a rotating auth.log handler, a named 'team_tryouts.auth' logger and a redaction filter — and get_auth_logger was never imported anywhere. The file was created and stayed empty: no login, no failure, no lockout, no role change, no deletion left a trace. After a suspected compromise there was nothing to look at. """ import logging import pytest from app.extensions import db from app.models import User @pytest.fixture def auth_log(caplog): """Capture records emitted on the auth logger. The logger sets propagate = False so its records never reach the root handler caplog installs; the handler is attached directly instead. """ logger = logging.getLogger('team_tryouts.auth') previous = logger.level logger.setLevel(logging.INFO) logger.addHandler(caplog.handler) try: yield caplog finally: logger.removeHandler(caplog.handler) logger.setLevel(previous) def _events(caplog): return [r.getMessage() for r in caplog.records] def _has_event(caplog, name): return any(f'event={name}' in message for message in _events(caplog)) class TestLoginEvents: def test_a_successful_login_is_recorded(self, client, as_role, auth_log): as_role('player') assert _has_event(auth_log, 'login.success') def test_the_record_carries_who_and_from_where(self, app, client, as_role, auth_log): user_id = as_role('coach') with app.app_context(): username = db.session.get(User, user_id).username message = next(m for m in _events(auth_log) if 'event=login.success' in m) assert f'username={username}' in message assert f'user_id={user_id}' in message assert 'role=coach' in message assert 'ip=' in message def test_a_wrong_password_is_recorded(self, app, client, make_user, login, auth_log): user_id = make_user('player') with app.app_context(): username = db.session.get(User, user_id).username login(username, password='WrongPassword1') assert _has_event(auth_log, 'login.failure') def test_an_unknown_username_is_recorded_separately(self, client, login, auth_log): login('no-such-account', password='WrongPassword1') assert _has_event(auth_log, 'login.failure.unknown_user') def test_a_run_of_failures_is_recorded(self, app, client, make_user, login, auth_log): """Renamed from account.locked with SEC-018: the window no longer refuses the account owner, so 'locked' overstated what happened.""" user_id = make_user('player') with app.app_context(): username = db.session.get(User, user_id).username for _ in range(5): login(username, password='WrongPassword1') assert _has_event(auth_log, 'account.throttled') def test_a_deactivated_account_attempt_is_recorded( self, app, client, make_user, login, auth_log ): user_id = make_user('player') with app.app_context(): user = db.session.get(User, user_id) user.is_active_account = False username = user.username db.session.commit() login(username) assert _has_event(auth_log, 'login.rejected.deactivated') def test_logout_is_recorded(self, client, as_role, auth_log): as_role('player') client.post('/auth/logout') assert _has_event(auth_log, 'logout') class TestAdministrativeEvents: def test_account_creation_is_recorded(self, client, as_role, auth_log): as_role('admin') client.post( '/users/create', data={ 'username': 'newcoach', 'email': 'newcoach@example.test', 'password': 'Password123', 'full_name': 'New Coach', 'role': 'coach', }, follow_redirects=True, ) assert _has_event(auth_log, 'account.created_by_admin') def test_a_role_change_records_both_roles(self, app, client, as_role, make_user, auth_log): target_id = make_user('player') as_role('admin') client.post( f'/users/{target_id}/edit', data={ 'full_name': 'Promoted', 'email': 'promoted@example.test', 'role': 'coach', 'is_active_account': 'on', }, follow_redirects=True, ) message = next(m for m in _events(auth_log) if 'event=account.role_changed' in m) assert 'previous_role=player' in message assert 'new_role=coach' in message assert f'target_id={target_id}' in message def test_account_deletion_is_recorded(self, client, as_role, make_user, auth_log): victim_id = make_user('player') as_role('admin') client.post(f'/users/{victim_id}/delete', follow_redirects=True) assert _has_event(auth_log, 'account.deleted') def test_a_self_service_password_change_is_recorded(self, app, client, as_role, auth_log): user_id = as_role('player') with app.app_context(): username = db.session.get(User, user_id).username client.post( '/users/profile/edit', data={ 'username': username, 'full_name': 'Same Name', 'email': 'same@example.test', 'password': 'BrandNew123', }, follow_redirects=True, ) assert _has_event(auth_log, 'account.password_changed') class TestRedaction: """The filter is a security control; it needs its own test. It used to inspect record.msg only, while every call site logs with %s placeholders — so the sensitive value sat in record.args and was never examined. """ def test_a_secret_passed_through_args_is_redacted(self): from app.logging_config import SensitiveDataFilter record = logging.LogRecord( 'test', logging.ERROR, 'x.py', 1, 'Database failure: %s', ('password=hunter2 host=db.internal',), None, ) SensitiveDataFilter().filter(record) rendered = record.getMessage() assert 'hunter2' not in rendered assert '[REDACTED]' in rendered def test_a_bearer_token_is_redacted(self): from app.logging_config import SensitiveDataFilter record = logging.LogRecord( 'test', logging.INFO, 'x.py', 1, 'Calling Discord with %s', ('Bearer abcdef123456',), None, ) SensitiveDataFilter().filter(record) assert 'abcdef123456' not in record.getMessage() def test_an_ordinary_message_is_left_alone(self): from app.logging_config import SensitiveDataFilter record = logging.LogRecord( 'test', logging.INFO, 'x.py', 1, 'event=login.success username=%s', ('alice',), None, ) SensitiveDataFilter().filter(record) assert record.getMessage() == 'event=login.success username=alice' def test_a_malformed_format_string_does_not_drop_the_record(self): from app.logging_config import SensitiveDataFilter record = logging.LogRecord( 'test', logging.INFO, 'x.py', 1, 'broken %d', ('not-a-number',), None, ) assert SensitiveDataFilter().filter(record) is True