team-tryouts/tests/test_audit_logging.py

"""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': '[email protected]',
                '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': '[email protected]',
                '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': '[email protected]',
                '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