✨(backend) add structured audit logging facility

Add a core.audit package emitting one ECS-shaped JSON line per
security-relevant action on a dedicated "audit" logger.

The audit logs reads the actor, auth method, tenant and network fields from
the request it is given, else from the request being served, which
AuditLogMiddleware keeps in a context variable so that a service needs
no request argument.

A person is identified by primary key, OIDC sub when the account has one
and email domain. The tenant is the application client id, else that
domain. The client IP is DRF's throttle ident, which now honours a
NUM_PROXIES setting.

The middleware also replaces the inbound X-Request-ID with a fresh id,
unless REQUEST_ID_TRUST_HEADER says the ingress overwrites it, and echoes
it in the response and the gunicorn access log. Audit events carry it as
trace.id.

An action is defined with a dotted name with its default ECS category
and types, validated at import, so a call site only names what was
attempted. A category or types given to audit.log win over them, and a
bare dotted name is accepted too.

 Meet declares all of the events core/auditing.py:
- audit.register lists the fields describing a model as a target. Every
  target carries its model name and primary key, so an unregistered one
  is still identified, and a user target its OIDC sub and email domain.
- audit.register_auth_method names the lasuite.auth.method of a DRF
  authentication class

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