diff --git a/CHANGELOG.md b/CHANGELOG.md index b6767b119..d429e8394 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 e1386a533..1bebecde3 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 000000000..35f6fc4af --- /dev/null +++ b/src/backend/core/audit/__init__.py @@ -0,0 +1,34 @@ +"""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 request_context +from .signals import LOGIN_ACTION, LOGOUT_ACTION, connect_auth_signals +from .utils import exception_type + +__all__ = [ + "AUDIT_LOGGER_NAME", + "LOGIN_ACTION", + "LOGOUT_ACTION", + "Action", + "ActorType", + "AlreadyRegistered", + "AuditJsonFormatter", + "AuditViewMixin", + "EventCategory", + "EventType", + "Outcome", + "Reason", + "connect_auth_signals", + "email_domain", + "exception_type", + "log", + "register", + "register_auth_method", + "request_context", +] diff --git a/src/backend/core/audit/actions.py b/src/backend/core/audit/actions.py new file mode 100644 index 000000000..1cce7e0ce --- /dev/null +++ b/src/backend/core/audit/actions.py @@ -0,0 +1,30 @@ +"""Specs of the actions audit events are emitted for.""" + +from dataclasses import dataclass + +from .ecs import DEFAULT_CATEGORY, check_classification +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. Without a + category, the action is an API call. + """ + + name: str + category: EventCategory | None = None + types: tuple[EventType, ...] = () + + def __post_init__(self): + """Validate the classification against ECS, 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)) + check_classification([self.category or DEFAULT_CATEGORY], 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 000000000..5695f4607 --- /dev/null +++ b/src/backend/core/audit/actor.py @@ -0,0 +1,187 @@ +"""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 enum import Enum +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" + +USER_ROLE_FLAGS = (("is_superuser", "superuser"), ("is_staff", "staff")) + + +class _ActorDefault(Enum): + """Sentinel telling an omitted ``actor`` apart from ``None``(no account).""" + + FROM_REQUEST = "from_request" + + +FROM_REQUEST = _ActorDefault.FROM_REQUEST + +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 ECS fields identifying a person: id and email domain. + + The id is missing for accounts that were deleted. + """ + return { + "id": str(user.pk) if user.pk is not None else None, + "domain": email_domain(getattr(user, "email", None)), + } + + +def user_sub(user) -> str | None: + """Return the OIDC sub of an account, missing for one that never signed in.""" + return getattr(user, "sub", None) or None + + +def user_roles(user) -> list[str] | None: + """Return the privileges of an account at the time of the event, if any.""" + roles = [role for flag, role in USER_ROLE_FLAGS if getattr(user, flag, False)] + return roles or None + + +def describe_actor( + request, + *, + actor: Any = FROM_REQUEST, + actor_type: ActorType | str | None = None, + client_id: str | None = None, + auth_method: str | None = None, +) -> dict[str, Any]: + """Return the fields describing the actor. + + That is the ECS ``user`` and ``organization`` fields, the name of the + service acting, if any, reported as ``service.origin.name``, and the + ``lasuite`` ones. Everything is read from ``request`` unless overridden. + ``actor=None`` means no account, whoever the request is signed in as: + an explicit ``actor_type`` alone does not discard it. + 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 = getattr(request, "user", None) if actor is FROM_REQUEST else actor + 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) + is_account = _is_account(user) + + lasuite: dict[str, Any] = { + "actor": { + "type": str(ActorType(actor_type)), + "sub": user_sub(user) if is_account else None, + }, + "auth": {"method": auth_method or request_auth_method(request)}, + "application": {"client_id": client_id}, + } + tenant = client_id or ( + email_domain(getattr(user, "email", None)) if is_account else None + ) + return { + "user": ( + {**describe_user(user), "roles": user_roles(user)} if is_account else None + ), + "organization": {"id": tenant}, + "service": user.get_username() if _is_service(user) else None, + "lasuite": lasuite, + } diff --git a/src/backend/core/audit/apps.py b/src/backend/core/audit/apps.py new file mode 100644 index 000000000..3219c89f9 --- /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 000000000..7bb887966 --- /dev/null +++ b/src/backend/core/audit/drf.py @@ -0,0 +1,181 @@ +"""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 .actor import FROM_REQUEST +from .ecs import DEFAULT_CATEGORY +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. The actor is the + account of the request unless ``audit_actor`` is assigned, ``None`` + recording no account. 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 = FROM_REQUEST + 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. A 401 is also filed under ``authentication``, so that + it counts as a failed authentication. + """ + 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 + } + category = category or DEFAULT_CATEGORY + fields = { + **details, + "category": ( + [category, EventCategory.AUTHENTICATION] + if status_code == 401 + else category + ), + "types": types + or [ACTION_TYPES.get(getattr(self, "action", None), EventType.INFO)], + "target": self.audit_target, + "actor": self.audit_actor, + "status_code": status_code, + } + 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 + ), + "error": error, + } + return fields diff --git a/src/backend/core/audit/ecs.py b/src/backend/core/audit/ecs.py new file mode 100644 index 000000000..68ced0d31 --- /dev/null +++ b/src/backend/core/audit/ecs.py @@ -0,0 +1,130 @@ +"""What the Elastic Common Schema says about audit events. + +Reference: +- https://github.com/elastic/ecs/blob/v9.5.0/schemas/event.yml +- https://github.com/elastic/ecs/blob/v9.5.0/schemas/entity.yml +""" + +from collections.abc import Iterable + +from django.conf import settings + +from .enums import EventCategory, EventType + +ECS_VERSION = "9.5.0" + +# The category of an event that names none, as an API call +DEFAULT_CATEGORY = EventCategory.API + +# ``expected_event_types`` of the categories in ``EventCategory`` +EXPECTED_EVENT_TYPES: dict[EventCategory, frozenset[EventType]] = { + EventCategory.API: frozenset( + { + EventType.ACCESS, + EventType.ADMIN, + EventType.ALLOWED, + EventType.CHANGE, + EventType.CREATION, + EventType.DELETION, + EventType.DENIED, + EventType.END, + EventType.INFO, + EventType.START, + EventType.USER, + } + ), + EventCategory.AUTHENTICATION: frozenset( + {EventType.START, EventType.END, EventType.INFO} + ), + EventCategory.CONFIGURATION: frozenset( + { + EventType.ACCESS, + EventType.CHANGE, + EventType.CREATION, + EventType.DELETION, + EventType.INFO, + } + ), + EventCategory.EMAIL: frozenset({EventType.INFO}), + EventCategory.FILE: frozenset( + { + EventType.ACCESS, + EventType.CHANGE, + EventType.CREATION, + EventType.DELETION, + EventType.INFO, + } + ), + EventCategory.IAM: frozenset( + { + EventType.ADMIN, + EventType.CHANGE, + EventType.CREATION, + EventType.DELETION, + EventType.GROUP, + EventType.INFO, + EventType.USER, + } + ), + EventCategory.SESSION: frozenset({EventType.START, EventType.END, EventType.INFO}), + EventCategory.WEB: frozenset({EventType.ACCESS, EventType.ERROR, EventType.INFO}), +} + +# Allowed values of ``entity.type`` +ENTITY_TYPES = frozenset( + { + "application", + "bucket", + "cloud", + "container", + "database", + "function", + "host", + "orchestrator", + "queue", + "service", + "session", + "user", + } +) + + +def is_expected(categories: Iterable[EventCategory], event_type: EventType) -> bool: + """Tell whether one of ``categories`` expects ``event_type``.""" + return any(event_type in EXPECTED_EVENT_TYPES[category] for category in categories) + + +def check_classification( + categories: Iterable[EventCategory | str], types: Iterable[EventType | str] +) -> None: + """Raise ``ValueError`` unless every type is expected by one of the categories.""" + categories = [EventCategory(category) for category in categories] + unexpected = [ + str(event_type) + for event_type in (EventType(item) for item in types) + if not is_expected(categories, event_type) + ] + if unexpected: + raise ValueError( + f"ECS {ECS_VERSION} does not expect event type {', '.join(unexpected)} " + f"in category {', '.join(str(category) for category in categories)}" + ) + + +def dataset() -> str: + """Return the dataset of audit events, ``.audit``.""" + service_name = settings.AUDIT_LOG_SERVICE_NAME + return f"{service_name}.audit".lower().replace("-", "_") + + +def stream_fields() -> dict[str, dict[str, str]]: + """Return the ``data_stream`` and ``event.dataset`` fields of audit events.""" + name = dataset() + return { + "data_stream": { + "type": "logs", + "dataset": name, + "namespace": settings.AUDIT_LOG_DATA_STREAM_NAMESPACE + }, + "event": {"dataset": name}, + } diff --git a/src/backend/core/audit/emitter.py b/src/backend/core/audit/emitter.py new file mode 100644 index 000000000..e1e7a05e8 --- /dev/null +++ b/src/backend/core/audit/emitter.py @@ -0,0 +1,223 @@ +"""Build ECS audit documents and emit them on the ``audit`` logger.""" + +import functools +import inspect +import logging +import socket +import uuid +from collections.abc import Iterable +from datetime import datetime, timezone +from typing import Any + +from django.conf import settings + +from .actions import Action +from .actor import FROM_REQUEST, describe_actor +from .ecs import ( + DEFAULT_CATEGORY, + ECS_VERSION, + check_classification, + is_expected, + stream_fields, +) +from .enums import ActorType, EventCategory, EventType, Outcome, Reason +from .request import RequestContext, request_context +from .targets import describe_target +from .utils import prune_empty, render_value + +AUDIT_LOGGER_NAME = "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 + + +@functools.cache +def service_version() -> str | None: + """Return the release of the backend.""" + return getattr(settings, "RELEASE", None) + + +@functools.cache +def service_node_name() -> str: + """Return the name of the node serving, its pod name on Kubernetes.""" + return socket.gethostname() + + +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 | Iterable[EventCategory | str] | None = None, + types: list[EventType | str] | None = None, + target: Any = None, + actor: Any = FROM_REQUEST, + actor_type: ActorType | str | None = None, + auth_method: str | None = None, + client_id: str | None = None, + target_service: 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 fields. + + ``action`` is what was attempted: an ``Action``, whose category and types + apply unless given here, or a bare dotted name (``room.create``). + ``category`` may be a list, for an event filed under several. + The actor, auth method and network fields are read from ``request``, by + default from the context of the request being served. + ``actor``, ``actor_type``, ``auth_method`` and ``client_id`` override them; + ``actor=None`` records no account even when the request is signed in. + ``target`` is the resource acted on, reported as ``entity.target``. + ``target_service`` names the peer service the backend called, reported as + ``service.target.name``. Any other keyword argument lands under + ``lasuite.details``, unless ``None`` or an empty mapping. The value of a + detail is data and is kept whole: a ``None`` or an empty mapping inside + it, as in the ``from`` and ``to`` of a change, stays. + """ + context = ( + request_context() if request is None else RequestContext.from_request(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) + actor_fields = describe_actor( + context.request, + actor=actor, + actor_type=actor_type, + client_id=client_id, + auth_method=auth_method, + ) + stream = stream_fields() + + document = prune_empty( + { + "@timestamp": datetime.now(timezone.utc).isoformat(timespec="milliseconds"), + "ecs": {"version": ECS_VERSION}, + "data_stream": stream["data_stream"], + "message": message, + "service": { + "name": settings.AUDIT_LOG_SERVICE_NAME, + "environment": getattr(settings, "ENVIRONMENT", None), + "version": service_version(), + "node": {"name": service_node_name()}, + "origin": {"name": actor_fields["service"]}, + "target": {"name": target_service}, + }, + "event": _event_fields(action, outcome, reason, category, types) + | stream["event"], + "client": {"ip": context.client_ip}, + "source": {"ip": context.client_ip}, + "http": { + "request": {"id": context.request_id, "method": context.method}, + "response": {"status_code": status_code}, + }, + "url": {"path": context.path}, + "user_agent": {"original": context.user_agent}, + "user": actor_fields["user"], + "organization": actor_fields["organization"], + "entity": { + "target": describe_target(target) if target is not None else None + }, + "lasuite": { + **actor_fields["lasuite"], + "outcome": str(outcome), + }, + "error": { + "message": str(error) if error is not None else None, + "type": error_type, + }, + } + ) + # Pruned apart and one level deep only: what a detail holds is data + if details := prune_empty(render_value(details), depth=1): + document["lasuite"]["details"] = details + return document + + +# The allowed kwargs of the``log`` function that fill an event field +EVENT_FIELDS = frozenset( + name + for name, parameter in inspect.signature(build_document).parameters.items() + if parameter.kind is inspect.Parameter.KEYWORD_ONLY +) + + +def _categories(category) -> list[EventCategory]: + if category is None: + return [DEFAULT_CATEGORY] + if isinstance(category, str): + return [EventCategory(category)] + return list(dict.fromkeys(EventCategory(item) for item in category)) or [ + DEFAULT_CATEGORY + ] + + +def _event_fields(action, outcome, reason, category, types) -> dict[str, Any]: + """Return the ECS ``event`` fields of the event.""" + categories = _categories(category) + type_list = [EventType(item) for item in (types or [])] + if not type_list: + type_list = [_default_type(outcome, categories)] + if ( + outcome == Outcome.DENIED + and EventType.DENIED not in type_list + and is_expected(categories, EventType.DENIED) + ): + type_list.append(EventType.DENIED) + try: + check_classification(categories, type_list) + except ValueError: + logger.exception("Audit event %r is misclassified", str(action)) + + return { + "kind": "event", + "id": str(uuid.uuid4()), + "action": str(action), + "category": [str(item) for item in categories], + "type": [str(item) for item in type_list], + "outcome": str(Outcome.FAILURE if outcome == Outcome.DENIED else outcome), + "reason": str(reason) if reason is not None else None, + } + + +def _default_type(outcome: Outcome, categories: list[EventCategory]) -> EventType: + """Return the type of an event whose action names none. + + ``denied`` or ``error`` when one of the categories expects it, else ``info``. + """ + preferred = {Outcome.DENIED: EventType.DENIED, Outcome.FAILURE: EventType.ERROR} + event_type = preferred.get(outcome) + if event_type is not None and is_expected(categories, event_type): + return event_type + return EventType.INFO diff --git a/src/backend/core/audit/enums.py b/src/backend/core/audit/enums.py new file mode 100644 index 000000000..56bb4b6fe --- /dev/null +++ b/src/backend/core/audit/enums.py @@ -0,0 +1,79 @@ +"""ECS enums shared by every audit event.""" + +from enum import StrEnum + + +class Outcome(StrEnum): + """Whether the audited action succeeded, failed, or was refused. + + ``unknown`` is for an action whose result was reported in terms the + backend does not recognise. + """ + + SUCCESS = "success" + FAILURE = "failure" + DENIED = "denied" + UNKNOWN = "unknown" + + +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 + # named by ``service.origin.name`` + 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 000000000..c4bd05745 --- /dev/null +++ b/src/backend/core/audit/formatter.py @@ -0,0 +1,39 @@ +"""Render audit records as single-line ECS JSON format.""" + +import json +import logging +from datetime import datetime, timezone +from typing import Any + +from .ecs import ECS_VERSION, stream_fields + + +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): + stream = stream_fields() + document = { + "@timestamp": datetime.fromtimestamp( + record.created, tz=timezone.utc + ).isoformat(timespec="milliseconds"), + "ecs": {"version": ECS_VERSION}, + "data_stream": stream["data_stream"], + "message": record.getMessage(), + "event": {**stream["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 000000000..463cafca2 --- /dev/null +++ b/src/backend/core/audit/registry.py @@ -0,0 +1,87 @@ +"""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(Application, entity_type="application") # ECS ``entity.type`` + 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 + +from .ecs import ENTITY_TYPES + + +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, under + ``entity.target``. ``entity_type`` is the ECS ``entity.type`` of the + model, when one of its allowed values fits. + """ + + fields: tuple[str, ...] = () + entity_type: str | None = None + + +_models: dict[type[Model], ModelOptions] = {} +_auth_methods: dict[str, str] = {} + + +def register(model: type[Model], *, fields=(), entity_type: str | None = None) -> None: + """Declare what audit events may say about ``model``.""" + if model in _models: + raise AlreadyRegistered(f"{model._meta.label} is already registered") # noqa: SLF001 + if entity_type is not None and entity_type not in ENTITY_TYPES: + raise ValueError( + f"{entity_type!r} is not an ECS entity type: " + f"use one of {', '.join(sorted(ENTITY_TYPES))}" + ) + _models[model] = ModelOptions(fields=tuple(fields), entity_type=entity_type) + + +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 000000000..0d277bae8 --- /dev/null +++ b/src/backend/core/audit/request.py @@ -0,0 +1,114 @@ +"""Read the network fields and the request id behind an audit event.""" + +import uuid +from contextvars import ContextVar, Token +from dataclasses import dataclass +from typing import Any + +from django.conf import settings + +from dockerflow.logging import request_id_context +from rest_framework.throttling import BaseThrottle + +USER_AGENT_MAX_LENGTH = 1024 + + +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") + + +@dataclass(frozen=True) +class RequestContext: + """What an audit event reads from the request behind it. + + The network fields are read once, when the request comes in. The request + itself is kept for the actor, only known once it is authenticated: it is + the Django request, onto which DRF copies its user and auth, but not its + authenticator, so the auth method of a DRF view is not known from it. + Outside a request, every field is ``None``. + """ + + request: Any = None + request_id: str | None = None + method: str | None = None + path: str | None = None + client_ip: str | None = None + user_agent: str | None = None + + @classmethod + def from_request(cls, request) -> "RequestContext": + """Read the context of ``request``, its user agent cut where ECS stops.""" + meta = getattr(request, "META", None) or {} + return cls( + request=request, + request_id=current_request_id(), + method=getattr(request, "method", None), + path=getattr(request, "path", None) or None, + client_ip=resolve_client_ip(request), + user_agent=meta.get("HTTP_USER_AGENT", "")[:USER_AGENT_MAX_LENGTH] or None, + ) + + +_request_context: ContextVar[RequestContext | None] = ContextVar( + "audit_request_context", default=None +) + + +def request_context() -> RequestContext: + """Return the context of the request being served, as set by ``AuditLogMiddleware``. + + It is empty outside a request. + """ + return _request_context.get() or RequestContext() + + +def set_request_context(context: RequestContext) -> Token: + """Make ``context`` the one of the request being served, until reset.""" + return _request_context.set(context) + + +def reset_request_context(token: Token) -> None: + """Restore the context that was current before ``set_request_context``.""" + _request_context.reset(token) + + +class AuditLogMiddleware: + """Settle the request id and the request context, 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 context of the request is kept 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_request_context(RequestContext.from_request(request)) + try: + response = self.get_response(request) + finally: + reset_request_context(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 000000000..bd71c5432 --- /dev/null +++ b/src/backend/core/audit/signals.py @@ -0,0 +1,81 @@ +"""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 get_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.""" + log( + LOGIN_ACTION, + outcome=Outcome.DENIED, + reason=Reason.AUTHENTICATION_FAILED, + request=request, + actor=None, + actor_type=ActorType.ANONYMOUS, + auth_method=get_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 000000000..73557616c --- /dev/null +++ b/src/backend/core/audit/targets.py @@ -0,0 +1,65 @@ +"""Describe the resource an audit event is about, as an ECS ``entity.target``. + +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 user_sub +from .registry import model_options +from .utils import prune_empty, render_value + +NAME_FIELD = "name" + +_logger = logging.getLogger(__name__) + + +def _is_user(obj: Any) -> bool: + return isinstance(obj, get_user_model()) + + +def describe_target(obj: Any) -> dict[str, Any]: + """Return the ``entity.target`` fields of a target. + + ``id`` is its primary key and ``sub_type`` its model name. ``type`` is the + ECS entity type registered for its model, ``user`` for a user. A + registered field called ``name`` is reported as ``name``, the others + under ``raw``, as the OIDC sub of a user. Empty values are left out, as is + a registered field that cannot be read, which is reported. + A mapping is taken as already described. + """ + if isinstance(obj, Mapping): + return dict(obj) + if not isinstance(obj, Model): + return {"id": str(obj), "sub_type": obj.__class__.__name__.lower()} + + meta = obj._meta # noqa: SLF001 + options = model_options(meta.model) + entity_type = options.entity_type or ("user" if _is_user(obj) else None) + raw: dict[str, Any] = {} + for name in options.fields: + try: + raw[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 _is_user(obj): + raw["sub"] = user_sub(obj) + return prune_empty( + { + "id": str(obj.pk) if obj.pk is not None else None, + "type": [entity_type] if entity_type else None, + "sub_type": meta.model_name, + "name": raw.pop(NAME_FIELD, None), + "raw": raw, + } + ) diff --git a/src/backend/core/audit/testing.py b/src/backend/core/audit/testing.py new file mode 100644 index 000000000..3346506f0 --- /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 000000000..622ce16bc --- /dev/null +++ b/src/backend/core/audit/utils.py @@ -0,0 +1,52 @@ +"""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, depth: int | None = None) -> Any: + """Drop ``None`` values and empty mappings, recursively. + + With ``depth``, only that many levels are pruned: the values below are + kept whole, ``None`` and empty mappings included. + """ + if not isinstance(value, Mapping) or depth == 0: + return value + pruned = {} + for key, item in value.items(): + cleaned = prune_empty(item, None if depth is None else depth - 1) + if cleaned is None or (isinstance(cleaned, Mapping) 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 000000000..941dda9ff --- /dev/null +++ b/src/backend/core/auditing.py @@ -0,0 +1,37 @@ +"""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, + entity_type="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 c68d79c8d..997ad0d14 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 000000000..52e3a62e0 --- /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 000000000..dadf87c85 --- /dev/null +++ b/src/backend/core/tests/audit/test_drf.py @@ -0,0 +1,371 @@ +"""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"}, + "response": {"status_code": 200}, + } + + +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"] == ["api", "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["entity"]["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["entity"]["target"]["id"] == str(room.pk) + assert event["entity"]["target"]["sub_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 also files the event under ``authentication``, whatever the spec. + + Neither category expects the ``denied`` type, so it is not added. + """ + 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"] == ["iam", "authentication"] + assert event["event"]["type"] == ["creation"] + assert event["event"]["outcome"] == "failure" + assert event["lasuite"]["outcome"] == "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_ecs.py b/src/backend/core/tests/audit/test_ecs.py new file mode 100644 index 000000000..a1b8b1b81 --- /dev/null +++ b/src/backend/core/tests/audit/test_ecs.py @@ -0,0 +1,47 @@ +"""Tests holding audit events to the Elastic Common Schema 9.5.0.""" + +import pytest + +from core import audit, auditing +from core.audit import ecs + + +def declared_actions() -> list[audit.Action]: + """Return every action the project and the facility declare.""" + actions = [ + value for value in vars(auditing).values() if isinstance(value, audit.Action) + ] + return [*actions, audit.LOGIN_ACTION, audit.LOGOUT_ACTION] + + +def test_check_classification_accepts_expected_types(): + """A type is valid when one of the categories expects it.""" + ecs.check_classification([audit.EventCategory.IAM], [audit.EventType.USER]) + ecs.check_classification( + [audit.EventCategory.API, audit.EventCategory.AUTHENTICATION], + [audit.EventType.CREATION, audit.EventType.DENIED], + ) + + +def test_check_classification_refuses_unexpected_types(): + """ECS expects no ``denied`` for an authentication, nor ``end`` on the web.""" + with pytest.raises(ValueError, match="denied"): + ecs.check_classification( + [audit.EventCategory.AUTHENTICATION], [audit.EventType.DENIED] + ) + with pytest.raises(ValueError, match="end"): + ecs.check_classification([audit.EventCategory.WEB], [audit.EventType.END]) + + +def test_every_category_has_its_expected_types(): + """The subset of categories the facility uses is fully transcribed.""" + assert set(ecs.EXPECTED_EVENT_TYPES) == set(audit.EventCategory) + + +@pytest.mark.parametrize("action", declared_actions(), ids=str) +def test_declared_actions_are_classified_as_ecs_expects(action): + """Every action of the catalogue is classified as ECS expects. + + ``Action`` refuses anything else when it is declared: this lists them. + """ + ecs.check_classification([action.category or ecs.DEFAULT_CATEGORY], action.types) 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 000000000..bf665c95b --- /dev/null +++ b/src/backend/core/tests/audit/test_emitter.py @@ -0,0 +1,706 @@ +"""Tests for building and emitting audit events.""" + +import json +import logging +import sys +import uuid +from datetime import datetime +from unittest import mock + +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 emitter +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 ApplicationFactory, 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.""" + with ( + mock.patch.object(emitter, "service_version", return_value="1.2.3"), + mock.patch.object(emitter, "service_node_name", return_value="node-1"), + ): + audit.log("room.create", target={"sub_type": "room", "id": "1"}, extra="x") + + assert len(audit_events) == 1 + + event = audit_events[0] + event_id = event["event"].pop("id") + + assert uuid.UUID(event_id).version == 4 + assert event["ecs"] == {"version": "9.5.0"} + assert event["data_stream"] == { + "type": "logs", + "dataset": "meet.audit", + "namespace": "default", + } + assert event["service"] == { + "name": "meet", + "environment": "test", + "version": "1.2.3", + "node": {"name": "node-1"}, + } + assert event["event"] == { + "kind": "event", + "dataset": "meet.audit", + "action": "room.create", + "category": ["api"], + "type": ["info"], + "outcome": "success", + } + assert event["entity"] == {"target": {"sub_type": "room", "id": "1"}} + assert event["lasuite"] == { + "actor": {"type": "system"}, + "auth": {"method": "none"}, + "outcome": "success", + "details": {"extra": "x"}, + } + assert event["log"]["level"] == "info" + assert "user" not in event + assert "organization" not in event + + +def test_audit_log_identifies_each_event(audit_events): + """Every event has its own id, so a shipper retrying it cannot duplicate it.""" + audit.log("something") + audit.log("something") + + assert audit_events[0]["event"]["id"] != audit_events[1]["event"]["id"] + + +@pytest.mark.parametrize( + "service_name,namespace,dataset", + [ + ("meet", "default", "meet.audit"), + ("La-Suite-Meet", "production", "la_suite_meet.audit"), + ], +) +def test_audit_log_routes_to_its_data_stream( + audit_events, settings, service_name, namespace, dataset +): + """The dataset follows the service name, minus what data stream names forbid.""" + settings.AUDIT_LOG_SERVICE_NAME = service_name + settings.AUDIT_LOG_DATA_STREAM_NAMESPACE = namespace + + audit.log("something") + + event = audit_events[0] + + assert event["data_stream"] == { + "type": "logs", + "dataset": dataset, + "namespace": namespace, + } + assert event["event"]["dataset"] == dataset + + +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", ["info"])), + ("denied", "permission_denied", ("warning", "failure", ["denied"])), + ("failure", "internal_error", ("error", "failure", ["info"])), + ("unknown", None, ("warning", "unknown", ["info"])), + ], +) +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 carries the ``denied`` ECS type in a category expecting it.""" + audit.log("something", outcome="denied", reason="rate_limited", types=["access"]) + + event = audit_events[0] + + assert event["event"]["type"] == ["access", "denied"] + + +def test_audit_log_denied_type_only_where_ecs_expects_it(audit_events): + """ECS expects no ``denied`` type for an authentication, so none is added.""" + audit.log( + "user.login", + outcome="denied", + reason="authentication_failed", + category=audit.EventCategory.AUTHENTICATION, + types=[audit.EventType.START], + ) + + event = audit_events[0] + + assert event["event"]["type"] == ["start"] + assert event["event"]["outcome"] == "failure" + assert event["lasuite"]["outcome"] == "denied" + + +def test_audit_log_failure_type_is_error_where_ecs_expects_it(audit_events): + """A failure without types is an ``error`` in a category expecting one.""" + audit.log("something", outcome="failure", category=audit.EventCategory.WEB) + + assert audit_events[0]["event"]["type"] == ["error"] + + +def test_audit_log_accepts_several_categories(audit_events): + """An event may be filed under several categories, each listed once.""" + audit.log( + "room.create", + category=[ + audit.EventCategory.API, + audit.EventCategory.AUTHENTICATION, + audit.EventCategory.API, + ], + types=[audit.EventType.CREATION], + ) + + assert audit_events[0]["event"]["category"] == ["api", "authentication"] + + +def test_audit_log_reports_a_misclassified_event_and_still_emits_it( + audit_events, caplog +): + """A classification ECS does not expect is an error, yet the event is kept.""" + with caplog.at_level(logging.ERROR, logger="core.audit.emitter"): + audit.log( + "something", + category=audit.EventCategory.AUTHENTICATION, + types=[audit.EventType.CREATION], + ) + + assert audit_events[0]["event"]["type"] == ["creation"] + assert "misclassified" in caplog.text + + +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_action_spec_validates_its_classification_against_ecs(): + """A type the category does not expect in ECS fails where it is declared.""" + with pytest.raises(ValueError, match="does not expect event type end"): + audit.Action( + "thing.grant", + category=audit.EventCategory.WEB, + types=(audit.EventType.END,), + ) + with pytest.raises(ValueError, match="in category api"): + audit.Action("thing.grant", types=(audit.EventType.ERROR,)) + + +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["entity"]["target"] == { + "id": str(room.pk), + "sub_type": "room", + "raw": {"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]["entity"]["target"] == { + "id": str(room.pk), + "sub_type": "room", + "name": "Daily standup", + "raw": {"slug": room.slug, "access_level": room.access_level}, + } + assert "user" not in audit_events[0] + + +def test_audit_log_registered_entity_type(audit_events): + """A model registered with an ECS entity type reports it.""" + application = ApplicationFactory() + + audit.log("thing.grant", target=application) + + target = audit_events[0]["entity"]["target"] + + assert target["type"] == ["application"] + assert target["sub_type"] == "application" + assert target["name"] == application.name + + +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 request id from dockerflow.""" + token = request_id_context.set("request-1") + request = RequestFactory().post( + "/external-api/v1.0/rooms/", + data="{}", + content_type="application/json", + REMOTE_ADDR="1.2.3.4", + HTTP_USER_AGENT="Mozilla/5.0 (X11; Linux x86_64)", + ) + + try: + audit.log("anything", request=request) + finally: + request_id_context.reset(token) + + event = audit_events[0] + + assert event["http"] == {"request": {"id": "request-1", "method": "POST"}} + assert event["url"] == {"path": "/external-api/v1.0/rooms/"} + assert event["client"] == {"ip": "1.2.3.4"} + assert event["user_agent"] == {"original": "Mozilla/5.0 (X11; Linux x86_64)"} + assert "trace" not in event + + +def test_audit_log_truncates_the_user_agent(audit_events): + """A user agent is cut where ECS stops indexing it.""" + request = RequestFactory().get("/", HTTP_USER_AGENT="x" * 5000) + + audit.log("anything", request=request) + + assert audit_events[0]["user_agent"]["original"] == "x" * 1024 + + +def test_audit_log_defaults_to_the_request_context(audit_events): + """Should read the request fields from the context of the request being served.""" + request = RequestFactory().post("/rooms/", REMOTE_ADDR="1.2.3.4") + request.user = AnonymousUser() + token = audit_request.set_request_context( + audit_request.RequestContext.from_request(request) + ) + + try: + audit.log("anything") + finally: + audit_request.reset_request_context(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_request_context(audit_events): + """Should prefer the request passed to the one being served.""" + token = audit_request.set_request_context( + audit_request.RequestContext.from_request(RequestFactory().get("/current/")) + ) + + try: + audit.log("anything", request=RequestFactory().get("/explicit/")) + finally: + audit_request.reset_request_context(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), "domain": "example.com"} + assert event["lasuite"]["actor"] == {"type": "user", "sub": user.sub} + 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) + + +@pytest.mark.parametrize( + "flags,roles", + [ + ({}, None), + ({"is_staff": True}, ["staff"]), + ({"is_staff": True, "is_superuser": True}, ["superuser", "staff"]), + ], +) +def test_audit_log_actor_roles(audit_events, flags, roles): + """The privileges of the actor at the time of the event are its roles.""" + request = RequestFactory().get("/") + request.user = UserFactory(**flags) + + audit.log("anything", request=request) + + assert audit_events[0]["user"].get("roles") == roles + + +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", "sub": user.sub} + assert event["lasuite"]["application"] == {"client_id": "app-1"} + assert event["user"] == {"id": str(user.pk), "domain": "example.com"} + assert event["organization"] == {"id": "app-1"} + + +def test_audit_log_actor_service(audit_events): + """Machine users are services, named as the origin of the request.""" + request = RequestFactory().get("/") + request.user = MachineUser("roomkit") + + audit.log("something", request=request) + + event = audit_events[0] + + assert event["lasuite"]["actor"] == {"type": "service"} + assert event["service"]["origin"] == {"name": "roomkit"} + assert "user" not in event + assert "organization" not in event + + +def test_audit_log_target_service(audit_events): + """A peer service the backend called is the target service.""" + audit.log("something", target_service="summary") + + event = audit_events[0] + + assert event["service"]["target"] == {"name": "summary"} + assert "origin" not in event["service"] + assert "target_service" not in event.get("lasuite", {}).get("details", {}) + + +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", "sub": user.sub} + assert event["user"] == {"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", "sub": user.sub} + 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_explicit_no_actor_ignores_the_signed_in_account(audit_events): + """``actor=None`` records no account, whoever the request is signed in as.""" + request = RequestFactory().get("/") + request.user = UserFactory(email="user@example.com") + + audit.log("something", request=request, actor=None) + + event = audit_events[0] + + assert event["lasuite"]["actor"] == {"type": "anonymous"} + assert "user" not in event + assert "organization" not in event + assert "example.com" not in json.dumps(event) + + +def test_audit_log_explicit_actor_type_alone_keeps_the_signed_in_account( + audit_events, +): + """Forcing the actor type does not discard the account of the request.""" + user = UserFactory(email="user@example.com") + request = RequestFactory().get("/") + request.user = user + + audit.log("something", request=request, actor_type="anonymous") + + assert audit_events[0]["user"]["id"] == str(user.pk) + + +def test_audit_log_application_without_an_account(audit_events): + """An application acting for nobody keeps its tenant but no user.""" + request = RequestFactory().get("/") + request.user = UserFactory(email="user@example.com") + + audit.log( + "something", + request=request, + actor=None, + actor_type="application", + client_id="app-1", + ) + + event = audit_events[0] + + assert event["lasuite"]["actor"] == {"type": "application"} + assert event["lasuite"]["application"] == {"client_id": "app-1"} + assert "user" not in event + assert event["organization"] == {"id": "app-1"} + + +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["ecs"] == {"version": "9.5.0"} + assert rendered["data_stream"]["dataset"] == "meet.audit" + assert rendered["event"] == {"dataset": "meet.audit", "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 000000000..245bab517 --- /dev/null +++ b/src/backend/core/tests/audit/test_registry.py @@ -0,0 +1,94 @@ +"""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 Application, 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_register_refuses_unknown_entity_types(): + """An entity type ECS does not allow fails where it is registered.""" + with pytest.raises(ValueError, match="not an ECS entity type"): + audit.register(Resource, entity_type="room") + + 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 model_options(Application).entity_type == "application" + 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 000000000..14ae7a9bb --- /dev/null +++ b/src/backend/core/tests/audit/test_request.py @@ -0,0 +1,271 @@ +"""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_request_context_reads_the_request(dockerflow_request_id): + """Should read the network fields and the request id of a request.""" + request = RequestFactory().post( + "/rooms/", + REMOTE_ADDR="1.2.3.4", + HTTP_USER_AGENT="Mozilla/5.0 (X11; Linux x86_64)", + ) + + context = audit_request.RequestContext.from_request(request) + + assert context == audit_request.RequestContext( + request=request, + request_id=dockerflow_request_id, + method="POST", + path="/rooms/", + client_ip="1.2.3.4", + user_agent="Mozilla/5.0 (X11; Linux x86_64)", + ) + + +def test_request_context_truncates_the_user_agent(): + """A user agent is cut where ECS stops indexing it.""" + request = RequestFactory().get("/", HTTP_USER_AGENT="x" * 5000) + + context = audit_request.RequestContext.from_request(request) + + assert context.user_agent == "x" * audit_request.USER_AGENT_MAX_LENGTH + + +def test_request_context_without_a_user_agent(): + """Should have no user agent when the client sent none.""" + context = audit_request.RequestContext.from_request(RequestFactory().get("/")) + + assert context.user_agent is None + + +def test_request_context_outside_a_request(): + """Should have an empty request context when no request is being served.""" + assert audit_request.request_context() == audit_request.RequestContext() + + +def test_middleware_sets_the_request_context_while_serving(): + """Should expose the request context to the code serving it, then forget it.""" + seen = [] + + def view(request): # pylint: disable=unused-argument + seen.append(audit_request.request_context()) + return HttpResponse() + + request = RequestFactory().get( + "/rooms/", REMOTE_ADDR="1.2.3.4", HTTP_USER_AGENT="calendar-app/2.3" + ) + response = audit_request.AuditLogMiddleware(view)(request) + + assert seen == [ + audit_request.RequestContext( + request=request, + request_id=response["X-Request-ID"], + method="GET", + path="/rooms/", + client_ip="1.2.3.4", + user_agent="calendar-app/2.3", + ) + ] + assert audit_request.request_context() == audit_request.RequestContext() + + +def test_middleware_forgets_the_request_context_when_the_view_raises(): + """Should not leak the request context 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.request_context() == audit_request.RequestContext() 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 000000000..73c860114 --- /dev/null +++ b/src/backend/core/tests/audit/test_signals.py @@ -0,0 +1,179 @@ +"""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), "domain": "example.com"} + assert event["lasuite"]["actor"] == {"type": "user", "sub": user.sub} + 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"] + 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_in_a_signed_in_session_is_anonymous(audit_events): + """A failed login never records the account the session is signed in as.""" + request = _request_with_session("post") + request.user = UserFactory(email="signed-in@example.com") + + assert authenticate(request=request, username="nobody", password="s3cret") is None + + [event] = find_events(audit_events, "user.login") + + assert event["lasuite"]["actor"] == {"type": "anonymous"} + assert "user" not in event + assert "organization" not in event + assert "example.com" 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 000000000..a6930cee9 --- /dev/null +++ b/src/backend/core/tests/audit/test_targets.py @@ -0,0 +1,150 @@ +"""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 ( + ApplicationFactory, + RecordingFactory, + RoomFactory, + UserFactory, +) +from core.models import Application, Recording, Resource, Room + +pytestmark = pytest.mark.django_db + + +def test_describe_target_reads_the_registered_fields(): + """A model is an ECS entity: its key, its model name and its registered fields.""" + room = RoomFactory() + + with override_registration(Room, fields=("slug", "access_level")): + described = describe_target(room) + + assert described == { + "id": str(room.pk), + "sub_type": "room", + "raw": {"slug": room.slug, "access_level": room.access_level}, + } + + +def test_describe_target_promotes_its_name(): + """A registered ``name`` is the ECS ``entity.name``, not a raw field.""" + room = RoomFactory(name="Daily standup") + + with override_registration(Room, fields=("name", "slug")): + described = describe_target(room) + + assert described == { + "id": str(room.pk), + "sub_type": "room", + "name": "Daily standup", + "raw": {"slug": room.slug}, + } + + +def test_describe_target_reports_the_registered_entity_type(): + """A model registered with an ECS entity type is of that type.""" + application = ApplicationFactory() + + with override_registration(Application, entity_type="application"): + described = describe_target(application) + + assert described == { + "id": str(application.pk), + "type": ["application"], + "sub_type": "application", + } + + +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 == { + "id": str(recording.pk), + "sub_type": "recording", + "raw": {"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 == {"id": str(room.pk), "sub_type": "room"} + + +def test_describe_target_identifies_users_without_their_email(): + """A user is an ECS user entity, identified by its key and OIDC sub.""" + user = UserFactory(email="jane@Example.org", sub="oidc-sub-1") + + described = describe_target(user) + + assert described == { + "id": str(user.pk), + "type": ["user"], + "sub_type": "user", + "raw": {"sub": "oidc-sub-1"}, + } + assert "example.org" not in str(described).lower() + + +def test_describe_target_of_a_user_without_sub(): + """A user who never signed in, such as a provisional one, has no sub.""" + user = UserFactory(email="jane@example.org", sub=None) + + assert describe_target(user) == { + "id": str(user.pk), + "type": ["user"], + "sub_type": "user", + } + + +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 == { + "id": str(room.pk), + "sub_type": "room", + "raw": {"slug": room.slug}, + } + + +def test_describe_target_mapping_passes_through(): + """A ready-made dict is used verbatim.""" + assert describe_target({"sub_type": "x", "id": "1"}) == { + "sub_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()) == {"id": "thing-1", "sub_type": "thing"} + + +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 000000000..7f0dfde8d --- /dev/null +++ b/src/backend/core/tests/audit/test_utils_prune_empty.py @@ -0,0 +1,44 @@ +""" +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 + + +def test_prune_empty_keeps_values_below_depth_whole(): + """Should prune only ``depth`` levels and keep anything deeper as it is.""" + document = { + "none": None, + "empty": {}, + "change": {"from": None, "to": {}}, + "deeper": {"inner": {"none": None}}, + } + + assert prune_empty(document, depth=1) == { + "change": {"from": None, "to": {}}, + "deeper": {"inner": {"none": None}}, + } + assert prune_empty(document, depth=2) == {"deeper": {"inner": {"none": None}}} + assert prune_empty(document, depth=0) is document diff --git a/src/backend/core/tests/conftest.py b/src/backend/core/tests/conftest.py index b8beeced6..2dc311f38 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 19c8dd942..fef0a35ec 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 f39a633bb..19043d520 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,31 @@ 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 + ) + AUDIT_LOG_DATA_STREAM_NAMESPACE = values.Value( + "default", environ_name="AUDIT_LOG_DATA_STREAM_NAMESPACE", 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 +1261,9 @@ class Base(Configuration): "format": "{asctime} {name} {levelname} {message}", "style": "{", }, + "audit_json": { + "()": "core.audit.formatter.AuditJsonFormatter", + }, }, "filters": { "silence_expected_401": { @@ -1239,6 +1276,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 +1313,11 @@ class Base(Configuration): ), "propagate": False, }, + "audit": { + "handlers": ["audit_console"], + "level": AUDIT_LOG_LEVEL, + "propagate": False, + }, }, } @@ -1384,6 +1431,18 @@ class Base(Configuration): stacklevel=2, ) + @classmethod + def _check_audit_log_data_stream_namespace(cls): + """Ensure the audit data stream namespace contains no ``-``. + + ECS splits data stream names ``--`` on - + """ + if "-" in cls.AUDIT_LOG_DATA_STREAM_NAMESPACE: + raise ValueError( + "AUDIT_LOG_DATA_STREAM_NAMESPACE " + f"'{cls.AUDIT_LOG_DATA_STREAM_NAMESPACE}' must not contain '-'." + ) + @classmethod def post_setup(cls): """Post setup configuration. @@ -1398,6 +1457,7 @@ class Base(Configuration): ) cls._check_recording_encoding_maps() + cls._check_audit_log_data_stream_namespace() if ( cls.SUMMARY_SERVICE_VERSION == 1 @@ -1451,6 +1511,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 +1564,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, + }, }, } )