feat(obs): journaliser les evenements d'authentification
OBS-001. logging_config.py configurait un fichier auth.log avec rotation,
un logger nomme 'team_tryouts.auth' et un filtre de redaction. Mais
get_auth_logger n'etait importe nulle part : le fichier etait cree et
restait vide. Aucune connexion, aucun echec, aucun verrouillage, aucun
changement de role, aucune suppression de compte ne laissait de trace.
En cas de suspicion de compromission, il n'y avait rien a consulter.
Ajout de log_auth_event(event, **fields), qui emet des paires cle=valeur
ordonnees -- greppable sans dependance de journalisation JSON.
Evenements couverts
authentification login.success, login.failure,
login.failure.unknown_user, login.rejected.locked,
login.rejected.deactivated, account.locked, logout,
account.registered
administration account.created_by_admin, account.updated,
account.role_changed (avec ancien et nouveau role),
account.deleted, account.password_reset_by_admin
libre-service account.password_changed
Le champ ip vient de request.remote_addr, donc de X-Forwarded-For. Tant que
Waitress tourne avec trusted_proxy='*' (SEC-WEB-002), cette valeur est
choisie par l'appelant : c'est une indication, pas une preuve. Le point est
documente dans la docstring.
Un test a fait remonter ARCH-003, jusqu'ici classe comme fragilite latente
Journaliser en fin de edit_user levait DetachedInstanceError : le
changement de role appelle db.session.remove() en plein cycle de requete,
ce qui detache current_user de la session. Le code s'en tirait parce qu'il
redirigeait immediatement sans plus y toucher. L'identite de l'acteur est
desormais capturee en debut de traitement. Le constat est donc confirme
comme reel, et non plus seulement probable -- sa correction de fond reste
au programme.
15 tests, dont 4 sur le filtre de redaction lui-meme : c'est un controle de
securite, il doit etre verifie.
Co-Authored-By: Claude Opus 5 <[email protected]>
This commit is contained in:
GGThed
@@ -0,0 +1,200 @@
|
||||
"""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_lockout_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
|
||||
|
||||
for _ in range(5):
|
||||
login(username, password='WrongPassword1')
|
||||
|
||||
assert _has_event(auth_log, 'account.locked')
|
||||
|
||||
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.get('/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
|
||||
Reference in New Issue
Block a user