diff --git a/CHANGELOG.md b/CHANGELOG.md index b6767b11..d429e839 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -18,6 +18,7 @@ and this project adheres to - ✨(backend) expose `allow_unregistered_rooms` in the frontend configuration - ✅(frontend) add vitest so the frontend can carry unit tests - ♿️(frontend) make participant pagination readable and keyboard reachable #1775 +- ✨(backend) add structured audit logging facility ### Changed @@ -28,6 +29,7 @@ and this project adheres to - 🐛(frontend) enforce recording-mode permissions on the checkboxes - 🔒️(agents) fix util-linux CVEs reported by Cyberwatch +- 🔒️(backend) identify throttled clients by IP using NUM_PROXIES - 🔒️(backend) fix HIGH CVEs in Django and urllib3 - 🔒️(agents) upgrade libpcre2-8-0 to fix CVE-2026-103111 - 🔒️(frontend) upgrade pcre2 to fix CVE-2026-103111 diff --git a/docker/files/usr/local/etc/gunicorn/meet.py b/docker/files/usr/local/etc/gunicorn/meet.py index e1386a53..1bebecde 100644 --- a/docker/files/usr/local/etc/gunicorn/meet.py +++ b/docker/files/usr/local/etc/gunicorn/meet.py @@ -14,4 +14,7 @@ accesslog = "-" # Using '-' for the error log file makes gunicorn log errors to stderr errorlog = "-" loglevel = "info" -access_log_format = '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s" %(M)s' +access_log_format = ( + '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s" %(M)s' + " rid=%({x-request-id}o)s" +) diff --git a/src/backend/core/audit/__init__.py b/src/backend/core/audit/__init__.py new file mode 100644 index 00000000..f145a73b --- /dev/null +++ b/src/backend/core/audit/__init__.py @@ -0,0 +1,32 @@ +"""Structured audit logging.""" + +from .actions import Action +from .actor import email_domain +from .drf import AuditViewMixin +from .emitter import AUDIT_LOGGER_NAME, log +from .enums import ActorType, EventCategory, EventType, Outcome, Reason +from .formatter import AuditJsonFormatter +from .registry import AlreadyRegistered, register, register_auth_method +from .request import current_request +from .signals import LOGIN_ACTION, LOGOUT_ACTION, connect_auth_signals + +__all__ = [ + "AUDIT_LOGGER_NAME", + "LOGIN_ACTION", + "LOGOUT_ACTION", + "Action", + "ActorType", + "AlreadyRegistered", + "AuditJsonFormatter", + "AuditViewMixin", + "EventCategory", + "EventType", + "Outcome", + "Reason", + "connect_auth_signals", + "current_request", + "email_domain", + "log", + "register", + "register_auth_method", +] diff --git a/src/backend/core/audit/actions.py b/src/backend/core/audit/actions.py new file mode 100644 index 00000000..413199bb --- /dev/null +++ b/src/backend/core/audit/actions.py @@ -0,0 +1,27 @@ +"""Specs of the actions audit events are emitted for.""" + +from dataclasses import dataclass + +from .enums import EventCategory, EventType + + +@dataclass(frozen=True) +class Action: + """An audited action: its dotted name and its ECS classification. + + ``category`` and ``types`` are the defaults of every event of the action: + a ``category`` or ``types`` given to ``log`` wins over them. + """ + + name: str + category: EventCategory | None = None + types: tuple[EventType, ...] = () + + def __post_init__(self): + """Validate the classification, so a bad one fails at import.""" + if self.category is not None: + object.__setattr__(self, "category", EventCategory(self.category)) + object.__setattr__(self, "types", tuple(EventType(t) for t in self.types)) + + def __str__(self) -> str: + return self.name diff --git a/src/backend/core/audit/actor.py b/src/backend/core/audit/actor.py new file mode 100644 index 00000000..a36429a9 --- /dev/null +++ b/src/backend/core/audit/actor.py @@ -0,0 +1,159 @@ +"""Resolve who is acting: actor type, identifiers, auth method and tenant. + +Personal data is kept to a minimum on purpose: a person is identified by its +primary key, its OIDC ``sub`` when it has one and the domain of its email +address. The address itself is never recorded. +""" + +from collections.abc import Mapping +from typing import Any + +from django.contrib.auth import get_user_model + +from lasuite.tools.email import get_domain_from_email + +from .enums import ActorType +from .registry import auth_methods, dotted_path + +AUTH_METHOD_NONE = "none" +AUTH_METHOD_SESSION = "session" +AUTH_METHOD_UNKNOWN = "unknown" + +DEFAULT_AUTH_METHODS = { + "rest_framework.authentication.SessionAuthentication": AUTH_METHOD_SESSION, + "rest_framework.authentication.BasicAuthentication": "basic", + "rest_framework.authentication.TokenAuthentication": "token", + "django.contrib.auth.backends.ModelBackend": "password", +} + + +def _auth_methods() -> dict[str, str]: + return {**DEFAULT_AUTH_METHODS, **auth_methods()} + + +def auth_method_for(authenticator) -> str: + """Return the auth method name for a DRF authenticator instance.""" + if authenticator is None: + return AUTH_METHOD_NONE + methods = _auth_methods() + for klass in type(authenticator).__mro__: + name = methods.get(dotted_path(klass)) + if name: + return name + return AUTH_METHOD_UNKNOWN + + +def auth_method_for_backend(backend: str | None) -> str: + """Return the auth method name for the dotted path of a login backend.""" + return _auth_methods().get(backend or "", AUTH_METHOD_UNKNOWN) + + +def request_auth_method(request) -> str: + """Return how ``request`` was authenticated. + + A DRF request names its authenticator. A plain Django request, as served + by the admin or the logout view, can only be authenticated by its session. + """ + if hasattr(request, "successful_authenticator"): + return auth_method_for(request.successful_authenticator) + if _is_authenticated(getattr(request, "user", None)): + return AUTH_METHOD_SESSION + return AUTH_METHOD_NONE + + +def email_domain(email) -> str | None: + """Return the lower-cased domain part of an email address, if any. + + It is parsed as for ``Application.can_delegate_email``, so an audited + domain is the one a delegation was checked against. + """ + domain = get_domain_from_email(str(email)) if email else None + return domain.lower() if domain else None + + +def client_id_from_auth(auth) -> str | None: + """Extract an application client id from a token payload.""" + if isinstance(auth, Mapping): + value = auth.get("client_id") + return str(value) if value else None + return None + + +def _is_authenticated(user) -> bool: + return bool(user is not None and getattr(user, "is_authenticated", False)) + + +def _is_account(user) -> bool: + """Tell whether ``user`` is a user account. + + It stays one once deleted, when Django clears its primary key. + """ + return isinstance(user, get_user_model()) + + +def _is_service(user) -> bool: + """Tell whether ``user`` authenticated without an account, as a machine user.""" + return _is_authenticated(user) and not _is_account(user) + + +def _default_actor_type(request, user, client_id) -> ActorType: + if client_id: + return ActorType.APPLICATION + if request is None and user is None: + return ActorType.SYSTEM + if _is_service(user): + return ActorType.SERVICE + if _is_account(user): + return ActorType.USER + return ActorType.ANONYMOUS + + +def describe_user(user) -> dict[str, Any]: + """Return the fields identifying a person: id, OIDC sub and email domain. + + The sub is missing for accounts that never signed in, such as provisional + users, and the id for accounts that were deleted. + """ + return { + "id": str(user.pk) if user.pk is not None else None, + "sub": getattr(user, "sub", None) or None, + "domain": email_domain(getattr(user, "email", None)), + } + + +def describe_actor( + request, + *, + actor=None, + actor_type: ActorType | str | None = None, + client_id: str | None = None, + auth_method: str | None = None, +) -> dict[str, Any]: + """Return the ECS ``user`` and ``organization`` fields and the ``lasuite`` ones. + + Everything is read from ``request`` unless overridden. Without a request + or an actor, the actor is the system. ``user`` is the account whose + authority the action used, see ``ActorType``: None for a service, the + system or an anonymous caller. + """ + user = actor if actor is not None else getattr(request, "user", None) + client_id = client_id or client_id_from_auth(getattr(request, "auth", None)) + actor_type = actor_type or _default_actor_type(request, user, client_id) + + lasuite: dict[str, Any] = { + "actor": { + "type": str(ActorType(actor_type)), + "name": user.get_username() if _is_service(user) else None, + }, + "auth": {"method": auth_method or request_auth_method(request)}, + "application": {"client_id": client_id}, + } + is_account = _is_account(user) + tenant = client_id or ( + email_domain(getattr(user, "email", None)) if is_account else None + ) + return { + "user": describe_user(user) if is_account else None, + "organization": {"id": tenant}, + "lasuite": lasuite, + } diff --git a/src/backend/core/audit/apps.py b/src/backend/core/audit/apps.py new file mode 100644 index 00000000..3219c89f --- /dev/null +++ b/src/backend/core/audit/apps.py @@ -0,0 +1,22 @@ +"""Application configurations of the audit facility.""" + +from django.apps import AppConfig +from django.utils.module_loading import autodiscover_modules + +from .signals import connect_auth_signals + + +class AuditConfig(AppConfig): + """Audit Django's authentication signals and load the project's declarations.""" + + name = "core.audit" + label = "audit" + + def ready(self): + """Connect the login, failed login and logout receivers. + + Then import the ``auditing`` module of every installed app, where the + project registers its models and authentication classes. + """ + connect_auth_signals() + autodiscover_modules("auditing") diff --git a/src/backend/core/audit/drf.py b/src/backend/core/audit/drf.py new file mode 100644 index 00000000..6f4574dc --- /dev/null +++ b/src/backend/core/audit/drf.py @@ -0,0 +1,174 @@ +"""Django REST framework integration + +``AuditViewMixin`` turns every response of an audited action into one audit +event, from DRF's ``finalize_response`` hook, which runs for successes and for +handled errors alike. An exception DRF does not handle is audited as an +internal error from ``handle_exception`` before it propagates. + +The CRUD actions a viewset audits are mapped in ``audit_actions``. +Extra action names require a decorator:: + + class RoomViewSet(audit.AuditViewMixin, viewsets.ModelViewSet): + audit_actions = {"create": ROOM_CREATE, "retrieve": ROOM_RETRIEVE} + + @action(detail=True, methods=["post"], audit_action=ROOM_INVITE) + def invite(self, request, pk=None): ... + +A refusal is recorded under the action that was attempted, with its outcome +and reason derived from the response status. +""" + +import logging +from collections.abc import Mapping +from typing import Any + +from .actions import Action +from .emitter import EVENT_FIELDS, log +from .enums import EventCategory, EventType, Outcome, Reason +from .utils import exception_type + +ACTION_TYPES = { + "create": EventType.CREATION, + "update": EventType.CHANGE, + "partial_update": EventType.CHANGE, + "destroy": EventType.DELETION, + "retrieve": EventType.ACCESS, + "list": EventType.ACCESS, +} +STATUS_REASONS = { + 400: Reason.VALIDATION_ERROR, + 401: Reason.AUTHENTICATION_FAILED, + 403: Reason.PERMISSION_DENIED, + 404: Reason.NOT_FOUND, + 409: Reason.CONFLICT, + 429: Reason.RATE_LIMITED, +} +DENIED_STATUSES = frozenset({401, 403, 429}) + +_logger = logging.getLogger(__name__) + + +def error_message(response) -> Any: + """Return the message of an error response, as DRF or the view wrote it.""" + data = getattr(response, "data", None) + if isinstance(data, Mapping): + return data.get("detail") or data.get("error") + return None + + +class AuditViewMixin: + """Emit one audit event per response of an audited action. + + ``audit_actions`` maps the CRUD actions only. An extra action is audited + by passing ``audit_action`` to its ``@action`` decorator. + + While handling a request, a view may *assign* ``audit_target``, + ``audit_actor`` and ``audit_details``; ``check_object_permissions`` sets + the target on its own, before a refusal can happen. A detail named after + an event field, as ``outcome`` or ``request``, is dropped: overriding one + is done in ``get_audit_fields``. + """ + + audit_actions: Mapping[str, Action | str] = {} + # Only declared so the router may pass the ``@action`` keyword arguments + # to ``as_view``; the action is read from the handler of the request. + audit_action: Action | str | None = None + audit_target: Any = None + audit_actor: Any = None + audit_details: Mapping[str, Any] | None = None + + def __init_subclass__(cls, **kwargs): + """Refuse extra actions in ``audit_actions``, keyed by a method name.""" + super().__init_subclass__(**kwargs) + if extra := sorted(set(cls.audit_actions) - set(ACTION_TYPES)): + raise TypeError( + f"{cls.__qualname__}.audit_actions only maps CRUD actions: " + f"audit {', '.join(extra)} with @action(audit_action=...)" + ) + + def check_object_permissions(self, request, obj): + """Remember the object as the target.""" + self.audit_target = obj + super().check_object_permissions(request, obj) + + def finalize_response(self, request, response, *args, **kwargs): + """Audit the response once DRF has built it.""" + response = super().finalize_response(request, response, *args, **kwargs) + self.emit_audit_event(request, response.status_code, error_message(response)) + return response + + def handle_exception(self, exc): + """Audit an exception DRF cannot turn into a response, then let it propagate. + + Only its class is recorded since its message could carry personal data. + """ + try: + return super().handle_exception(exc) + except Exception as error: + self.emit_audit_event(self.request, 500, error_type=exception_type(error)) + raise + + def get_audit_action(self) -> Action | str | None: + """Return what the current request audits, if anything. + + An extra action is read from its handler, so a request that reaches + none, as an OPTIONS request or a refused method, audits nothing. + """ + name = getattr(self, "action", None) + if name in ACTION_TYPES: + return self.audit_actions.get(name) + handler = getattr(self, name, None) if name else None + return getattr(handler, "kwargs", {}).get("audit_action") + + def emit_audit_event(self, request, status_code, error=None, error_type=None): + """Emit the event of the current action, if it is audited. + + Never raises: a response must not fail because it could not be audited. + """ + try: + action = self.get_audit_action() + if action is not None: + fields = self.get_audit_fields(status_code, error) + log(action, request=request, error_type=error_type, **fields) + except Exception: # pylint: disable=broad-exception-caught + _logger.exception("Audit event of %s could not be emitted", request.path) + + def get_audit_fields(self, status_code, error=None) -> dict[str, Any]: + """Return the fields of the event for a response of ``status_code``. + + The category and types of the ``Action`` win over those derived from + the DRF action. + """ + action = self.get_audit_action() + category, types = None, [] + if isinstance(action, Action): + category, types = action.category, list(action.types) + details = { + key: value + for key, value in (self.audit_details or {}).items() + if key not in EVENT_FIELDS + } + fields = { + **details, + "category": category or EventCategory.API, + "types": types + or [ACTION_TYPES.get(getattr(self, "action", None), EventType.INFO)], + "target": self.audit_target, + "actor": self.audit_actor, + } + if status_code >= 400: + fields |= { + "outcome": ( + Outcome.DENIED + if status_code in DENIED_STATUSES + else Outcome.FAILURE + ), + "reason": STATUS_REASONS.get( + status_code, Reason.INTERNAL_ERROR if status_code >= 500 else None + ), + "status_code": status_code, + "error": error, + } + if status_code == 401: + fields["category"] = EventCategory.AUTHENTICATION + return fields diff --git a/src/backend/core/audit/emitter.py b/src/backend/core/audit/emitter.py new file mode 100644 index 00000000..e1b307a6 --- /dev/null +++ b/src/backend/core/audit/emitter.py @@ -0,0 +1,159 @@ +"""Build ECS audit documents and emit them on the ``audit`` logger.""" + +import inspect +import logging +from datetime import datetime, timezone +from typing import Any + +from django.conf import settings + +from .actions import Action +from .actor import describe_actor +from .enums import ActorType, EventCategory, EventType, Outcome, Reason +from .request import current_request, current_request_id, resolve_client_ip +from .targets import describe_target +from .utils import prune_empty, render_value + +AUDIT_LOGGER_NAME = "audit" +ECS_VERSION = "8.11.0" +LOG_TYPE = "audit" + +_audit_logger = logging.getLogger(AUDIT_LOGGER_NAME) +_logger = logging.getLogger(__name__) + + +def log(action: Action | str, **fields: Any) -> None: + """Emit one audit event.""" + try: + document = build_document(action, **fields) + except Exception: # pylint: disable=broad-exception-caught + _logger.exception("Audit event %r could not be built", action) + return + + _audit_logger.log( + level_for(document["lasuite"]["outcome"], document["event"].get("reason")), + str(action), + extra={"audit": document}, + ) + + +def level_for(outcome: Outcome | str, reason: Reason | str | None) -> int: + """Derive the logging level so call sites never choose one.""" + if Outcome(outcome) == Outcome.SUCCESS: + return logging.INFO + if reason is not None and Reason(reason) == Reason.INTERNAL_ERROR: + return logging.ERROR + return logging.WARNING + + +def build_document( # noqa: PLR0913 # pylint: disable=too-many-arguments,too-many-locals + action: Action | str, + *, + request: Any = None, + outcome: Outcome | str = Outcome.SUCCESS, + reason: Reason | str | None = None, + category: EventCategory | str | None = None, + types: list[EventType | str] | None = None, + target: Any = None, + actor: Any = None, + actor_type: ActorType | str | None = None, + auth_method: str | None = None, + client_id: str | None = None, + status_code: int | None = None, + error: Any = None, + error_type: str | None = None, + message: str | None = None, + **details: Any, +) -> dict[str, Any]: + """Return the ECS document of an event, pruned of empty values. + + ``action`` is what was attempted: an ``Action``, whose category and types + apply unless given here, or a bare dotted name (``room.create``). + The actor, auth method and network fields are read from ``request``, by + default the request being served. + ``actor``, ``actor_type``, ``auth_method`` and ``client_id`` override them. + ``target`` is the resource acted on. Any other keyword argument lands under + ``lasuite.details``. + """ + if request is None: + request = current_request() + outcome = Outcome(outcome) + reason = Reason(reason) if reason is not None else None + if isinstance(action, Action): + category = category or action.category + types = types or list(action.types) + client_ip = resolve_client_ip(request) if request is not None else None + actor_fields = describe_actor( + request, + actor=actor, + actor_type=actor_type, + client_id=client_id, + auth_method=auth_method, + ) + + return prune_empty( + { + "@timestamp": datetime.now(timezone.utc).isoformat(timespec="milliseconds"), + "ecs": {"version": ECS_VERSION}, + "log_type": LOG_TYPE, + "message": message, + "service": { + "name": getattr(settings, "AUDIT_LOG_SERVICE_NAME", None), + "environment": getattr(settings, "ENVIRONMENT", None), + }, + "event": _event_fields(action, outcome, reason, category, types), + "trace": {"id": current_request_id()}, + "client": {"ip": client_ip}, + "source": {"ip": client_ip}, + "http": { + "request": {"method": getattr(request, "method", None)}, + "response": {"status_code": status_code}, + }, + "url": {"path": getattr(request, "path", None) or None}, + "user": actor_fields["user"], + "organization": actor_fields["organization"], + "lasuite": { + **actor_fields["lasuite"], + "outcome": str(outcome), + "target": describe_target(target) if target is not None else None, + "details": render_value(details), + }, + "error": { + "message": str(error) if error is not None else None, + "type": error_type, + }, + } + ) + + +# The keyword arguments of ``log`` that fill an event field rather than a detail +EVENT_FIELDS = frozenset( + name + for name, parameter in inspect.signature(build_document).parameters.items() + if parameter.kind is inspect.Parameter.KEYWORD_ONLY +) + + +def _event_fields(action, outcome, reason, category, types) -> dict[str, Any]: + type_list = [str(EventType(item)) for item in (types or [])] + if not type_list: + type_list = [str(_default_type(outcome))] + if outcome == Outcome.DENIED and str(EventType.DENIED) not in type_list: + type_list.append(str(EventType.DENIED)) + + return { + "kind": "event", + "action": str(action), + "category": [str(EventCategory(category or EventCategory.WEB))], + "type": type_list, + "outcome": "success" if outcome == Outcome.SUCCESS else "failure", + "reason": str(reason) if reason is not None else None, + } + + +def _default_type(outcome: Outcome) -> EventType: + if outcome == Outcome.SUCCESS: + return EventType.INFO + if outcome == Outcome.DENIED: + return EventType.DENIED + return EventType.ERROR diff --git a/src/backend/core/audit/enums.py b/src/backend/core/audit/enums.py new file mode 100644 index 00000000..9cd35669 --- /dev/null +++ b/src/backend/core/audit/enums.py @@ -0,0 +1,74 @@ +"""ECS enums shared by every audit event.""" + +from enum import StrEnum + + +class Outcome(StrEnum): + """Whether the audited action succeeded, failed, or was refused.""" + + SUCCESS = "success" + FAILURE = "failure" + DENIED = "denied" + + +class Reason(StrEnum): + """Why an action did not succeed.""" + + AUTHENTICATION_FAILED = "authentication_failed" + PERMISSION_DENIED = "permission_denied" + RATE_LIMITED = "rate_limited" + VALIDATION_ERROR = "validation_error" + NOT_FOUND = "not_found" + CONFLICT = "conflict" + INTERNAL_ERROR = "internal_error" + + +class ActorType(StrEnum): + """Kind of principal behind an action. + + ``user.*`` is the account whose authority the action used: the actor for + ``user``, the delegating user for ``application``, absent otherwise. + """ + + # A person's account acting for itself. + USER = "user" + # A client application acting on behalf of a user, named by its client id. + APPLICATION = "application" + # An internal peer of the deployment acting on its own behalf with a + # shared secret, named by ``lasuite.actor.name``. Never an account. + SERVICE = "service" + # The backend itself, with no inbound request. + SYSTEM = "system" + # A caller that did not authenticate, or failed to. + ANONYMOUS = "anonymous" + + +class EventCategory(StrEnum): + """Subset of the ECS ``event.category`` .""" + + API = "api" + AUTHENTICATION = "authentication" + CONFIGURATION = "configuration" + EMAIL = "email" + FILE = "file" + IAM = "iam" + SESSION = "session" + WEB = "web" + + +class EventType(StrEnum): + """Subset of the ECS ``event.type``.""" + + ACCESS = "access" + ADMIN = "admin" + ALLOWED = "allowed" + CHANGE = "change" + CREATION = "creation" + DELETION = "deletion" + DENIED = "denied" + END = "end" + ERROR = "error" + GROUP = "group" + INFO = "info" + START = "start" + USER = "user" diff --git a/src/backend/core/audit/formatter.py b/src/backend/core/audit/formatter.py new file mode 100644 index 00000000..03952534 --- /dev/null +++ b/src/backend/core/audit/formatter.py @@ -0,0 +1,35 @@ +"""Render audit records as single-line ECS JSON format.""" + +import json +import logging +from datetime import datetime, timezone +from typing import Any + + +class AuditJsonFormatter(logging.Formatter): + """Serialise the document attached to the record under ``audit`` in ECS format.""" + + def format(self, record: logging.LogRecord) -> str: + document = getattr(record, "audit", None) + if not isinstance(document, dict): + document = { + "@timestamp": datetime.fromtimestamp( + record.created, tz=timezone.utc + ).isoformat(timespec="milliseconds"), + "log_type": "audit", + "message": record.getMessage(), + "event": {"action": record.getMessage()}, + } + + document = { + **document, + "log": {"level": record.levelname.lower(), "logger": record.name}, + } + if record.exc_info: + error: dict[str, Any] = dict(document.get("error") or {}) + error["stack_trace"] = self.formatException(record.exc_info) + document["error"] = error + + return json.dumps( + document, ensure_ascii=False, default=str, separators=(",", ":") + ) diff --git a/src/backend/core/audit/registry.py b/src/backend/core/audit/registry.py new file mode 100644 index 00000000..e682cc44 --- /dev/null +++ b/src/backend/core/audit/registry.py @@ -0,0 +1,76 @@ +"""Declare what audit events may say about models and authentication classes. + +The project registers them from an ``auditing`` module in one of its apps, +imported once the audit app is ready:: + + audit.register(Room, fields=("slug", "access_level")) # describe the target + audit.register_auth_method(ApplicationJWTAuthentication, "application_jwt") + +A target is always identified by its model name and primary key, so a model +that is not registered is still identifiable, just less detailed. +""" + +from dataclasses import dataclass + +from django.db.models import Model + + +class AlreadyRegistered(Exception): + """A model or an authentication class that was registered twice.""" + + +@dataclass(frozen=True) +class ModelOptions: + """What audit events may say about a model. + + ``fields`` describe the model when it is the target of an event. + """ + + fields: tuple[str, ...] = () + + +_models: dict[type[Model], ModelOptions] = {} +_auth_methods: dict[str, str] = {} + + +def register(model: type[Model], *, fields=()) -> None: + """Declare what audit events may say about ``model``.""" + if model in _models: + raise AlreadyRegistered(f"{model._meta.label} is already registered") # noqa: SLF001 + _models[model] = ModelOptions(fields=tuple(fields)) + + +def unregister(model: type[Model]) -> ModelOptions | None: + """Forget ``model`` and return what was registered for it, if anything.""" + return _models.pop(model, None) + + +def model_options(model: type[Model]) -> ModelOptions: + """Return what is registered for a model, or for its concrete model.""" + for klass in (model, model._meta.concrete_model): # noqa: SLF001 + if (options := _models.get(klass)) is not None: + return options + return ModelOptions() + + +def dotted_path(klass: type) -> str: + """Return the dotted path Django and DRF name a class by.""" + return f"{klass.__module__}.{klass.__qualname__}" + + +def register_auth_method(klass: type, name: str) -> None: + """Name the ``lasuite.auth.method`` of a DRF authentication class or a login backend. + + A DRF class is also the default of its subclasses. A login backend must be + registered itself: custom backends often subclass ``ModelBackend`` only for + its permission checks, and must not pass for password logins. + """ + path = dotted_path(klass) + if path in _auth_methods: + raise AlreadyRegistered(f"{path} is already registered") + _auth_methods[path] = name + + +def auth_methods() -> dict[str, str]: + """Return the registered auth methods, keyed by dotted path.""" + return dict(_auth_methods) diff --git a/src/backend/core/audit/request.py b/src/backend/core/audit/request.py new file mode 100644 index 00000000..0e24d02a --- /dev/null +++ b/src/backend/core/audit/request.py @@ -0,0 +1,76 @@ +"""Read the network fields and the request id behind an audit event.""" + +import uuid +from contextvars import ContextVar, Token + +from django.conf import settings + +from dockerflow.logging import request_id_context +from rest_framework.throttling import BaseThrottle + +_current_request: ContextVar = ContextVar("audit_request", default=None) + + +def current_request(): + """Return the request being served, if any, as set by ``AuditLogMiddleware``. + + It is the Django request: DRF copies its user and auth onto it, but not its + authenticator, so the auth method of a DRF view is not known from it. + """ + return _current_request.get() + + +def set_current_request(request) -> Token: + """Make ``request`` the request being served, until the token is reset.""" + return _current_request.set(request) + + +def reset_current_request(token: Token) -> None: + """Restore the request that was current before ``set_current_request``.""" + _current_request.reset(token) + + +def current_request_id() -> str | None: + """Return the id of the request being served, if any.""" + return request_id_context.get(None) + + +def resolve_client_ip(request) -> str | None: + """Return the address of the real client, never the one of a proxy. + + It reuses DRF's throttles to identify the client. + """ + return BaseThrottle().get_ident(request) or request.META.get("REMOTE_ADDR") + + +class AuditLogMiddleware: + """Settle the request id and the current request, then echo the id. + + It must come right after ``DockerflowMiddleware``, which sets the id from + the inbound ``DOCKERFLOW_REQUEST_ID_HEADER_NAME`` header. Unless + ``REQUEST_ID_TRUST_HEADER`` says the ingress overwrites that header, the id + is replaced by a fresh one before anything logs, so that a client, the web + server access log and the audit events of a request can be joined on an id + the client did not choose. + + The request is kept as the current one while it is served, so that an + audit event emitted far from the view, as from a service, still reads its + actor and network fields from it. + """ + + def __init__(self, get_response): + self.get_response = get_response + + def __call__(self, request): + if not settings.REQUEST_ID_TRUST_HEADER: + request_id_context.set(str(uuid.uuid4())) + + token = set_current_request(request) + try: + response = self.get_response(request) + finally: + reset_current_request(token) + header = settings.DOCKERFLOW_REQUEST_ID_HEADER_NAME + if not response.has_header(header): + response[header] = current_request_id() + return response diff --git a/src/backend/core/audit/signals.py b/src/backend/core/audit/signals.py new file mode 100644 index 00000000..327aa3a9 --- /dev/null +++ b/src/backend/core/audit/signals.py @@ -0,0 +1,85 @@ +"""Audit Django's authentication signals: login, failed login, logout.""" + +from django.contrib.auth import BACKEND_SESSION_KEY +from django.contrib.auth.signals import ( + user_logged_in, + user_logged_out, + user_login_failed, +) + +from .actions import Action +from .actor import AUTH_METHOD_UNKNOWN, auth_method_for_backend +from .emitter import log +from .enums import ActorType, EventCategory, EventType, Outcome, Reason + +LOGIN_ACTION = Action( + "user.login", category=EventCategory.AUTHENTICATION, types=(EventType.START,) +) +LOGOUT_ACTION = Action( + "user.logout", category=EventCategory.AUTHENTICATION, types=(EventType.END,) +) + + +def get_login_backend(request, user) -> str | None: + """Return the dotted path of the backend a login went through.""" + session = getattr(request, "session", None) + from_session = session.get(BACKEND_SESSION_KEY) if session is not None else None + return from_session or getattr(user, "backend", None) + + +def auth_method_from_credentials(credentials) -> str: + """Name the mechanism of a failed login from the credentials it submitted.""" + if "password" in credentials: + return "password" + if "nonce" in credentials: + return "oidc" + return AUTH_METHOD_UNKNOWN + + +def on_user_logged_in(sender, request, user, **kwargs): # pylint: disable=unused-argument + """Record a successful login.""" + backend = get_login_backend(request, user) + log( + LOGIN_ACTION, + request=request, + actor=user, + auth_method=auth_method_for_backend(backend), + auth_backend=backend, + ) + + +def on_user_login_failed(sender, credentials, request, **kwargs): # pylint: disable=unused-argument + """Record a failed login. + + It is a refusal, like a 401 on the API, whether the credentials were + rejected or a backend raised ``PermissionDenied``. Its actor is anonymous + even without a request, as when ``authenticate`` is called without one. + """ + log( + LOGIN_ACTION, + outcome=Outcome.DENIED, + reason=Reason.AUTHENTICATION_FAILED, + request=request, + actor_type=ActorType.ANONYMOUS, + auth_method=auth_method_from_credentials(credentials), + ) + + +def on_user_logged_out(sender, request, user, **kwargs): # pylint: disable=unused-argument + """Record a logout, unless no one was signed in.""" + if user is None: + return + log( + LOGOUT_ACTION, + request=request, + actor=user, + ) + + +def connect_auth_signals() -> None: + """Connect the receivers to authentication signal.""" + user_logged_in.connect(on_user_logged_in, dispatch_uid="audit.user_logged_in") + user_login_failed.connect( + on_user_login_failed, dispatch_uid="audit.user_login_failed" + ) + user_logged_out.connect(on_user_logged_out, dispatch_uid="audit.user_logged_out") diff --git a/src/backend/core/audit/targets.py b/src/backend/core/audit/targets.py new file mode 100644 index 00000000..088c0e98 --- /dev/null +++ b/src/backend/core/audit/targets.py @@ -0,0 +1,48 @@ +"""Describe the resource an audit event is about. + +The fields describing each model are those registered for it, see +``core.audit.registry``. A target is always identified by its model name and +primary key, so a model that is not registered is still identifiable, just +less detailed. +""" + +import logging +from collections.abc import Mapping +from typing import Any + +from django.contrib.auth import get_user_model +from django.db.models import Model + +from .actor import describe_user +from .registry import model_options +from .utils import render_value + +_logger = logging.getLogger(__name__) + + +def describe_target(obj: Any) -> dict[str, Any]: + """Return ``{"type": ..., "id": ..., **fields}`` for a target. + + A user will carries its OIDC sub and its email domain. + A registered field that cannot be read is left out and simply reported. + """ + if isinstance(obj, Mapping): + return dict(obj) + if not isinstance(obj, Model): + return {"type": obj.__class__.__name__.lower(), "id": str(obj)} + + meta = obj._meta # noqa: SLF001 + document: dict[str, Any] = { + "type": meta.model_name, + "id": str(obj.pk) if obj.pk is not None else None, + } + for name in model_options(meta.model).fields: + try: + document[name] = render_value(getattr(obj, name)) + except Exception: # pylint: disable=broad-exception-caught + _logger.exception( + "Audit field %r of %s could not be read", name, meta.label + ) + if isinstance(obj, get_user_model()): + document |= describe_user(obj) + return document diff --git a/src/backend/core/audit/testing.py b/src/backend/core/audit/testing.py new file mode 100644 index 00000000..3346506f --- /dev/null +++ b/src/backend/core/audit/testing.py @@ -0,0 +1,62 @@ +"""Helpers for asserting on audit events in tests.""" + +import logging +from collections.abc import Iterator +from contextlib import contextmanager +from dataclasses import asdict +from typing import Any + +from . import registry +from .actions import Action +from .emitter import AUDIT_LOGGER_NAME + + +class _CollectingHandler(logging.Handler): + """Keep the documents attached to the records it receives.""" + + def __init__(self): + super().__init__(level=logging.DEBUG) + self.documents: list[dict[str, Any]] = [] + + def emit(self, record: logging.LogRecord) -> None: + document = getattr(record, "audit", None) + if not isinstance(document, dict): + document = {"message": record.getMessage()} + self.documents.append({**document, "log": {"level": record.levelname.lower()}}) + + +@contextmanager +def capture_audit() -> Iterator[list[dict[str, Any]]]: + """Collect the audit documents emitted inside the block""" + logger = logging.getLogger(AUDIT_LOGGER_NAME) + handler = _CollectingHandler() + previous_level = logger.level + logger.addHandler(handler) + logger.setLevel(logging.DEBUG) + try: + yield handler.documents + finally: + logger.removeHandler(handler) + logger.setLevel(previous_level) + + +def find_events( + events: list[dict[str, Any]], action: Action | str +) -> list[dict[str, Any]]: + """Return the captured events whose ``event.action`` is ``action``.""" + return [ + event for event in events if event.get("event", {}).get("action") == str(action) + ] + + +@contextmanager +def override_registration(model, **options) -> Iterator[None]: + """Register ``model`` with ``options`` inside the block, whatever it was before.""" + previous = registry.unregister(model) + registry.register(model, **options) + try: + yield + finally: + registry.unregister(model) + if previous is not None: + registry.register(model, **asdict(previous)) diff --git a/src/backend/core/audit/utils.py b/src/backend/core/audit/utils.py new file mode 100644 index 00000000..bbba2c72 --- /dev/null +++ b/src/backend/core/audit/utils.py @@ -0,0 +1,48 @@ +"""Value helpers used to assemble audit logs.""" + +from collections.abc import Mapping +from enum import Enum +from typing import Any + +from django.db.models import Model, QuerySet + + +def render_value(value: Any) -> Any: + """Render a value as something stable and JSON-friendly. + + Model instances are reduced to their primary key, enums to their value. + """ + if isinstance(value, Model): + return str(value.pk) + if isinstance(value, Enum): + return value.value + if isinstance(value, Mapping): + return {str(key): render_value(item) for key, item in value.items()} + if isinstance(value, (QuerySet, list, tuple, set, frozenset)): + return [render_value(item) for item in value] + if value is None or isinstance(value, (bool, int, float, str)): + return value + return str(value) + + +def exception_type(error: BaseException) -> str: + """Return the dotted name of an exception's class. + + Audit events record it rather than the message, which may carry personal + data. + """ + error_class = type(error) + return f"{error_class.__module__}.{error_class.__qualname__}" + + +def prune_empty(value: Any) -> Any: + """Drop ``None`` values and empty mappings, recursively.""" + if not isinstance(value, Mapping): + return value + pruned = {} + for key, item in value.items(): + cleaned = prune_empty(item) + if cleaned is None or (isinstance(cleaned, dict) and not cleaned): + continue + pruned[key] = cleaned + return pruned diff --git a/src/backend/core/auditing.py b/src/backend/core/auditing.py new file mode 100644 index 00000000..7dff995a --- /dev/null +++ b/src/backend/core/auditing.py @@ -0,0 +1,33 @@ +"""What Meet audits, and what its audit events may say. + +Imported by the audit app once it is ready, see ``core.audit.apps``. +""" + +from lasuite.oidc_resource_server.authentication import ResourceServerAuthentication + +from core import audit, models +from core.authentication.backends import OIDCAuthenticationBackend +from core.authentication.livekit import LiveKitTokenAuthentication +from core.external_api.authentication import ( + AddonsJWTAuthentication, + ApplicationJWTAuthentication, +) +from core.recording.event.authentication import HeaderBasedAuthentication +from core.roomkit.authentication import ServerToServerAuthentication + +# Models + +audit.register(models.Application, fields=("client_id", "name", "is_active", "scopes")) +audit.register(models.ResourceAccess, fields=("resource_id", "user_id", "role")) +audit.register(models.Room, fields=("slug", "name", "access_level")) +audit.register(models.Recording, fields=("room_id", "status", "mode")) + +# Authentication classes and login backends -> ``lasuite.auth.method`` + +audit.register_auth_method(OIDCAuthenticationBackend, "oidc") +audit.register_auth_method(ApplicationJWTAuthentication, "application_jwt") +audit.register_auth_method(AddonsJWTAuthentication, "addons_jwt") +audit.register_auth_method(ResourceServerAuthentication, "resource_server") +audit.register_auth_method(LiveKitTokenAuthentication, "livekit_token") +audit.register_auth_method(HeaderBasedAuthentication, "shared_secret") +audit.register_auth_method(ServerToServerAuthentication, "shared_secret") diff --git a/src/backend/core/recording/event/authentication.py b/src/backend/core/recording/event/authentication.py index c68d79c8..997ad0d1 100644 --- a/src/backend/core/recording/event/authentication.py +++ b/src/backend/core/recording/event/authentication.py @@ -40,6 +40,8 @@ class HeaderBasedAuthentication(BaseAuthentication): AUTH_HEADER = "Authorization" TOKEN_TYPE = "Bearer" # noqa S105 REALM = "" + # Names the service in the audit log + MACHINE_USER_NAME = "machine_user" EXPECTED_TOKEN_SETTINGS_KEY = None @@ -74,7 +76,7 @@ class HeaderBasedAuthentication(BaseAuthentication): ) raise AuthenticationFailed("Invalid token") - return MachineUser(), token + return MachineUser(self.MACHINE_USER_NAME), token def authenticate_header(self, request): """Return the WWW-Authenticate header value.""" @@ -88,4 +90,5 @@ class RecordingProcessWebhookAuthentication(HeaderBasedAuthentication): """ REALM = "External process webhook API" + MACHINE_USER_NAME = "summary" EXPECTED_TOKEN_SETTINGS_KEY = "SUMMARY_SERVICE_WEBHOOK_API_TOKEN" # noqa S105 diff --git a/src/backend/core/tests/audit/__init__.py b/src/backend/core/tests/audit/__init__.py new file mode 100644 index 00000000..52e3a62e --- /dev/null +++ b/src/backend/core/tests/audit/__init__.py @@ -0,0 +1 @@ +"""Tests for the audit logging facility.""" diff --git a/src/backend/core/tests/audit/test_drf.py b/src/backend/core/tests/audit/test_drf.py new file mode 100644 index 00000000..6f8d8604 --- /dev/null +++ b/src/backend/core/tests/audit/test_drf.py @@ -0,0 +1,363 @@ +"""Tests for the audit of DRF views through ``AuditViewMixin``.""" + +# pylint: disable=missing-function-docstring,unused-argument + +from unittest import mock + +from django.core.exceptions import PermissionDenied as DjangoPermissionDenied + +import pytest +from rest_framework import ( + decorators, + exceptions, + mixins, + permissions, + routers, + viewsets, +) +from rest_framework.response import Response +from rest_framework.test import APIRequestFactory + +from core import audit, models +from core.audit.testing import find_events +from core.authentication.backends import SessionAuthenticationWith401 +from core.factories import RoomFactory + +pytestmark = pytest.mark.django_db + + +class ThingViewSet(audit.AuditViewMixin, viewsets.ViewSet): + """A viewset auditing ``list`` and ``create`` but not ``destroy``.""" + + authentication_classes = [SessionAuthenticationWith401] + permission_classes = [] + audit_actions = {"list": "thing.list", "create": "thing.create"} + error = None + + def list(self, request): + if self.error is not None: + raise self.error + self.audit_details = {"total": 3} + return Response([]) + + def create(self, request): + return Response({"error": "Already exists."}, status=409) + + def destroy(self, request, pk=None): + return Response(status=204) + + +class RoomViewSet( + audit.AuditViewMixin, mixins.RetrieveModelMixin, viewsets.GenericViewSet +): + """A viewset whose target comes from ``get_object``.""" + + authentication_classes = [] + permission_classes = [] + queryset = models.Room.objects.all() + audit_actions = {"retrieve": "room.retrieve"} + + def get_serializer(self, *args, **kwargs): + return type("Serializer", (), {"data": {}})() + + +GRANT = audit.Action( + "thing.grant", + category=audit.EventCategory.IAM, + types=(audit.EventType.CREATION,), +) + + +class GrantViewSet(audit.AuditViewMixin, viewsets.ViewSet): + """A viewset whose extra action declares its audit on the route.""" + + authentication_classes = [SessionAuthenticationWith401] + permission_classes = [] + error = None + + @decorators.action(detail=False, methods=["post"], audit_action=GRANT) + def grant(self, request): + if self.error is not None: + raise self.error + return Response({}) + + @decorators.action(detail=False, methods=["post"]) + def ping(self, request): + return Response({}) + + +class ListingViewSet(ThingViewSet): + """A ``ThingViewSet`` keeping the details it was built with.""" + + def list(self, request): + return Response([]) + + +class DenyObjects(permissions.BasePermission): + """Refuse every object, whatever the request.""" + + def has_object_permission(self, request, view, obj): + return False + + +def test_success_is_audited_with_the_view_details(audit_events): + """A successful action is recorded with its type and the view's details.""" + view = ThingViewSet.as_view({"get": "list"}) + + response = view(APIRequestFactory().get("/things/", REMOTE_ADDR="1.2.3.4")) + + assert response.status_code == 200 + + [event] = find_events(audit_events, "thing.list") + + assert event["event"]["category"] == ["api"] + assert event["event"]["type"] == ["access"] + assert event["event"]["outcome"] == "success" + assert event["lasuite"]["details"] == {"total": 3} + assert event["client"] == {"ip": "1.2.3.4"} + assert event["url"] == {"path": "/things/"} + assert event["http"] == {"request": {"method": "GET"}} + + +def test_missing_credentials_are_audited_as_authentication_denial(audit_events): + """A 401 is a denial in the authentication category.""" + view = ThingViewSet.as_view({"get": "list"}, error=exceptions.NotAuthenticated()) + + response = view(APIRequestFactory().get("/things/")) + + assert response.status_code == 401 + + [event] = find_events(audit_events, "thing.list") + + assert event["event"]["category"] == ["authentication"] + assert event["event"]["type"] == ["access", "denied"] + assert event["event"]["reason"] == "authentication_failed" + assert event["lasuite"]["outcome"] == "denied" + assert event["lasuite"]["actor"] == {"type": "anonymous"} + assert event["http"]["response"] == {"status_code": 401} + assert event["error"]["message"] == "Authentication credentials were not provided." + assert event["log"]["level"] == "warning" + assert "details" not in event["lasuite"] + + +@pytest.mark.parametrize( + "error,status_code,outcome,reason", + [ + ( + exceptions.AuthenticationFailed("bad"), + 401, + "denied", + "authentication_failed", + ), + (exceptions.PermissionDenied("scope"), 403, "denied", "permission_denied"), + (DjangoPermissionDenied("nope"), 403, "denied", "permission_denied"), + (exceptions.Throttled(wait=10), 429, "denied", "rate_limited"), + ( + exceptions.ValidationError({"name": ["x"]}), + 400, + "failure", + "validation_error", + ), + (exceptions.NotFound(), 404, "failure", "not_found"), + (exceptions.MethodNotAllowed("PUT"), 405, "failure", None), + ], +) +def test_errors_are_audited_from_the_status_code( + audit_events, error, status_code, outcome, reason +): + """The outcome and the reason are derived from the response status.""" + view = ThingViewSet.as_view({"get": "list"}, error=error) + + response = view(APIRequestFactory().get("/things/")) + + assert response.status_code == status_code + + [event] = find_events(audit_events, "thing.list") + + assert event["lasuite"]["outcome"] == outcome + assert event["event"].get("reason") == reason + assert event["http"]["response"] == {"status_code": status_code} + + +def test_error_message_of_a_view_response(audit_events): + """An error response built by the view reports its ``error`` message.""" + view = ThingViewSet.as_view({"post": "create"}) + + response = view(APIRequestFactory().post("/things/")) + + assert response.status_code == 409 + + [event] = find_events(audit_events, "thing.create") + + assert event["event"]["type"] == ["creation"] + assert event["event"]["reason"] == "conflict" + assert event["lasuite"]["outcome"] == "failure" + assert event["error"] == {"message": "Already exists."} + + +def test_actions_missing_from_the_map_are_not_audited(audit_events): + """Only the actions listed in ``audit_actions`` emit events.""" + view = ThingViewSet.as_view({"delete": "destroy"}) + + response = view(APIRequestFactory().delete("/things/1/"), pk="1") + + assert response.status_code == 204 + assert audit_events == [] + + +def test_unhandled_exception_is_audited_as_internal_error(audit_events): + """An exception DRF does not handle is recorded, by class only, then raised.""" + view = ThingViewSet.as_view( + {"get": "list"}, error=RuntimeError("user@example.com is broken") + ) + + with pytest.raises(RuntimeError): + view(APIRequestFactory().get("/things/")) + + [event] = find_events(audit_events, "thing.list") + + assert event["event"]["type"] == ["access"] + assert event["event"]["reason"] == "internal_error" + assert event["lasuite"]["outcome"] == "failure" + assert event["http"]["response"] == {"status_code": 500} + assert event["error"] == {"type": "builtins.RuntimeError"} + assert event["log"]["level"] == "error" + assert "user@example.com" not in str(event) + + +def test_object_permission_denial_keeps_the_target(audit_events): + """A refusal on a detail route names the object that was refused.""" + room = RoomFactory() + view = RoomViewSet.as_view({"get": "retrieve"}, permission_classes=[DenyObjects]) + + response = view(APIRequestFactory().get(f"/rooms/{room.pk}/"), pk=str(room.pk)) + + assert response.status_code == 403 + + [event] = find_events(audit_events, "room.retrieve") + + assert event["lasuite"]["outcome"] == "denied" + assert event["lasuite"]["target"]["id"] == str(room.pk) + + +def test_object_of_a_detail_route_is_the_target(audit_events): + """The object of a detail route becomes the target of the event.""" + room = RoomFactory() + view = RoomViewSet.as_view({"get": "retrieve"}) + + response = view(APIRequestFactory().get(f"/rooms/{room.pk}/"), pk=str(room.pk)) + + assert response.status_code == 200 + + [event] = find_events(audit_events, "room.retrieve") + + assert event["lasuite"]["target"]["id"] == str(room.pk) + assert event["lasuite"]["target"]["type"] == "room" + + +def test_extra_actions_cannot_be_mapped_by_method_name(): + """Renaming a method must not silently stop auditing it.""" + with pytest.raises(TypeError, match="grant"): + + class MappedViewSet(audit.AuditViewMixin, viewsets.ViewSet): # pylint: disable=unused-variable + """Maps an extra action in ``audit_actions``.""" + + audit_actions = {"list": "thing.list", "grant": "thing.grant"} + + +def test_extra_action_is_audited_from_its_route(audit_events): + """The ``audit_action`` of a routed ``@action`` names the event.""" + router = routers.SimpleRouter() + router.register("things", GrantViewSet, basename="thing") + [route] = [url for url in router.urls if url.name == "thing-grant"] + + response = route.callback(APIRequestFactory().post("/things/grant/")) + + assert response.status_code == 200 + + [event] = find_events(audit_events, GRANT) + + assert event["event"]["category"] == ["iam"] + assert event["event"]["type"] == ["creation"] + + +def test_extra_action_is_audited_without_a_router(audit_events): + """A view built by hand reads ``audit_action`` from its handler.""" + view = GrantViewSet.as_view({"post": "grant"}) + + response = view(APIRequestFactory().post("/things/grant/")) + + assert response.status_code == 200 + assert len(find_events(audit_events, GRANT)) == 1 + + +def test_extra_action_without_audit_action_is_not_audited(audit_events): + """An ``@action`` that does not name an audit action emits nothing.""" + view = GrantViewSet.as_view({"post": "ping"}) + + response = view(APIRequestFactory().post("/things/ping/")) + + assert response.status_code == 200 + assert audit_events == [] + + +def test_unauthenticated_extra_action_is_an_authentication_denial(audit_events): + """A 401 still files the event under ``authentication``, whatever the spec.""" + view = GrantViewSet.as_view({"post": "grant"}, error=exceptions.NotAuthenticated()) + + response = view(APIRequestFactory().post("/things/grant/")) + + assert response.status_code == 401 + + [event] = find_events(audit_events, GRANT) + + assert event["event"]["category"] == ["authentication"] + assert event["event"]["type"] == ["creation", "denied"] + + +@pytest.mark.parametrize("method", ["options", "get"]) +def test_requests_reaching_no_extra_action_are_not_audited(audit_events, method): + """An OPTIONS request, or a method the route refuses, audits nothing. + + The router hands the route's ``audit_action`` to every view it builds, the + ones answering those requests included. + """ + router = routers.SimpleRouter() + router.register("things", GrantViewSet, basename="thing") + [route] = [url for url in router.urls if url.name == "thing-grant"] + + response = route.callback(getattr(APIRequestFactory(), method)("/things/grant/")) + + assert response.status_code == (200 if method == "options" else 405) + assert audit_events == [] + + +def test_details_never_override_event_fields(audit_events): + """A detail named after an event field is dropped, never raising.""" + view = ListingViewSet.as_view( + {"get": "list"}, + audit_details={"request": None, "outcome": "failure", "total": 3}, + ) + + response = view(APIRequestFactory().get("/things/")) + + assert response.status_code == 200 + + [event] = find_events(audit_events, "thing.list") + + assert event["event"]["outcome"] == "success" + assert event["url"] == {"path": "/things/"} + assert event["lasuite"]["details"] == {"total": 3} + + +def test_failing_audit_never_fails_the_response(audit_events): + """An error assembling the event is logged, and the response is kept.""" + view = ThingViewSet.as_view({"get": "list"}) + + with mock.patch.object( + ThingViewSet, "get_audit_fields", side_effect=RuntimeError("boom") + ): + response = view(APIRequestFactory().get("/things/")) + + assert response.status_code == 200 + assert audit_events == [] diff --git a/src/backend/core/tests/audit/test_emitter.py b/src/backend/core/tests/audit/test_emitter.py new file mode 100644 index 00000000..c6c3759e --- /dev/null +++ b/src/backend/core/tests/audit/test_emitter.py @@ -0,0 +1,486 @@ +"""Tests for building and emitting audit events.""" + +import json +import logging +import sys +from datetime import datetime + +from django.contrib.auth.models import AnonymousUser +from django.test import RequestFactory + +import pytest +from dockerflow.logging import request_id_context + +from core import audit +from core.audit import request as audit_request +from core.audit.formatter import AuditJsonFormatter +from core.audit.testing import find_events, override_registration +from core.factories import RoomFactory, UserFactory +from core.models import Room +from core.recording.event.authentication import MachineUser + +pytestmark = pytest.mark.django_db + + +def test_audit_log_emits_ecs_document(audit_events): + """A minimal call produces a complete, pruned ECS document.""" + audit.log("room.create", target={"type": "room", "id": "1"}, extra="x") + + assert len(audit_events) == 1 + + event = audit_events[0] + + assert event["log_type"] == "audit" + assert event["ecs"] == {"version": "8.11.0"} + assert event["service"] == {"name": "meet", "environment": "test"} + assert event["event"] == { + "kind": "event", + "action": "room.create", + "category": ["web"], + "type": ["info"], + "outcome": "success", + } + assert event["lasuite"] == { + "actor": {"type": "system"}, + "auth": {"method": "none"}, + "outcome": "success", + "target": {"type": "room", "id": "1"}, + "details": {"extra": "x"}, + } + assert event["log"]["level"] == "info" + assert "user" not in event + assert "organization" not in event + + +def test_audit_log_timestamp_is_utc_with_explicit_offset(audit_events): + """Timestamps are ISO 8601, millisecond precision, UTC with offset.""" + audit.log("something") + + timestamp = audit_events[0]["@timestamp"] + parsed = datetime.fromisoformat(timestamp) + + assert timestamp.endswith("+00:00") + assert parsed.utcoffset().total_seconds() == 0 + + +@pytest.mark.parametrize( + "outcome,reason,expected", + [ + ("success", None, ("info", "success", ["info"])), + ("failure", "validation_error", ("warning", "failure", ["error"])), + ("denied", "permission_denied", ("warning", "failure", ["denied"])), + ("failure", "internal_error", ("error", "failure", ["error"])), + ], +) +def test_audit_log_outcome_reason_and_level(audit_events, outcome, reason, expected): + """The level is derived from the outcome.""" + level, wire_outcome, types = expected + + audit.log("something", outcome=outcome, reason=reason) + + event = audit_events[0] + + assert event["event"]["outcome"] == wire_outcome + assert event["event"].get("reason") == reason + assert event["event"]["type"] == types + assert event["lasuite"]["outcome"] == outcome + assert event["log"]["level"] == level + + +def test_audit_log_denied_adds_denied_type_to_explicit_types(audit_events): + """A denial always carries the ``denied`` ECS type.""" + audit.log("something", outcome="denied", reason="rate_limited", types=["access"]) + + event = audit_events[0] + + assert event["event"]["type"] == ["access", "denied"] + + +def test_audit_log_accepts_categories_and_types(audit_events): + """Category and types are validated against the ECS subset.""" + audit.log( + "user.login", + category=audit.EventCategory.AUTHENTICATION, + types=[audit.EventType.START], + ) + + event = audit_events[0] + + assert event["event"]["category"] == ["authentication"] + assert event["event"]["type"] == ["start"] + + +def test_audit_log_classifies_an_action_by_its_spec(audit_events): + """An ``Action`` brings its category and types, and names the event.""" + action = audit.Action( + "thing.grant", + category=audit.EventCategory.IAM, + types=(audit.EventType.CREATION,), + ) + + audit.log(action) + + event = audit_events[0] + + assert event["event"]["action"] == "thing.grant" + assert event["event"]["category"] == ["iam"] + assert event["event"]["type"] == ["creation"] + + +def test_audit_log_arguments_win_over_the_spec(audit_events): + """A category or types given to ``log`` override those of the ``Action``.""" + action = audit.Action( + "thing.grant", + category=audit.EventCategory.IAM, + types=(audit.EventType.CREATION,), + ) + + audit.log( + action, + category=audit.EventCategory.CONFIGURATION, + types=[audit.EventType.CHANGE], + ) + + event = audit_events[0] + + assert event["event"]["category"] == ["configuration"] + assert event["event"]["type"] == ["change"] + + +def test_action_spec_validates_its_classification(): + """A category or type outside the ECS subset fails where it is declared.""" + with pytest.raises(ValueError): + audit.Action("thing.grant", category="nonsense") + with pytest.raises(ValueError): + audit.Action("thing.grant", types=("nonsense",)) + + +def test_audit_log_records_the_error_type(audit_events): + """The class of an error lands in ``error.type``, next to its message.""" + audit.log( + "anything", + outcome="failure", + reason="internal_error", + error="boom", + error_type="builtins.RuntimeError", + ) + + assert audit_events[0]["error"] == { + "message": "boom", + "type": "builtins.RuntimeError", + } + + +def test_audit_log_fails_open_on_invalid_input(audit_events, caplog): + """A bad call never raises: it is reported on the application logger.""" + with caplog.at_level(logging.ERROR, logger="core.audit.emitter"): + audit.log("something", outcome="maybe") + + assert audit_events == [] + assert "could not be built" in caplog.text + + +def test_audit_log_skips_a_target_field_that_cannot_be_read(audit_events, caplog): + """A broken registration costs the field, not the event.""" + room = RoomFactory() + + with ( + override_registration(Room, fields=("no_such_field", "slug")), + caplog.at_level(logging.ERROR, logger="core.audit.targets"), + ): + audit.log("anything", target=room) + + [event] = audit_events + + assert event["lasuite"]["target"] == { + "type": "room", + "id": str(room.pk), + "slug": room.slug, + } + assert "no_such_field" in caplog.text + + +def test_audit_log_describes_registered_targets(audit_events): + """Describe rooms with the fields registered in ``core.auditing``.""" + room = RoomFactory(name="Daily standup") + + audit.log("room.create", target=room) + + assert audit_events[0]["lasuite"]["target"] == { + "type": "room", + "id": str(room.pk), + "slug": room.slug, + "name": "Daily standup", + "access_level": room.access_level, + } + + +def test_audit_log_normalises_details(audit_events): + """Nested details are rendered: enums, models as keys, lists, no ``None``.""" + room = RoomFactory() + + audit.log( + "something", + rooms=[room], + nested={"outcome": audit.Outcome.DENIED}, + empty=None, + ) + + details = audit_events[0]["lasuite"]["details"] + + assert details["rooms"] == [str(room.pk)] + assert details["nested"] == {"outcome": "denied"} + assert "empty" not in details + + +def test_audit_log_reads_request_fields(audit_events): + """Should read the HTTP fields from the request, the trace id from dockerflow.""" + token = request_id_context.set("trace-1") + request = RequestFactory().post( + "/external-api/v1.0/rooms/", + data="{}", + content_type="application/json", + REMOTE_ADDR="1.2.3.4", + ) + + try: + audit.log("anything", request=request) + finally: + request_id_context.reset(token) + + event = audit_events[0] + + assert event["http"] == {"request": {"method": "POST"}} + assert event["url"] == {"path": "/external-api/v1.0/rooms/"} + assert event["client"] == {"ip": "1.2.3.4"} + assert event["trace"] == {"id": "trace-1"} + + +def test_audit_log_defaults_to_the_current_request(audit_events): + """Should read the request fields from the request being served.""" + request = RequestFactory().post("/rooms/", REMOTE_ADDR="1.2.3.4") + request.user = AnonymousUser() + token = audit_request.set_current_request(request) + + try: + audit.log("anything") + finally: + audit_request.reset_current_request(token) + + event = audit_events[0] + + assert event["http"] == {"request": {"method": "POST"}} + assert event["url"] == {"path": "/rooms/"} + assert event["client"] == {"ip": "1.2.3.4"} + assert event["lasuite"]["actor"] == {"type": "anonymous"} + + +def test_audit_log_explicit_request_wins_over_the_current_one(audit_events): + """Should prefer the request passed to the one being served.""" + token = audit_request.set_current_request(RequestFactory().get("/current/")) + + try: + audit.log("anything", request=RequestFactory().get("/explicit/")) + finally: + audit_request.reset_current_request(token) + + assert audit_events[0]["url"] == {"path": "/explicit/"} + + +def test_audit_log_reports_the_client_not_the_proxy(audit_events): + """Should report the forwarded client address, not the one of the proxy.""" + request = RequestFactory().get( + "/", REMOTE_ADDR="1.2.3.4", HTTP_X_FORWARDED_FOR="5.6.7.8" + ) + audit.log("something", request=request) + + event = audit_events[0] + + assert event["client"]["ip"] == "5.6.7.8" + assert event["source"] == {"ip": "5.6.7.8"} + + +def test_audit_log_actor_user_is_id_sub_and_domain_only(audit_events): + """A human actor is identified without email or name.""" + user = UserFactory(email="john.doe@example.com", full_name="John Doe") + request = RequestFactory().get("/") + request.user = user + + audit.log("anything", request=request) + + event = audit_events[0] + + assert event["user"] == { + "id": str(user.pk), + "sub": user.sub, + "domain": "example.com", + } + assert event["lasuite"]["actor"] == {"type": "user"} + assert event["lasuite"]["auth"] == {"method": "session"} + assert event["organization"] == {"id": "example.com"} + assert "John" not in json.dumps(event) + assert "john.doe" not in json.dumps(event) + + +def test_audit_log_anonymous_plain_request_has_no_auth_method(audit_events): + """A plain Django request without a signed-in user is not authenticated.""" + request = RequestFactory().get("/") + request.user = AnonymousUser() + + audit.log("anything", request=request) + + assert audit_events[0]["lasuite"]["auth"] == {"method": "none"} + + +def test_audit_log_actor_application_with_delegated_user(audit_events): + """A client id in the token payload makes the actor an application.""" + user = UserFactory(email="user@example.com") + request = RequestFactory().get("/") + request.user = user + request.auth = {"client_id": "app-1", "delegated": True} + + audit.log("something", request=request) + + event = audit_events[0] + + assert event["lasuite"]["actor"] == {"type": "application"} + assert event["lasuite"]["application"] == {"client_id": "app-1"} + assert event["user"] == { + "id": str(user.pk), + "sub": user.sub, + "domain": "example.com", + } + assert event["organization"] == {"id": "app-1"} + + +def test_audit_log_actor_service(audit_events): + """Machine users are services identified by name.""" + request = RequestFactory().get("/") + request.user = MachineUser("roomkit") + + audit.log("something", request=request) + + event = audit_events[0] + + assert event["lasuite"]["actor"] == {"type": "service", "name": "roomkit"} + assert "user" not in event + assert "organization" not in event + + +def test_audit_log_actor_deleted_user_is_not_a_service(audit_events): + """A deleted account has no primary key left, yet it is still a user. + + A service is named by its username, which for an account is an email address. + """ + user = UserFactory(email="john.doe@example.com", admin_email="admin@example.com") + user.delete() + request = RequestFactory().get("/") + request.user = user + + audit.log("anything", request=request) + + event = audit_events[0] + + assert event["lasuite"]["actor"] == {"type": "user"} + assert event["user"] == {"sub": user.sub, "domain": "example.com"} + assert "admin@example.com" not in json.dumps(event) + + +def test_audit_log_explicit_overrides(audit_events): + """Actor, actor type, auth method and client id can be forced.""" + user = UserFactory(email="user@example.com") + + audit.log( + "something", + actor=user, + actor_type="system", + auth_method="oidc", + client_id="app-2", + ) + + event = audit_events[0] + + assert event["lasuite"]["actor"] == {"type": "system"} + assert event["lasuite"]["auth"] == {"method": "oidc"} + assert event["lasuite"]["application"] == {"client_id": "app-2"} + assert event["user"]["id"] == str(user.pk) + assert event["organization"] == {"id": "app-2"} + + +def test_audit_log_status_code_error_and_message(audit_events): + """Response status, error message and free text have their ECS slots.""" + audit.log( + "something", + outcome="denied", + reason="permission_denied", + status_code=403, + error="Insufficient permissions.", + message="scope missing", + ) + + event = audit_events[0] + + assert event["http"] == {"response": {"status_code": 403}} + assert event["error"] == {"message": "Insufficient permissions."} + assert event["message"] == "scope missing" + + +def test_audit_json_formatter_renders_one_line_of_json(): + """The formatter emits compact, single-line, non-ASCII friendly JSON.""" + record = logging.makeLogRecord( + { + "name": "audit", + "levelname": "INFO", + "msg": "anything", + "audit": {"event": {"action": "anything"}, "note": "multi\nline wörld"}, + } + ) + + rendered = AuditJsonFormatter().format(record) + + assert "\n" not in rendered + assert "wörld" in rendered + assert json.loads(rendered) == { + "event": {"action": "anything"}, + "note": "multi\nline wörld", + "log": {"level": "info", "logger": "audit"}, + } + + +def test_audit_json_formatter_wraps_plain_records(): + """A plain record on the audit logger still renders as JSON.""" + record = logging.makeLogRecord( + {"name": "audit", "levelname": "WARNING", "msg": "log %s", "args": ("x",)} + ) + + rendered = json.loads(AuditJsonFormatter().format(record)) + + assert rendered["log_type"] == "audit" + assert rendered["event"] == {"action": "log x"} + assert rendered["message"] == "log x" + assert rendered["@timestamp"].endswith("+00:00") + + +def test_audit_json_formatter_adds_stack_trace(): + """An attached traceback lands under ``error.stack_trace``.""" + try: + raise ValueError("boom") + except ValueError: + record = logging.makeLogRecord( + {"name": "audit", "levelname": "ERROR", "msg": "x", "audit": {}} + ) + record.exc_info = sys.exc_info() + + rendered = json.loads(AuditJsonFormatter().format(record)) + + assert "ValueError: boom" in rendered["error"]["stack_trace"] + + +def test_find_events_filters_by_action(audit_events): + """The test helper narrows captured events by action.""" + audit.log("first") + audit.log("second") + + found = find_events(audit_events, "second") + + assert [event["event"]["action"] for event in found] == ["second"] diff --git a/src/backend/core/tests/audit/test_registry.py b/src/backend/core/tests/audit/test_registry.py new file mode 100644 index 00000000..7791f024 --- /dev/null +++ b/src/backend/core/tests/audit/test_registry.py @@ -0,0 +1,85 @@ +"""Tests for the registry of audited models and authentication classes.""" + +from types import SimpleNamespace + +import pytest + +from core import audit +from core.audit.actor import auth_method_for, auth_method_for_backend +from core.audit.registry import ( + ModelOptions, + auth_methods, + dotted_path, + model_options, + unregister, +) +from core.audit.testing import override_registration +from core.external_api.authentication import ApplicationJWTAuthentication +from core.models import Resource, Room + + +def test_register_twice_is_refused(): + """A model is registered once, like in the admin.""" + audit.register(Resource, fields=("id",)) + try: + with pytest.raises(audit.AlreadyRegistered): + audit.register(Resource) + finally: + unregister(Resource) + + +def test_register_refuses_unknown_options(): + """A misspelled option is an error, not silently ignored.""" + with pytest.raises(TypeError): + audit.register(Resource, field=("name",)) # pylint: disable=unexpected-keyword-arg + + assert model_options(Resource) == ModelOptions() + + +def test_model_options_falls_back_to_the_concrete_model(): + """A proxy model is described as the model it proxies.""" + proxy = type("ProxyRoom", (), {"_meta": SimpleNamespace(concrete_model=Room)}) + + with override_registration(Room, fields=("slug",)): + assert model_options(proxy).fields == ("slug",) + + +def test_override_registration_restores_the_previous_one(): + """The test helper puts back what the project registered.""" + registered = model_options(Room) + + with override_registration(Room, fields=("slug",)): + assert model_options(Room).fields == ("slug",) + + assert model_options(Room) == registered + + +def test_project_declarations_are_discovered(): + """``core.auditing`` is imported when the audit app is ready.""" + assert model_options(Room).fields == ("slug", "name", "access_level") + assert auth_methods()[dotted_path(ApplicationJWTAuthentication)] == ( + "application_jwt" + ) + assert ( + auth_method_for_backend( + "core.authentication.backends.OIDCAuthenticationBackend" + ) + == "oidc" + ) + + +def test_register_auth_method_twice_is_refused(): + """An authentication class is named once.""" + with pytest.raises(audit.AlreadyRegistered): + audit.register_auth_method(ApplicationJWTAuthentication, "other") + + +def test_auth_method_is_inherited_by_subclasses(): + """A DRF class takes the name of its closest registered base.""" + + class CustomAuthentication(ApplicationJWTAuthentication): + """A project subclass nobody registered.""" + + authenticator = object.__new__(CustomAuthentication) + + assert auth_method_for(authenticator) == "application_jwt" diff --git a/src/backend/core/tests/audit/test_request.py b/src/backend/core/tests/audit/test_request.py new file mode 100644 index 00000000..7c6779b1 --- /dev/null +++ b/src/backend/core/tests/audit/test_request.py @@ -0,0 +1,224 @@ +"""Tests for the network fields and the request id of audit events.""" + +import uuid + +from django.http import HttpResponse +from django.test import RequestFactory + +import pytest +from dockerflow.logging import request_id_context +from faker import Faker + +from core.api.throttling import CreationCallbackAnonRateThrottle +from core.audit import request as audit_request + +fake = Faker() + + +def _set_num_proxies(settings, count): + """Trust ``count`` proxies, as DRF's ``NUM_PROXIES`` setting.""" + settings.REST_FRAMEWORK = {**settings.REST_FRAMEWORK, "NUM_PROXIES": count} + + +@pytest.fixture(name="dockerflow_request_id") +def fixture_dockerflow_request_id(): + """Simulate the dockerflow middleware having assigned a request id.""" + request_id = fake.uuid4() + token = request_id_context.set(request_id) + try: + yield request_id + finally: + request_id_context.reset(token) + + +def test_resolve_client_ip_without_forwarded_header(): + """Should use the peer address when no proxy header is present.""" + peer_ip = fake.ipv4() + request = RequestFactory().get("/", REMOTE_ADDR=peer_ip) + + assert audit_request.resolve_client_ip(request) == peer_ip + + +def test_resolve_client_ip_prefers_the_client_over_the_proxy(): + """Should return the client the trusted proxy saw, not the proxy address.""" + request = RequestFactory().get( + "/", REMOTE_ADDR="1.2.3.4", HTTP_X_FORWARDED_FOR="4.5.6.7, 10.0.0.1" + ) + + assert audit_request.resolve_client_ip(request) == "10.0.0.1" + + +def test_resolve_client_ip_skips_trusted_proxies(settings): + """Should skip the load balancer entry when two proxies are trusted.""" + _set_num_proxies(settings, 2) + request = RequestFactory().get( + "/", HTTP_X_FORWARDED_FOR="1.1.1.1, 2.2.2.2, 8.8.8.8" + ) + + assert audit_request.resolve_client_ip(request) == "2.2.2.2" + + +def test_resolve_client_ip_clamps_when_fewer_addresses_than_proxies(settings): + """Should never index out of range on a short chain.""" + _set_num_proxies(settings, 5) + request = RequestFactory().get("/", HTTP_X_FORWARDED_FOR="1.2.3.4") + + assert audit_request.resolve_client_ip(request) == "1.2.3.4" + + +def test_resolve_client_ip_ignores_an_empty_forwarded_header(): + """Should fall back to the peer address when the header is blank.""" + peer_ip = fake.ipv4() + request = RequestFactory().get("/", REMOTE_ADDR=peer_ip, HTTP_X_FORWARDED_FOR=" , ") + + assert audit_request.resolve_client_ip(request) == peer_ip + + +def test_resolve_client_ip_without_trusted_proxy(settings): + """Should ignore the header entirely when no proxy is trusted.""" + _set_num_proxies(settings, 0) + request = RequestFactory().get( + "/", REMOTE_ADDR="1.2.3.4", HTTP_X_FORWARDED_FOR="4.5.6.7" + ) + + assert audit_request.resolve_client_ip(request) == "1.2.3.4" + + +def test_resolve_client_ip_is_the_throttle_identity(settings): + """Should identify the client exactly as Meet's throttles do.""" + _set_num_proxies(settings, 2) + request = RequestFactory().get( + "/", REMOTE_ADDR="1.2.3.4", HTTP_X_FORWARDED_FOR="6.6.6.6, 5.6.7.8, 10.0.0.1" + ) + + assert audit_request.resolve_client_ip(request) == "5.6.7.8" + assert CreationCallbackAnonRateThrottle().get_ident(request) == "5.6.7.8" + + +def test_resolve_client_ip_tolerates_bare_requests(): + """Should accept requests built by hand, which have an empty META.""" + request = RequestFactory().get("/") + request.META = {} + + assert audit_request.resolve_client_ip(request) is None + + +def test_current_request_id_is_dockerflow_request_id(dockerflow_request_id): + """Should reuse the dockerflow request id as the trace id.""" + assert audit_request.current_request_id() == dockerflow_request_id + + +def test_current_request_id_outside_a_request(): + """Should have no id when dockerflow did not assign one.""" + assert audit_request.current_request_id() is None + + +def test_middleware_replaces_an_untrusted_request_id(dockerflow_request_id): + """Should not reuse an inbound id unless the ingress is trusted to set it.""" + middleware = audit_request.AuditLogMiddleware(lambda request: HttpResponse()) + + response = middleware(RequestFactory().get("/")) + + request_id = response["X-Request-ID"] + + assert request_id != dockerflow_request_id + assert str(uuid.UUID(request_id)) == request_id + assert audit_request.current_request_id() == request_id + + +def test_middleware_echoes_a_trusted_request_id(settings, dockerflow_request_id): + """Should keep and echo the inbound id when the ingress is trusted.""" + settings.REQUEST_ID_TRUST_HEADER = True + middleware = audit_request.AuditLogMiddleware(lambda request: HttpResponse()) + + response = middleware(RequestFactory().get("/")) + + assert response["X-Request-ID"] == dockerflow_request_id + + +def test_middleware_echoes_on_the_configured_header(settings, dockerflow_request_id): + """Should echo the id on the header dockerflow reads it from.""" + settings.REQUEST_ID_TRUST_HEADER = True + settings.DOCKERFLOW_REQUEST_ID_HEADER_NAME = "X-Trace-ID" + middleware = audit_request.AuditLogMiddleware(lambda request: HttpResponse()) + + response = middleware(RequestFactory().get("/")) + + assert response["X-Trace-ID"] == dockerflow_request_id + assert not response.has_header("X-Request-ID") + + +@pytest.mark.usefixtures("dockerflow_request_id") +def test_middleware_keeps_an_existing_response_header(): + """Should leave an X-Request-ID set by the view untouched.""" + + def view(request): # pylint: disable=unused-argument + response = HttpResponse() + response["X-Request-ID"] = "from-the-view" + return response + + response = audit_request.AuditLogMiddleware(view)(RequestFactory().get("/")) + + assert response["X-Request-ID"] == "from-the-view" + + +@pytest.mark.django_db +def test_request_id_from_the_client_is_replaced_by_default(client): + """Should answer with an id of its own, not the one the client sent.""" + response = client.get("/api/v1.0/config/", HTTP_X_REQUEST_ID="abc-123") + + assert response.status_code == 200 + assert response["X-Request-ID"] != "abc-123" + assert uuid.UUID(response["X-Request-ID"]) + + +@pytest.mark.django_db +def test_request_id_flows_through_the_test_client_when_trusted(client, settings): + """Should echo the id dockerflow read when the ingress is trusted.""" + settings.REQUEST_ID_TRUST_HEADER = True + + response = client.get("/api/v1.0/config/", HTTP_X_REQUEST_ID="abc-123") + + assert response.status_code == 200 + assert response["X-Request-ID"] == "abc-123" + + +@pytest.mark.django_db +def test_request_id_is_echoed_on_responses_of_outer_middleware(client): + """Should reach responses that never get to the view, as slash redirects.""" + response = client.get("/api/v1.0/config") + + assert response.status_code == 301 + assert uuid.UUID(response["X-Request-ID"]) + + +def test_current_request_outside_a_request(): + """Should have no current request when none is being served.""" + assert audit_request.current_request() is None + + +def test_middleware_sets_the_current_request_while_serving(): + """Should expose the request to the code serving it, then forget it.""" + seen = [] + + def view(request): # pylint: disable=unused-argument + seen.append(audit_request.current_request()) + return HttpResponse() + + request = RequestFactory().get("/") + audit_request.AuditLogMiddleware(view)(request) + + assert seen == [request] + assert audit_request.current_request() is None + + +def test_middleware_forgets_the_current_request_when_the_view_raises(): + """Should not leak the request to the next one when the view raises.""" + + def view(request): + raise RuntimeError("boom") + + with pytest.raises(RuntimeError): + audit_request.AuditLogMiddleware(view)(RequestFactory().get("/")) + + assert audit_request.current_request() is None diff --git a/src/backend/core/tests/audit/test_signals.py b/src/backend/core/tests/audit/test_signals.py new file mode 100644 index 00000000..716750e0 --- /dev/null +++ b/src/backend/core/tests/audit/test_signals.py @@ -0,0 +1,160 @@ +"""Tests for the audit of Django's authentication signals.""" + +import json + +from django.contrib.auth import authenticate, login +from django.contrib.sessions.middleware import SessionMiddleware +from django.http import HttpResponse +from django.test import RequestFactory + +import pytest + +from core import audit +from core.audit.testing import find_events +from core.factories import UserFactory + +pytestmark = pytest.mark.django_db + + +def _request_with_session(method="get"): + request = getattr(RequestFactory(), method)("/", REMOTE_ADDR="1.2.3.4") + SessionMiddleware(lambda req: HttpResponse())(request) + return request + + +def test_login_is_audited(audit_events, client): + """A login records the user, the mechanism and the backend.""" + user = UserFactory(email="user@example.com") + + client.force_login(user) + + [event] = find_events(audit_events, "user.login") + assert event["event"]["category"] == ["authentication"] + assert event["event"]["type"] == ["start"] + assert event["event"]["outcome"] == "success" + assert event["user"] == { + "id": str(user.pk), + "sub": user.sub, + "domain": "example.com", + } + assert event["lasuite"]["actor"] == {"type": "user"} + assert event["lasuite"]["auth"] == {"method": "password"} + assert event["lasuite"]["details"]["auth_backend"].endswith("ModelBackend") + + +def test_login_through_oidc_backend_is_named_oidc(audit_events): + """The OIDC backend is reported as the ``oidc`` auth method.""" + user = UserFactory() + user.backend = "core.authentication.backends.OIDCAuthenticationBackend" + request = _request_with_session() + + login(request, user) + + [event] = find_events(audit_events, "user.login") + assert event["lasuite"]["auth"] == {"method": "oidc"} + assert event["client"] == {"ip": "1.2.3.4"} + assert event["lasuite"]["details"]["auth_backend"] == user.backend + + +def test_login_given_its_backend_is_named_after_it(audit_events): + """A backend passed to ``login`` rather than set by ``authenticate`` counts.""" + backend = "core.authentication.backends.OIDCAuthenticationBackend" + + login(_request_with_session(), UserFactory(), backend=backend) + + [event] = find_events(audit_events, "user.login") + assert event["lasuite"]["auth"] == {"method": "oidc"} + assert event["lasuite"]["details"]["auth_backend"] == backend + + +def test_login_through_an_unlisted_backend_is_unknown(audit_events): + """A backend missing from the setting is unknown, even a ModelBackend subclass.""" + user = UserFactory() + user.backend = "django.contrib.auth.backends.RemoteUserBackend" + + login(_request_with_session(), user) + + [event] = find_events(audit_events, "user.login") + assert event["lasuite"]["auth"] == {"method": "unknown"} + assert event["lasuite"]["details"]["auth_backend"] == user.backend + + +def test_failed_login_is_audited_without_credentials(audit_events): + """A failed login is a warning that never contains the credentials.""" + request = _request_with_session("post") + + assert authenticate(request=request, username="nobody", password="s3cret") is None + + [event] = find_events(audit_events, "user.login") + assert event["event"]["outcome"] == "failure" + assert event["event"]["type"] == ["start", "denied"] + assert event["event"]["reason"] == "authentication_failed" + assert event["lasuite"]["outcome"] == "denied" + assert event["lasuite"]["actor"] == {"type": "anonymous"} + assert event["lasuite"]["auth"] == {"method": "password"} + assert event["log"]["level"] == "warning" + assert "s3cret" not in json.dumps(event) + assert "nobody" not in json.dumps(event) + + +def test_failed_login_without_request_is_anonymous(audit_events): + """A failed login is anonymous even when no request is at hand.""" + assert authenticate(username="nobody", password="s3cret") is None + + [event] = find_events(audit_events, "user.login") + assert event["event"]["outcome"] == "failure" + assert event["lasuite"]["outcome"] == "denied" + assert event["lasuite"]["actor"] == {"type": "anonymous"} + assert event["lasuite"]["auth"] == {"method": "password"} + + +@pytest.mark.parametrize( + "credentials,method", + [ + # What the OIDC callback hands to ``authenticate``. + ({"nonce": "n-0nce", "code_verifier": "v3rifier"}, "oidc"), + ({"token": "t0ken"}, "unknown"), + ], +) +def test_failed_login_is_named_after_its_credentials(audit_events, credentials, method): + """A failed attempt is named after what it submitted, never recording it.""" + request = _request_with_session() + + assert authenticate(request=request, **credentials) is None + + [event] = find_events(audit_events, "user.login") + assert event["event"]["outcome"] == "failure" + assert event["lasuite"]["outcome"] == "denied" + assert event["lasuite"]["auth"] == {"method": method} + for value in credentials.values(): + assert value not in json.dumps(event) + + +def test_logout_is_audited(audit_events, client): + """A logout records the user who left.""" + user = UserFactory() + client.force_login(user) + + client.logout() + + [event] = find_events(audit_events, "user.logout") + assert event["event"]["type"] == ["end"] + assert event["user"]["id"] == str(user.pk) + + +def test_logout_without_a_signed_in_user_is_not_audited(audit_events, client): + """Django signals a logout without a user when no one was signed in.""" + client.logout() + + assert find_events(audit_events, "user.logout") == [] + + +def test_connect_auth_signals_is_idempotent(audit_events, client): + """Connecting twice does not duplicate events.""" + audit.connect_auth_signals() + audit.connect_auth_signals() + user = UserFactory() + + client.force_login(user) + + assert len(find_events(audit_events, "user.login")) == 1 diff --git a/src/backend/core/tests/audit/test_targets.py b/src/backend/core/tests/audit/test_targets.py new file mode 100644 index 00000000..4263282e --- /dev/null +++ b/src/backend/core/tests/audit/test_targets.py @@ -0,0 +1,116 @@ +"""Tests for the description of audit targets.""" + +from django.utils.functional import SimpleLazyObject + +import pytest + +from core.audit.registry import ModelOptions, model_options +from core.audit.targets import describe_target +from core.audit.testing import override_registration +from core.factories import RecordingFactory, RoomFactory, UserFactory +from core.models import Recording, Resource, Room + +pytestmark = pytest.mark.django_db + + +def test_describe_target_reads_the_registered_fields(): + """A model is described by its name, its key and its registered fields.""" + room = RoomFactory() + + with override_registration(Room, fields=("slug", "access_level")): + described = describe_target(room) + + assert described == { + "type": "room", + "id": str(room.pk), + "slug": room.slug, + "access_level": room.access_level, + } + + +def test_describe_target_renders_values(): + """Foreign keys, enums and other values are rendered for JSON.""" + recording = RecordingFactory() + + with override_registration(Recording, fields=("room_id", "room")): + described = describe_target(recording) + + assert described == { + "type": "recording", + "id": str(recording.pk), + "room_id": str(recording.room_id), + "room": str(recording.room_id), + } + + +def test_describe_target_without_fields(): + """A model registered without fields stays identifiable.""" + room = RoomFactory() + + with override_registration(Room): + described = describe_target(room) + + assert described == {"type": "room", "id": str(room.pk)} + + +def test_describe_target_identifies_users_without_their_email(): + """A user is identified by its key, OIDC sub and email domain.""" + user = UserFactory(email="jane@Example.org", sub="oidc-sub-1") + + assert describe_target(user) == { + "type": "user", + "id": str(user.pk), + "sub": "oidc-sub-1", + "domain": "example.org", + } + + +def test_describe_target_of_a_user_without_sub(): + """A user who never signed in, such as a provisional one, has no sub. + + The empty value is pruned when the event is built. + """ + user = UserFactory(email="jane@example.org", sub=None) + + assert describe_target(user) == { + "type": "user", + "id": str(user.pk), + "sub": None, + "domain": "example.org", + } + + +def test_describe_target_sees_through_lazy_objects(): + """A lazy proxy is described as the object it wraps.""" + room = RoomFactory() + + with override_registration(Room, fields=("slug",)): + described = describe_target(SimpleLazyObject(lambda: room)) + + assert described == { + "type": "room", + "id": str(room.pk), + "slug": room.slug, + } + + +def test_describe_target_mapping_passes_through(): + """A ready-made dict is used verbatim.""" + assert describe_target({"type": "x", "id": "1"}) == {"type": "x", "id": "1"} + + +def test_describe_target_of_a_plain_object(): + """Anything else is identified by its class and string form.""" + + class Thing: # pylint: disable=missing-class-docstring + def __str__(self): + return "thing-1" + + assert describe_target(Thing()) == {"type": "thing", "id": "thing-1"} + + +def test_model_options_by_model(): + """Options are looked up by model, and default to nothing.""" + with override_registration(Room, fields=("slug",)): + assert model_options(Room) == ModelOptions(fields=("slug",)) + assert model_options(Resource) == ModelOptions() diff --git a/src/backend/core/tests/audit/test_utils_prune_empty.py b/src/backend/core/tests/audit/test_utils_prune_empty.py new file mode 100644 index 00000000..4f177245 --- /dev/null +++ b/src/backend/core/tests/audit/test_utils_prune_empty.py @@ -0,0 +1,27 @@ +""" +Test audit.utils.prune_empty +""" + +from core.audit.utils import prune_empty + + +def test_prune_empty_drops_none_and_empty_mappings(): + """Should drop None and emptied mappings but keep falsy values.""" + document = { + "none": None, + "emptied": {"inner": None, "deeper": {"again": None}}, + "kept": {"zero": 0, "false": False, "blank": "", "none": None}, + "list": [], + } + + assert prune_empty(document) == { + "kept": {"zero": 0, "false": False, "blank": ""}, + "list": [], + } + + +def test_prune_empty_leaves_non_mappings_untouched(): + """Should return anything that is not a mapping as it is.""" + assert prune_empty([None, {}]) == [None, {}] + assert prune_empty("text") == "text" + assert prune_empty(None) is None diff --git a/src/backend/core/tests/conftest.py b/src/backend/core/tests/conftest.py index b8beeced..2dc311f3 100644 --- a/src/backend/core/tests/conftest.py +++ b/src/backend/core/tests/conftest.py @@ -3,6 +3,9 @@ from unittest import mock import pytest +from dockerflow.logging import request_id_context + +from core.audit.testing import capture_audit USER = "user" TEAM = "team" @@ -14,3 +17,23 @@ def mock_user_get_teams(): """Mock for the "get_teams" method on the User model.""" with mock.patch("core.models.User.get_teams") as mock_get_teams: yield mock_get_teams + + +@pytest.fixture +def audit_events(): + """Collect the audit events emitted during the test, as dicts.""" + with capture_audit() as events: + yield events + + +@pytest.fixture(autouse=True) +def isolated_request_id(): + """Keep dockerflow's request id from leaking from one test to the next. + + Its middleware sets the context variable on every request the test client + makes and never clears it, which would make the trace id of a later test + depend on the order tests ran in. + """ + token = request_id_context.set(None) + yield + request_id_context.reset(token) diff --git a/src/backend/core/tests/recording/event/test_authentication.py b/src/backend/core/tests/recording/event/test_authentication.py index 19c8dd94..fef0a35e 100644 --- a/src/backend/core/tests/recording/event/test_authentication.py +++ b/src/backend/core/tests/recording/event/test_authentication.py @@ -24,6 +24,8 @@ def test_successful_authentication(settings): user, token = RecordingProcessWebhookAuthentication().authenticate(request) assert token == "valid-test-token" assert isinstance(user, MachineUser) + # Names the summary service in the audit log + assert user.get_username() == "summary" def test_authentication_fails_when_token_not_configured(settings): diff --git a/src/backend/meet/settings.py b/src/backend/meet/settings.py index f39a633b..993084d4 100755 --- a/src/backend/meet/settings.py +++ b/src/backend/meet/settings.py @@ -311,6 +311,7 @@ class Base(Configuration): MIDDLEWARE = [ "django.middleware.security.SecurityMiddleware", "dockerflow.django.middleware.DockerflowMiddleware", + "core.audit.request.AuditLogMiddleware", "whitenoise.middleware.WhiteNoiseMiddleware", "django.contrib.sessions.middleware.SessionMiddleware", "django.middleware.locale.LocaleMiddleware", @@ -331,6 +332,7 @@ class Base(Configuration): INSTALLED_APPS = [ # Meet "core", + "core.audit.apps.AuditConfig", "demo", "drf_spectacular", # Third party apps @@ -383,6 +385,13 @@ class Base(Configuration): "PAGE_SIZE": 20, "DEFAULT_VERSIONING_CLASS": "rest_framework.versioning.URLPathVersioning", "DEFAULT_SCHEMA_CLASS": "drf_spectacular.openapi.AutoSchema", + # Trusted proxies appending to X-Forwarded-For in front of the backend. + # Throttles and audit events identify the client as the entry that many + # positions from the right; unset, DRF would use the raw header, which a + # client can vary to escape its throttle. + "NUM_PROXIES": values.IntegerValue( + 1, environ_name="NUM_PROXIES", environ_prefix=None + ), "DEFAULT_THROTTLE_RATES": { "room_creation": values.Value( default="50/minute", @@ -1210,6 +1219,28 @@ class Base(Configuration): environ_prefix=None, ) + AUDIT_LOG_LEVEL = values.Value( + "INFO", environ_name="AUDIT_LOG_LEVEL", environ_prefix=None + ) + AUDIT_LOG_STREAM = values.Value( + "ext://sys.stdout", environ_name="AUDIT_LOG_STREAM", environ_prefix=None + ) + AUDIT_LOG_SERVICE_NAME = values.Value( + "meet", environ_name="AUDIT_LOG_SERVICE_NAME", environ_prefix=None + ) + # Reuse the inbound request id as the trace id + # Only enable it when the ingress overwrites the header + # When off, the backend generates the id. + REQUEST_ID_TRUST_HEADER = values.BooleanValue( + False, environ_name="REQUEST_ID_TRUST_HEADER", environ_prefix=None + ) + + DOCKERFLOW_REQUEST_ID_HEADER_NAME = values.Value( + "X-Request-ID", + environ_name="DOCKERFLOW_REQUEST_ID_HEADER_NAME", + environ_prefix=None, + ) + LOGGING_SILENCED_401_PATHS = values.ListValue( default=["/api/v1.0/users/me/"], environ_name="LOGGING_SILENCED_401_PATHS", @@ -1227,6 +1258,9 @@ class Base(Configuration): "format": "{asctime} {name} {levelname} {message}", "style": "{", }, + "audit_json": { + "()": "core.audit.formatter.AuditJsonFormatter", + }, }, "filters": { "silence_expected_401": { @@ -1239,6 +1273,11 @@ class Base(Configuration): "formatter": "simple", "filters": ["silence_expected_401"], }, + "audit_console": { + "class": "logging.StreamHandler", + "stream": AUDIT_LOG_STREAM, + "formatter": "audit_json", + }, }, # Override root logger to send it to console "root": { @@ -1271,6 +1310,11 @@ class Base(Configuration): ), "propagate": False, }, + "audit": { + "handlers": ["audit_console"], + "level": AUDIT_LOG_LEVEL, + "propagate": False, + }, }, } @@ -1451,6 +1495,8 @@ class Base(Configuration): # Ignore the logs added by the DockerflowMiddleware ignore_logger("request.summary") + # Audit events are a data stream, not errors to report + ignore_logger("audit") class Build(Base): @@ -1502,16 +1548,31 @@ class Test(Base): { "version": 1, "disable_existing_loggers": False, + "formatters": { + "audit_json": { + "()": "core.audit.formatter.AuditJsonFormatter", + }, + }, "handlers": { "console": { "class": "logging.StreamHandler", }, + "audit_console": { + "class": "logging.StreamHandler", + "stream": "ext://sys.stdout", + "formatter": "audit_json", + }, }, "loggers": { "meet": { "handlers": ["console"], "level": "DEBUG", }, + "audit": { + "handlers": ["audit_console"], + "level": "INFO", + "propagate": False, + }, }, } )