From 2b2d4a72ae5c6b63c80d43af9fb3f2d44b7b2f25 Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Mon, 19 Oct 2026 21:19:39 +0100 Subject: [PATCH 01/12] Harden WebSocket message handling and stop logging secrets - Log only op name and size for WS messages (payloads carry JWTs) - Validate DATA for leader ops; ignore non-object frames and non-string ops - Guard update_session against a deleted user - Recursively redact sensitive keys from REST request body logs; do not log non-JSON bodies - Default log_level to INFO Co-Authored-By: Claude Sonnet 5.5 --- server/controllers/ws_controller.py | 58 ++++++++++++---- server/digi_server/settings.py | 2 +- server/test/controllers/test_ws_controller.py | 66 ++++++++++++++++++ server/test/utils/web/test_log_redaction.py | 69 +++++++++++++++++++ server/utils/web/base_controller.py | 6 +- server/utils/web/log_redaction.py | 46 +++++++++++++ 6 files changed, 233 insertions(+), 14 deletions(-) create mode 100644 server/test/utils/web/test_log_redaction.py create mode 100644 server/utils/web/log_redaction.py diff --git a/server/controllers/ws_controller.py b/server/controllers/ws_controller.py index 5953c27d..7fd2baaf 100644 --- a/server/controllers/ws_controller.py +++ b/server/controllers/ws_controller.py @@ -131,8 +131,12 @@ def update_session(self, user_id=None) -> bool: user_id=user_id, ) ) - if self.current_user_id: - user = session.get(User, self.current_user_id) + user = ( + session.get(User, self.current_user_id) + if self.current_user_id + else None + ) + if user is not None: user.last_seen = datetime.datetime.now(tz=datetime.timezone.utc) session.commit() return cleared @@ -466,17 +470,25 @@ async def on_message(self, message: Union[str, bytes]): if self.current_username else self.request.remote_ip ) - get_logger().debug(f"WebSocket message from {user_part}: {message}") + size = len(message) try: message = json.loads(message) ws_op = message["OP"] - except (json.JSONDecodeError, KeyError) as e: + if not isinstance(ws_op, str): + raise TypeError("OP must be a string") + except (json.JSONDecodeError, KeyError, TypeError) as e: get_logger().warning( - f"Malformed WS message from {self.request.remote_ip}: {e}" + f"Malformed WS message ({size} bytes) from " + f"{self.request.remote_ip}: {type(e).__name__}" ) return + # Never log the payload: AUTHENTICATE / REFRESH_TOKEN carry live JWTs. + get_logger().debug( + f"WebSocket message from {user_part}: {ws_op} ({size} bytes)" + ) + # Connection boundary: an exception escaping on_message ends Tornado's # read loop without calling on_close, leaving a handler that no longer # reads frames but still counts as a connected owner. Each op keeps its @@ -535,8 +547,12 @@ async def _handle_session_op(self, ws_op: str, message: dict) -> None: ) # Ownership rule: only the authenticated show user on its own row. if self._is_leader(session, show_session): + data = message.get("DATA") + if not isinstance(data, dict): + get_logger().warning(f"Ignored {ws_op}: DATA must be an object") + return handler = getattr(self, self._LEADER_OP_HANDLERS[ws_op]) - await handler(session, show_session, entry, message["DATA"]) + await handler(session, show_session, entry, data) else: get_logger().debug( f"Ignored {ws_op} from client " @@ -551,7 +567,7 @@ async def _handle_session_op(self, ws_op: str, message: dict) -> None: ) if show_session and self._user_has_show_execute_access(session, show): await self._op_jump_to_page( - session, show_session, entry, message["DATA"] + session, show_session, entry, message.get("DATA") ) else: get_logger().debug( @@ -637,19 +653,35 @@ def _resume_client(self, new_uuid: Any) -> None: async def _op_script_scroll(self, session, show_session, entry, data) -> None: """Leader op ``SCRIPT_SCROLL``: record and broadcast the leader's line.""" - show_session.latest_line_ref = data["current_line"] + line_ref = data.get("current_line") + if not isinstance(line_ref, str): + get_logger().warning("Ignored SCRIPT_SCROLL: invalid current_line") + return + show_session.latest_line_ref = line_ref session.commit() await self.application.ws_send_to_all("NOOP", "SCRIPT_SCROLL", data) async def _op_begin_interval(self, session, show_session, entry, data) -> None: """Leader op ``BEGIN_INTERVAL``: start an interval after the given act.""" - act: Act = session.get(Act, data["actId"]) - if not entry: + act_id = data.get("actId") + length = data.get("length") + if ( + not entry + or isinstance(act_id, bool) + or not isinstance(act_id, int) + or isinstance(length, bool) + or not isinstance(length, (int, float)) + ): + get_logger().warning("Ignored BEGIN_INTERVAL: invalid actId or length") + return + act: Optional[Act] = session.get(Act, act_id) + if act is None: + get_logger().warning("Ignored BEGIN_INTERVAL: unknown act") return show_interval = Interval( session_id=show_session.id, act_id=act.id, - initial_length=data["length"], + initial_length=length, ) session.add(show_interval) session.flush() @@ -825,7 +857,9 @@ async def _handle_script_room_op(self, ws_op: str, message: dict): get_logger().warning("RoomManager not available, ignoring collab OP") return - data = message.get("DATA", {}) + data = message.get("DATA") + if not isinstance(data, dict): + data = {} # Everything that touches the shared draft only exists in collaborative mode; # in classic mode a stray client must not be able to open a room. diff --git a/server/digi_server/settings.py b/server/digi_server/settings.py index ae5b73b3..37737242 100644 --- a/server/digi_server/settings.py +++ b/server/digi_server/settings.py @@ -265,7 +265,7 @@ def init_settings(self): self.define( "log_level", str, - "DEBUG", + "INFO", True, self._application.regen_logging, display_name="Log Level", diff --git a/server/test/controllers/test_ws_controller.py b/server/test/controllers/test_ws_controller.py index 08525d2f..296bb8d4 100644 --- a/server/test/controllers/test_ws_controller.py +++ b/server/test/controllers/test_ws_controller.py @@ -3474,6 +3474,72 @@ async def test_jump_to_page_without_page_does_not_kill_connection(self): await self._still_responsive(ws_l, self.admin_id) ws_l.close() + @gen_test + async def test_leader_ops_with_malformed_data_are_ignored(self): + """Non-object / wrong-typed DATA on leader ops is rejected without + changing state or killing the connection. + """ + ws_l, uuid_l = await self._connect_and_auth(self.admin_id) + self._start_live_session(uuid_l, self.admin_id) + + def latest(): + with self._app.get_db().sessionmaker() as session: + show = session.get(Show, self.show_id) + live = session.get(ShowSession, show.current_session_id) + return live.latest_line_ref + + before = latest() + for op in ("SCRIPT_SCROLL", "BEGIN_INTERVAL", "END_INTERVAL"): + for bad in (None, [], "x", 5): + await ws_l.write_message(json.dumps({"OP": op, "DATA": bad})) + await ws_l.write_message(json.dumps({"OP": op})) + await ws_l.write_message( + json.dumps({"OP": "SCRIPT_SCROLL", "DATA": {"current_line": ["x"]}}) + ) + await ws_l.write_message( + json.dumps({"OP": "BEGIN_INTERVAL", "DATA": {"actId": "a", "length": 1}}) + ) + await ws_l.write_message(json.dumps({"OP": "LIVE_SHOW_JUMP_TO_PAGE"})) + await self._still_responsive(ws_l, self.admin_id) + self.assertEqual(before, latest()) + ws_l.close() + + @gen_test + async def test_non_object_and_non_string_op_frames_are_ignored(self): + ws, _ = await self._connect_and_auth(self.admin_id) + for frame in ("[]", '"abc"', "5", "null", '{"OP": ["x"]}', '{"OP": {}}'): + await ws.write_message(frame) + await self._still_responsive(ws, self.admin_id) + ws.close() + + @gen_test + async def test_ws_payload_and_tokens_are_not_logged(self): + """AUTHENTICATE tokens never reach the log; only op name and size do.""" + ws, _ = await self._connect_and_auth() + sentinel = self._app.jwt_service.create_access_token( + data={"user_id": self.admin_id} + ) + with self.assertLogs(get_logger(), level="DEBUG") as captured: + await ws.write_message( + json.dumps({"OP": "AUTHENTICATE", "DATA": {"token": sentinel}}) + ) + await self._read_until(ws, op="WS_AUTH_SUCCESS") + joined = "\n".join(captured.output) + self.assertIn("AUTHENTICATE", joined) + self.assertNotIn(sentinel, joined) + ws.close() + + @gen_test + async def test_update_session_survives_deleted_user(self): + ws, uuid = await self._connect_and_auth(self.admin2_id) + handler = self._app.get_ws(uuid) + with self._app.get_db().sessionmaker() as session: + session.get(Session, uuid).user_id = None + session.delete(session.get(User, self.admin2_id)) + session.commit() + handler.update_session() # must not raise + ws.close() + @gen_test async def test_db_error_in_reconcile_leaves_connection_unauthenticated(self): """A failure while settling ownership must not leave the socket half diff --git a/server/test/utils/web/test_log_redaction.py b/server/test/utils/web/test_log_redaction.py new file mode 100644 index 00000000..1f25e8b5 --- /dev/null +++ b/server/test/utils/web/test_log_redaction.py @@ -0,0 +1,69 @@ +import json +import unittest + +from tornado.httpclient import HTTPRequest +from tornado.testing import gen_test + +from test.conftest import DigiScriptTestCase +from utils.web.log_redaction import REDACTED, redact_sensitive_keys + + +class TestRedactSensitiveKeys(unittest.TestCase): + def test_redacts_nested_and_case_insensitive(self): + data = { + "username": "bob", + "Password": "p1", + "nested": {"new_password": "p2", "list": [{"api_token": "t"}, 3]}, + "token": "abc", + } + result = redact_sensitive_keys(data) + self.assertEqual("bob", result["username"]) + self.assertEqual(REDACTED, result["Password"]) + self.assertEqual(REDACTED, result["nested"]["new_password"]) + self.assertEqual(REDACTED, result["nested"]["list"][0]["api_token"]) + self.assertEqual(3, result["nested"]["list"][1]) + self.assertEqual(REDACTED, result["token"]) + + def test_does_not_mutate_input(self): + data = {"password": "p"} + redact_sensitive_keys(data) + self.assertEqual({"password": "p"}, data) + + def test_scalars_pass_through(self): + self.assertEqual("x", redact_sensitive_keys("x")) + self.assertIsNone(redact_sensitive_keys(None)) + + +class TestRestBodyLogging(DigiScriptTestCase): + @gen_test + async def test_sentinel_secrets_never_logged(self): + body = { + "username": "nobody", + "password": "SENTINEL-PASSWORD", + "extra": {"access_token": "SENTINEL-TOKEN"}, + } + request = HTTPRequest( + self.get_url("/api/v1/auth/login"), + method="POST", + body=json.dumps(body), + ) + with self.assertLogs(level="DEBUG") as captured: + await self.http_client.fetch(request, raise_error=False) + joined = "\n".join(captured.output) + self.assertIn("/api/v1/auth/login", joined) + self.assertNotIn("SENTINEL-PASSWORD", joined) + self.assertNotIn("SENTINEL-TOKEN", joined) + + @gen_test + async def test_non_json_body_not_logged(self): + request = HTTPRequest( + self.get_url("/api/v1/auth/login"), + method="POST", + body="password=SENTINEL-RAW", + ) + with self.assertLogs(level="DEBUG") as captured: + await self.http_client.fetch(request, raise_error=False) + self.assertNotIn("SENTINEL-RAW", "\n".join(captured.output)) + + def test_default_log_level_is_info(self): + self.assertEqual("INFO", self._app.digi_settings.settings["log_level"].default) diff --git a/server/utils/web/base_controller.py b/server/utils/web/base_controller.py index 0794f217..e1a42f52 100644 --- a/server/utils/web/base_controller.py +++ b/server/utils/web/base_controller.py @@ -15,6 +15,7 @@ from models.user import User from rbac.role import Role from schemas.schemas import ShowSchema, UserSchema +from utils.web.log_redaction import redact_sensitive_keys if TYPE_CHECKING: @@ -182,8 +183,10 @@ def on_finish(self): try: body = escape.json_decode(self.request.body) except BaseException: + # Not JSON, so it cannot be redacted by key: log only its size. get_logger().debug( - f"{self.request.method} {self.request.path} {self.request.body}{user_suffix}", + f"{self.request.method} {self.request.path} " + f"{user_suffix}", extra=self._log_extra(), ) else: @@ -195,6 +198,7 @@ def on_finish(self): ): body = deepcopy(body) redacted_data_paths.apply(body) + body = redact_sensitive_keys(body) log_method( f"{self.request.method} {self.request.path} {body}{user_suffix}", diff --git a/server/utils/web/log_redaction.py b/server/utils/web/log_redaction.py new file mode 100644 index 00000000..01733751 --- /dev/null +++ b/server/utils/web/log_redaction.py @@ -0,0 +1,46 @@ +"""Key-based redaction of secrets from structured data before it is logged.""" + +from __future__ import annotations + +from typing import Any + + +REDACTED = "<-- REDACTED -->" + +# Lower-cased dict keys whose values must never reach a log file. +SENSITIVE_KEYS = frozenset( + { + "password", + "new_password", + "old_password", + "current_password", + "token", + "access_token", + "refresh_token", + "api_token", + "secret", + } +) + + +def redact_sensitive_keys(value: Any) -> Any: + """Return a copy of *value* with the values of sensitive keys replaced. + + Recurses through dicts and lists. Key matching is case-insensitive. The input + is not modified. + + :param value: Decoded JSON data (dict, list or scalar). + :returns: A redacted copy. + """ + if isinstance(value, dict): + return { + key: ( + REDACTED + if isinstance(key, str) and key.lower() in SENSITIVE_KEYS + else redact_sensitive_keys(item) + ) + for key, item in value.items() + } + if isinstance(value, list): + return [redact_sensitive_keys(item) for item in value] + return value From 8d9e2fc64f61e0f9ab5216be280682a1fc6e6b6f Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Mon, 19 Oct 2026 21:20:45 +0100 Subject: [PATCH 02/12] Require auth and bound client log posts; stop disclosing server paths and /debug Client log endpoints now require login, cap batch size, message and extra size, and rate-limit per IP. Filesystem path settings are only returned to admins (and never broadcast), and /debug is admin-only. Both clients hold pre-login log entries until a token exists. Co-Authored-By: Claude Sonnet 5.5 --- client-v3/src/js/logger.ts | 15 +- client/src/js/logger.ts | 15 +- docs/pages/user_config.md | 2 + server/controllers/api/v1/logging.py | 114 ++++++++++++- server/controllers/api/v1/settings.py | 6 +- server/controllers/controllers.py | 3 + server/digi_server/settings.py | 32 +++- .../test/controllers/api/v1/test_logging.py | 154 ++++++++++++------ .../test/controllers/api/v1/test_settings.py | 56 +++++++ server/test/digi_server/test_digi_server.py | 3 +- 10 files changed, 335 insertions(+), 65 deletions(-) diff --git a/client-v3/src/js/logger.ts b/client-v3/src/js/logger.ts index fbcc197e..be45f57d 100644 --- a/client-v3/src/js/logger.ts +++ b/client-v3/src/js/logger.ts @@ -33,11 +33,20 @@ function flushQueue() { flushTimer = null; if (logQueue.length === 0) return; + // The server only accepts log posts from logged-in users. Before login, keep the + // most recent entries queued (bounded) and send them once a token exists. + const token = useUserStore().authToken; + if (!token) { + if (logQueue.length > MAX_QUEUE_SIZE) logQueue.splice(0, logQueue.length - MAX_QUEUE_SIZE); + return; + } + const batch = logQueue.splice(0); - const token = useUserStore().authToken; - const headers: Record = { 'Content-Type': 'application/json' }; - if (token) headers['Authorization'] = `Bearer ${token}`; + const headers: Record = { + 'Content-Type': 'application/json', + Authorization: `Bearer ${token}`, + }; fetch(makeURL('/api/v1/logs/batch'), { method: 'POST', diff --git a/client/src/js/logger.ts b/client/src/js/logger.ts index 9df953cd..3185ee60 100644 --- a/client/src/js/logger.ts +++ b/client/src/js/logger.ts @@ -39,11 +39,20 @@ function flushQueue() { flushTimer = null; if (logQueue.length === 0) return; + // The server only accepts log posts from logged-in users. Before login, keep the + // most recent entries queued (bounded) and send them once a token exists. + const token = store.getters.AUTH_TOKEN; + if (!token) { + if (logQueue.length > MAX_QUEUE_SIZE) logQueue.splice(0, logQueue.length - MAX_QUEUE_SIZE); + return; + } + const batch = logQueue.splice(0); - const token = store.getters.AUTH_TOKEN; - const headers: Record = { 'Content-Type': 'application/json' }; - if (token) headers['Authorization'] = `Bearer ${token}`; + const headers: Record = { + 'Content-Type': 'application/json', + Authorization: `Bearer ${token}`, + }; fetch(makeURL('/api/v1/logs/batch'), { method: 'POST', diff --git a/docs/pages/user_config.md b/docs/pages/user_config.md index 3275ba11..38c47ec5 100644 --- a/docs/pages/user_config.md +++ b/docs/pages/user_config.md @@ -91,6 +91,8 @@ All log entries are attributed to the logged-in user where one is present: - **Server logs**: Each HTTP access log line and request-body debug line includes `[username]` in the message (e.g. `200 GET /api/v1/user/settings (127.0.0.1) [alice] 5.23ms`). WebSocket messages and close events also include the username once the connection has been authenticated. - **Client logs**: The server extracts the username from the JWT token on each batch submission, so all client log entries are attributed even if the client sends no user information itself. +- **Client log limits**: Submitting client logs requires being logged in, so entries generated before login are held in the browser and sent after login. A single batch may contain at most 100 entries, messages are truncated at 4 KB, oversized extra data is dropped, and each IP address is limited to 600 entries per minute (further entries are rejected until the window resets). +- **Server file paths**: The database, log, compiled script and draft script locations are only shown to administrators (on the Settings tab); other users and logged-out visitors never receive them. #### Filtering diff --git a/server/controllers/api/v1/logging.py b/server/controllers/api/v1/logging.py index 75856952..cf87657d 100644 --- a/server/controllers/api/v1/logging.py +++ b/server/controllers/api/v1/logging.py @@ -1,4 +1,6 @@ -from typing import Any, Dict, List +import json +import time +from typing import Any, Dict, List, Optional from tornado import escape, httputil @@ -6,6 +8,76 @@ from digi_server.logger import get_logger, map_client_level from utils.web.base_controller import BaseAPIController from utils.web.route import ApiRoute, ApiVersion +from utils.web.web_decorators import api_authenticated + + +#: Maximum number of entries accepted in one batch request. +MAX_BATCH_ENTRIES = 100 +#: Maximum length (characters) of a single log message; longer ones are truncated. +MAX_MESSAGE_LENGTH = 4096 +#: Maximum serialised size (characters) of an entry's ``extra``; larger is replaced. +MAX_EXTRA_LENGTH = 4096 +#: Per-IP budget: at most this many log entries per window. +RATE_LIMIT_ENTRIES = 600 +RATE_LIMIT_WINDOW_SECONDS = 60.0 + + +class ClientLogRateLimiter: + """Fixed-window, per-IP limiter on the number of client log entries. + + One instance lives on the application object, so no state is shared between + application instances (or test workers). + """ + + def __init__( + self, + limit: int = RATE_LIMIT_ENTRIES, + window: float = RATE_LIMIT_WINDOW_SECONDS, + ): + self.limit = limit + self.window = window + self._windows: Dict[str, tuple] = {} + + def check(self, key: str, cost: int, now: Optional[float] = None) -> float: + """Try to consume *cost* entries for *key*. + + :param key: The client identifier (IP address). + :param cost: Number of entries in the request. + :param now: Current monotonic time; defaults to ``time.monotonic()``. + :returns: 0 if allowed, otherwise the seconds until the window resets. + """ + now = time.monotonic() if now is None else now + # Drop expired windows so the dict stays bounded by active clients. + expired = [ + ip for ip, (start, _) in self._windows.items() if now - start >= self.window + ] + for ip in expired: + del self._windows[ip] + start, used = self._windows.get(key, (now, 0)) + if used + cost > self.limit: + return max(self.window - (now - start), 1.0) + self._windows[key] = (start, used + cost) + return 0.0 + + +def _clean_text(value: Any, limit: int) -> str: + """Coerce *value* to a bounded, single-line string safe to write to a log.""" + text = value if isinstance(value, str) else str(value) + if len(text) > limit: + text = text[:limit] + "...[truncated]" + return text.replace("\r", "\\r").replace("\n", "\\n") + + +def _clean_extra(value: Any) -> Dict: + """Return *value* if it is a small JSON-serialisable dict, else a stand-in.""" + if not isinstance(value, dict): + return {} + try: + if len(json.dumps(value, default=str)) > MAX_EXTRA_LENGTH: + return {"extra": "[omitted: too large]"} + except (TypeError, ValueError): + return {"extra": "[omitted: not serialisable]"} + return {str(k): v for k, v in value.items()} class ClientLoggingBase(BaseAPIController): @@ -18,20 +90,41 @@ def __init__( super().__init__(application, request, **kwargs) self.client_logger = get_logger("Client") - def process_logs(self, entries: List[Dict]): + def process_logs(self, entries: List[Any]): + """Validate, bound and write a list of client log entries. + + Responds 429 (with ``Retry-After``) if the caller's IP exceeded its budget. + + :param entries: The raw entries from the request body. + """ + limiter = getattr(self.application, "client_log_limiter", None) + if limiter is None: + limiter = ClientLogRateLimiter() + self.application.client_log_limiter = limiter + retry_after = limiter.check(self.request.remote_ip or "unknown", len(entries)) + if retry_after: + self.set_status(429) + self.set_header("Retry-After", str(int(retry_after) + 1)) + self.write({"message": "Too many log entries"}) + return + # Build request-level context added to every entry's extra request_extra = { "remote_ip": self.request.remote_ip, - "agent": self.request.headers.get("User-Agent", "Unknown"), + "agent": _clean_text( + self.request.headers.get("User-Agent", "Unknown"), 256 + ), } if self.current_user: request_extra["user_id"] = self.current_user.get("id") request_extra["username"] = self.current_user.get("username") for entry in entries: - level = entry.get("level", "INFO").upper() - message = entry.get("message", "") - extra = {**entry.get("extra", {}), **request_extra} + if not isinstance(entry, dict): + continue + level = _clean_text(entry.get("level", "INFO"), 16).upper() + message = _clean_text(entry.get("message", ""), MAX_MESSAGE_LENGTH) + extra = {**_clean_extra(entry.get("extra")), **request_extra} log_level = map_client_level(level) @@ -58,6 +151,7 @@ def process_logs(self, entries: List[Dict]): @ApiRoute("logs/batch", ApiVersion.V1, ignore_logging=True) class ClientLoggingBatchController(ClientLoggingBase): + @api_authenticated async def post(self): client_log_enabled = await self.application.digi_settings.get( "client_log_enabled" @@ -85,11 +179,19 @@ async def post(self): self.write({"message": "Expected 'batch' to be a list of log entries"}) return + if len(batch) > MAX_BATCH_ENTRIES: + self.set_status(413) + self.write( + {"message": f"Batch exceeds the {MAX_BATCH_ENTRIES} entry limit"} + ) + return + self.process_logs(batch) @ApiRoute("logs", ApiVersion.V1, ignore_logging=True) class ClientLoggingController(ClientLoggingBase): + @api_authenticated async def post(self): client_log_enabled = await self.application.digi_settings.get( "client_log_enabled" diff --git a/server/controllers/api/v1/settings.py b/server/controllers/api/v1/settings.py index 94a8f984..ea1411ba 100644 --- a/server/controllers/api/v1/settings.py +++ b/server/controllers/api/v1/settings.py @@ -51,7 +51,8 @@ async def _collab_mode_change_blocked(self, settings: Settings, data: dict) -> b @allow_when_password_required async def get(self): settings: Settings = self.application.digi_settings - settings_json = await settings.as_json() + is_admin = bool(self.current_user and self.current_user["is_admin"]) + settings_json = await settings.as_json(include_sensitive=is_admin) await self.finish(settings_json) @api_authenticated @@ -114,5 +115,6 @@ async def get(self): class RawSettingsController(BaseAPIController): async def get(self): settings: Settings = self.application.digi_settings - settings_json = await settings.raw_json() + is_admin = bool(self.current_user and self.current_user["is_admin"]) + settings_json = await settings.raw_json(include_sensitive=is_admin) await self.finish(settings_json) diff --git a/server/controllers/controllers.py b/server/controllers/controllers.py index d5b67150..183beadf 100644 --- a/server/controllers/controllers.py +++ b/server/controllers/controllers.py @@ -9,6 +9,7 @@ from utils.module_discovery import get_resource_path, import_modules, is_frozen from utils.web.base_controller import BaseAPIController, BaseController from utils.web.route import ApiRoute, ApiVersion, Route +from utils.web.web_decorators import api_authenticated, require_admin IMPORTED_CONTROLLERS = {} @@ -128,6 +129,8 @@ def delete(self): @Route("/debug") class DebugController(BaseController): + @api_authenticated + @require_admin def get(self): self.set_status(200) self.set_header("Content-Type", "application/json") diff --git a/server/digi_server/settings.py b/server/digi_server/settings.py index ae5b73b3..a1b909c9 100644 --- a/server/digi_server/settings.py +++ b/server/digi_server/settings.py @@ -170,6 +170,20 @@ def as_json(self): } +#: Settings holding server filesystem locations. They are only disclosed to +#: administrators; everyone else (and every broadcast) gets them omitted. +SENSITIVE_SETTINGS = frozenset( + { + "db_path", + "log_path", + "db_log_path", + "client_log_path", + "compiled_script_path", + "draft_script_path", + } +) + + class Settings: def __init__(self, application: DigiScriptServer, settings_path=None): self._application = application @@ -595,17 +609,31 @@ def _json(self): settings_json[key] = value.get_value() return settings_json - async def as_json(self): + async def as_json(self, include_sensitive: bool = False): + """Return all setting values plus the server version. + + :param include_sensitive: Include the filesystem path settings in + :data:`SENSITIVE_SETTINGS`. Only pass True for administrators. + """ async with self.lock: settings_json = {} for key, value in self.settings.items(): + if not include_sensitive and key in SENSITIVE_SETTINGS: + continue settings_json[key] = value.get_value() settings_json["version"] = _get_version() return json.loads(json.dumps(settings_json)) - async def raw_json(self): + async def raw_json(self, include_sensitive: bool = False): + """Return full setting metadata (type, default, help text, ...). + + :param include_sensitive: Include the filesystem path settings in + :data:`SENSITIVE_SETTINGS`. Only pass True for administrators. + """ async with self.lock: settings_json = {} for key, value in self.settings.items(): + if not include_sensitive and key in SENSITIVE_SETTINGS: + continue settings_json[key] = value.as_json() return json.loads(json.dumps(settings_json)) diff --git a/server/test/controllers/api/v1/test_logging.py b/server/test/controllers/api/v1/test_logging.py index 905ed3ed..725f61be 100644 --- a/server/test/controllers/api/v1/test_logging.py +++ b/server/test/controllers/api/v1/test_logging.py @@ -1,72 +1,130 @@ import json from tornado import escape -from tornado.testing import gen_test +from controllers.api.v1.logging import ( + MAX_BATCH_ENTRIES, + MAX_MESSAGE_LENGTH, + ClientLogRateLimiter, +) +from digi_server.logger import get_logger from test.conftest import DigiScriptTestCase class TestLoggingController(DigiScriptTestCase): - @gen_test - async def test_logging_endpoint_success(self): - """Test that the logging endpoint successfully receives logs.""" + def _post(self, path, payload, token=None, body=None): + headers = {"Content-Type": "application/json"} + if token: + headers["Authorization"] = f"Bearer {token}" + return self.fetch( + path, + method="POST", + body=body if body is not None else json.dumps(payload), + headers=headers, + ) + + def test_logging_endpoint_success(self): + token = self._create_and_login_admin() payload = { "level": "INFO", "message": "Test message from client", "extra": {"source": "unit-test"}, } - response = await self.http_client.fetch( - self.get_url("/api/v1/logs"), - method="POST", - body=json.dumps(payload), - headers={"Content-Type": "application/json"}, - ) + response = self._post("/api/v1/logs", payload, token) self.assertEqual(200, response.code) - data = escape.json_decode(response.body) - self.assertEqual("OK", data["status"]) + self.assertEqual("OK", escape.json_decode(response.body)["status"]) - @gen_test - async def test_logging_endpoint_disabled(self): - """Test that the logging endpoint returns 403 when disabled in settings.""" - # Disable client logging in settings - await self._app.digi_settings.set("client_log_enabled", False) + def test_logging_requires_authentication(self): + payload = {"level": "INFO", "message": "anonymous"} + with self.assertNoLogs(get_logger("Client"), level="DEBUG"): + self.assertEqual(401, self._post("/api/v1/logs", payload).code) + self.assertEqual( + 401, self._post("/api/v1/logs/batch", {"batch": [payload]}).code + ) - payload = {"level": "INFO", "message": "Test message from client"} - response = await self.http_client.fetch( - self.get_url("/api/v1/logs"), - method="POST", - body=json.dumps(payload), - headers={"Content-Type": "application/json"}, - raise_error=False, + def test_logging_endpoint_disabled(self): + token = self._create_and_login_admin() + self.io_loop.run_sync( + lambda: self._app.digi_settings.set("client_log_enabled", False) ) + response = self._post("/api/v1/logs", {"level": "INFO", "message": "x"}, token) self.assertEqual(403, response.code) - data = escape.json_decode(response.body) - self.assertEqual("Client logging is disabled", data["message"]) - - # Re-enable for other tests - await self._app.digi_settings.set("client_log_enabled", True) - - @gen_test - async def test_logging_endpoint_invalid_json(self): - """Test that the logging endpoint returns 400 for invalid JSON.""" - response = await self.http_client.fetch( - self.get_url("/api/v1/logs"), - method="POST", - body="invalid json", - headers={"Content-Type": "application/json"}, - raise_error=False, + self.assertEqual( + "Client logging is disabled", escape.json_decode(response.body)["message"] ) + + def test_logging_endpoint_invalid_json(self): + token = self._create_and_login_admin() + response = self._post("/api/v1/logs", None, token, body="invalid json") self.assertEqual(400, response.code) - @gen_test - async def test_logging_endpoint_different_levels(self): - """Test that the logging endpoint accepts various log levels.""" + def test_logging_endpoint_different_levels(self): + token = self._create_and_login_admin() for level in ["DEBUG", "INFO", "WARN", "ERROR"]: - payload = {"level": level, "message": f"Test level {level}"} - response = await self.http_client.fetch( - self.get_url("/api/v1/logs"), - method="POST", - body=json.dumps(payload), - headers={"Content-Type": "application/json"}, + response = self._post( + "/api/v1/logs", {"level": level, "message": f"lvl {level}"}, token ) self.assertEqual(200, response.code) + + def test_batch_over_limit_rejected(self): + token = self._create_and_login_admin() + batch = [{"level": "INFO", "message": "m"}] * (MAX_BATCH_ENTRIES + 1) + self.assertEqual( + 413, self._post("/api/v1/logs/batch", {"batch": batch}, token).code + ) + batch = batch[:MAX_BATCH_ENTRIES] + self.assertEqual( + 200, self._post("/api/v1/logs/batch", {"batch": batch}, token).code + ) + + def test_message_truncated_and_newlines_escaped(self): + token = self._create_and_login_admin() + message = "A\nFAKE LOG LINE " + "x" * (MAX_MESSAGE_LENGTH * 2) + with self.assertLogs(get_logger("Client"), level="DEBUG") as logs: + response = self._post( + "/api/v1/logs", {"level": "INFO", "message": message}, token + ) + self.assertEqual(200, response.code) + out = logs.records[0].getMessage() + self.assertNotIn("\n", out) + self.assertIn("[truncated]", out) + self.assertLess(len(out), MAX_MESSAGE_LENGTH + 1500) + + def test_oversized_extra_replaced(self): + token = self._create_and_login_admin() + with self.assertLogs(get_logger("Client"), level="DEBUG") as logs: + self._post( + "/api/v1/logs", + {"level": "INFO", "message": "m", "extra": {"k": "y" * 100000}}, + token, + ) + out = logs.records[0].getMessage() + self.assertIn("too large", out) + self.assertNotIn("yyyyyyyyyy", out) + + def test_non_string_fields_coerced(self): + token = self._create_and_login_admin() + batch = [ + {"level": 5, "message": {"a": 1}, "extra": "not-a-dict"}, + {"level": None, "message": None, "extra": [1, 2]}, + "not-an-object", + ] + response = self._post("/api/v1/logs/batch", {"batch": batch}, token) + self.assertEqual(200, response.code) + + def test_rate_limit_returns_429(self): + token = self._create_and_login_admin() + self._app.client_log_limiter = ClientLogRateLimiter(limit=3, window=60) + payload = {"level": "INFO", "message": "m"} + for _ in range(3): + self.assertEqual(200, self._post("/api/v1/logs", payload, token).code) + response = self._post("/api/v1/logs", payload, token) + self.assertEqual(429, response.code) + self.assertIn("Retry-After", response.headers) + + def test_rate_limiter_window_resets_and_prunes(self): + limiter = ClientLogRateLimiter(limit=2, window=10) + self.assertEqual(0, limiter.check("a", 2, now=0)) + self.assertGreater(limiter.check("a", 1, now=1), 0) + self.assertEqual(0, limiter.check("b", 1, now=11)) + self.assertNotIn("a", limiter._windows) diff --git a/server/test/controllers/api/v1/test_settings.py b/server/test/controllers/api/v1/test_settings.py index 64a9597c..b966cc33 100644 --- a/server/test/controllers/api/v1/test_settings.py +++ b/server/test/controllers/api/v1/test_settings.py @@ -1,4 +1,5 @@ import pytest +from tornado import escape from tornado.testing import gen_test from digi_server.logger import get_logger @@ -64,3 +65,58 @@ def test_jwt_lifetime_as_json_includes_choice_labels(self): self.assertEqual( len(json_repr["choice_labels"]), len(json_repr["choice_options"]) ) + + +class TestSettingsDisclosure(DigiScriptTestCase): + PATH_KEYS = ( + "db_path", + "log_path", + "db_log_path", + "client_log_path", + "compiled_script_path", + "draft_script_path", + ) + + def _get(self, path, token=None): + headers = {"Authorization": f"Bearer {token}"} if token else {} + return escape.json_decode(self.fetch(path, headers=headers).body) + + def test_settings_hide_paths_from_anonymous(self): + for path in ("/api/v1/settings", "/api/v1/settings/raw"): + data = self._get(path) + for key in self.PATH_KEYS: + self.assertNotIn(key, data) + self.assertIn("client_log_enabled", data) + + def test_settings_hide_paths_from_non_admin(self): + admin = self._create_and_login_admin() + user = self._create_and_login_user(admin) + for path in ("/api/v1/settings", "/api/v1/settings/raw"): + data = self._get(path, user) + for key in self.PATH_KEYS: + self.assertNotIn(key, data) + + def test_settings_show_paths_to_admin(self): + admin = self._create_and_login_admin() + for path in ("/api/v1/settings", "/api/v1/settings/raw"): + data = self._get(path, admin) + for key in self.PATH_KEYS: + self.assertIn(key, data) + + def test_broadcast_payload_has_no_paths(self): + data = self.io_loop.run_sync(self._app.digi_settings.as_json) + for key in self.PATH_KEYS: + self.assertNotIn(key, data) + + +class TestDebugEndpoint(DigiScriptTestCase): + def test_debug_requires_admin(self): + self.assertEqual(401, self.fetch("/debug").code) + admin = self._create_and_login_admin() + user = self._create_and_login_user(admin) + self.assertEqual( + 401, self.fetch("/debug", headers={"Authorization": f"Bearer {user}"}).code + ) + self.assertEqual( + 200, self.fetch("/debug", headers={"Authorization": f"Bearer {admin}"}).code + ) diff --git a/server/test/digi_server/test_digi_server.py b/server/test/digi_server/test_digi_server.py index 0572580c..4f9359e9 100644 --- a/server/test/digi_server/test_digi_server.py +++ b/server/test/digi_server/test_digi_server.py @@ -10,7 +10,8 @@ class TestDigiScriptServer(DigiScriptTestCase): def test_debug(self): - response = self.fetch("/debug") + token = self._create_and_login_admin() + response = self.fetch("/debug", headers={"Authorization": f"Bearer {token}"}) response_body = tornado.escape.json_decode(response.body) self.assertEqual(200, response.code) From 357b3769d1f60cbb95de2b6d7092d7eebe95550e Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Mon, 19 Oct 2026 21:21:07 +0100 Subject: [PATCH 03/12] Security hygiene: JSON body helper, 403 for non-admin, RBAC validation, settings allow-list, security headers Co-Authored-By: Claude Sonnet 5.5 --- server/controllers/api/v1/auth/user.py | 14 +- server/controllers/api/v1/rbac.py | 104 ++++++------ server/controllers/api/v1/settings.py | 4 +- .../api/v1/show/session/sessions.py | 4 +- server/controllers/api/v1/user/settings.py | 36 +++-- server/controllers/api/v2/users/users.py | 6 +- .../test/controllers/api/v1/auth/test_auth.py | 2 +- .../controllers/api/v1/test_db_backups.py | 8 +- .../controllers/api/v1/test_logs_viewer.py | 8 +- .../api/v1/test_security_hygiene.py | 151 ++++++++++++++++++ .../controllers/api/v1/test_system_info.py | 4 +- .../test/controllers/api/v1/test_websocket.py | 2 +- server/test/controllers/api/v2/test_users.py | 6 +- server/utils/web/base_controller.py | 10 ++ server/utils/web/json_body.py | 27 ++++ server/utils/web/web_decorators.py | 6 +- 16 files changed, 301 insertions(+), 91 deletions(-) create mode 100644 server/test/controllers/api/v1/test_security_hygiene.py create mode 100644 server/utils/web/json_body.py diff --git a/server/controllers/api/v1/auth/user.py b/server/controllers/api/v1/auth/user.py index fe6999af..bf7d6451 100644 --- a/server/controllers/api/v1/auth/user.py +++ b/server/controllers/api/v1/auth/user.py @@ -1,7 +1,6 @@ from datetime import datetime, timezone from sqlalchemy import select -from tornado import escape from digi_server.logger import get_logger from models.session import Session @@ -10,6 +9,7 @@ from schemas.schemas import UserSchema from services.password_service import PasswordService from utils.web.base_controller import BaseAPIController +from utils.web.json_body import get_json_object from utils.web.route import ApiRoute, ApiVersion from utils.web.web_decorators import ( allow_when_password_required, @@ -37,7 +37,7 @@ async def post(self): if has_any_users: self.requires_admin() - data = escape.json_decode(self.request.body) + data = get_json_object(self) username = data.get("username", "") if not username: @@ -99,7 +99,7 @@ class UserDeleteController(BaseAPIController): @require_admin @no_live_session async def post(self): - data = escape.json_decode(self.request.body) + data = get_json_object(self) user_to_delete = data.get("id", None) if not user_to_delete: self.set_status(400) @@ -152,7 +152,7 @@ async def post(self): class LoginHandler(BaseAPIController): @redact_data_paths(paths=["/password"]) async def post(self): - data = escape.json_decode(self.request.body) + data = get_json_object(self) username = data.get("username", "") if not username: @@ -261,7 +261,7 @@ def _log_out_client(self, session_id: str) -> None: @api_authenticated @allow_when_password_required async def post(self): - data = escape.json_decode(self.request.body) + data = get_json_object(self) if self.current_user: # Revoke the JWT first, so a failure below can never leave the token @@ -335,7 +335,7 @@ async def patch(self): :return: 200 on success, 401 if old password wrong, 400 if new password invalid """ - data = escape.json_decode(self.request.body) + data = get_json_object(self) old_password = data.get("old_password", "") new_password = data.get("new_password", "") @@ -417,7 +417,7 @@ async def post(self): :return: 200 with temporary password on success, 400 if validation fails """ - data = escape.json_decode(self.request.body) + data = get_json_object(self) user_id = data.get("user_id") if not user_id: diff --git a/server/controllers/api/v1/rbac.py b/server/controllers/api/v1/rbac.py index a36df59b..19c8f683 100644 --- a/server/controllers/api/v1/rbac.py +++ b/server/controllers/api/v1/rbac.py @@ -1,12 +1,13 @@ from collections import defaultdict from sqlalchemy import inspect -from tornado import escape +from tornado.web import HTTPError from models.user import User from rbac.role import Role from registry.schema import get_registry from utils.web.base_controller import BaseAPIController +from utils.web.json_body import get_json_object from utils.web.route import ApiRoute, ApiVersion from utils.web.web_decorators import ( allow_when_password_required, @@ -15,6 +16,43 @@ ) +def _parse_role_change(data: dict) -> tuple[str, dict, int, Role]: + """Validate the body of a role grant/revoke request. + + :param data: The decoded JSON request body. + :returns: ``(resource, object, user_id, role)`` with types normalised. + :raises HTTPError: With status 400 if a field is missing or has the wrong type, + or if ``role`` is not a valid role value. + """ + resource = data.get("resource", None) + rbac_object = data.get("object", None) + user = data.get("user", None) + role = data.get("role", None) + + for name, value in ( + ("resource", resource), + ("object", rbac_object), + ("user", user), + ("role", role), + ): + if not value: + raise HTTPError(400, reason=f"{name} body parameter not fulfilled") + + if not isinstance(resource, str): + raise HTTPError(400, reason="resource must be a string") + if not isinstance(rbac_object, dict): + raise HTTPError(400, reason="object must be an object") + try: + user_id = int(user) + except (TypeError, ValueError): + raise HTTPError(400, reason="user must be an integer") from None + try: + role_value = Role(role) + except (TypeError, ValueError): + raise HTTPError(400, reason="invalid role") from None + return resource, rbac_object, user_id, role_value + + @ApiRoute("rbac/roles", ApiVersion.V1) class RBACRolesHandler(BaseAPIController): @allow_when_password_required @@ -125,28 +163,8 @@ class RBACRolesGrantHandler(BaseAPIController): @api_authenticated @require_admin async def post(self): - data = escape.json_decode(self.request.body) - resource = data.get("resource", None) - rbac_object = data.get("object", None) - user = data.get("user", None) - role = data.get("role", None) - - if not resource: - self.set_status(400) - await self.finish({"message": "resource body parameter not fulfilled"}) - return - if not rbac_object: - self.set_status(400) - await self.finish({"message": "object body parameter not fulfilled"}) - return - if not user: - self.set_status(400) - await self.finish({"message": "user body parameter not fulfilled"}) - return - if not role: - self.set_status(400) - await self.finish({"message": "role body parameter not fulfilled"}) - return + data = get_json_object(self) + resource, rbac_object, user, role = _parse_role_change(data) mapper = self.application.get_db().get_mapper_for_table(resource) if not mapper: @@ -155,7 +173,7 @@ async def post(self): return with self.make_session() as session: - user = session.get(User, int(user)) + user = session.get(User, user) if not user: self.set_status(404) await self.finish({"message": "user not found"}) @@ -165,12 +183,16 @@ async def post(self): cols.update( {col.key: rbac_object.get(col.key) for col in resource.primary_key} ) + if any(v is None for v in cols.values()): + self.set_status(400) + await self.finish({"message": "object is missing primary key fields"}) + return rbac_object = session.get(mapper, cols) if not rbac_object: self.set_status(404) await self.finish({"message": "object not found"}) return - self.application.rbac.give_role(user, rbac_object, Role(role)) + self.application.rbac.give_role(user, rbac_object, role) for socket in self.application.get_all_ws(user.id): await socket.write_message( {"OP": "NOOP", "DATA": {}, "ACTION": "GET_CURRENT_RBAC"} @@ -182,28 +204,8 @@ class RBACRolesRevokeHandler(BaseAPIController): @api_authenticated @require_admin async def post(self): - data = escape.json_decode(self.request.body) - resource = data.get("resource", None) - rbac_object = data.get("object", None) - user = data.get("user", None) - role = data.get("role", None) - - if not resource: - self.set_status(400) - await self.finish({"message": "resource body parameter not fulfilled"}) - return - if not rbac_object: - self.set_status(400) - await self.finish({"message": "object body parameter not fulfilled"}) - return - if not user: - self.set_status(400) - await self.finish({"message": "user body parameter not fulfilled"}) - return - if not role: - self.set_status(400) - await self.finish({"message": "role body parameter not fulfilled"}) - return + data = get_json_object(self) + resource, rbac_object, user, role = _parse_role_change(data) mapper = self.application.get_db().get_mapper_for_table(resource) if not mapper: @@ -212,7 +214,7 @@ async def post(self): return with self.make_session() as session: - user = session.get(User, int(user)) + user = session.get(User, user) if not user: self.set_status(404) await self.finish({"message": "user not found"}) @@ -222,12 +224,16 @@ async def post(self): cols.update( {col.key: rbac_object.get(col.key) for col in resource.primary_key} ) + if any(v is None for v in cols.values()): + self.set_status(400) + await self.finish({"message": "object is missing primary key fields"}) + return rbac_object = session.get(mapper, cols) if not rbac_object: self.set_status(404) await self.finish({"message": "object not found"}) return - self.application.rbac.revoke_role(user, rbac_object, Role(role)) + self.application.rbac.revoke_role(user, rbac_object, role) for socket in self.application.get_all_ws(user.id): await socket.write_message( {"OP": "NOOP", "DATA": {}, "ACTION": "GET_CURRENT_RBAC"} diff --git a/server/controllers/api/v1/settings.py b/server/controllers/api/v1/settings.py index 94a8f984..56fe472e 100644 --- a/server/controllers/api/v1/settings.py +++ b/server/controllers/api/v1/settings.py @@ -1,11 +1,11 @@ from sqlalchemy import select -from tornado import escape from controllers.api.constants import ERROR_COLLAB_MODE_CHANGE_BLOCKED from digi_server.logger import get_logger from digi_server.settings import COLLAB_EDITING_SETTING, Settings from models.session import Session from utils.web.base_controller import BaseAPIController +from utils.web.json_body import get_json_object from utils.web.route import ApiRoute, ApiVersion from utils.web.web_decorators import ( allow_when_password_required, @@ -60,7 +60,7 @@ async def get(self): async def patch(self): settings: Settings = self.application.digi_settings - data = escape.json_decode(self.request.body) + data = get_json_object(self) get_logger().debug(f"New settings data patched: {data}") if COLLAB_EDITING_SETTING in data and not isinstance( diff --git a/server/controllers/api/v1/show/session/sessions.py b/server/controllers/api/v1/show/session/sessions.py index c84e6cc9..63fac7b7 100644 --- a/server/controllers/api/v1/show/session/sessions.py +++ b/server/controllers/api/v1/show/session/sessions.py @@ -2,7 +2,6 @@ from typing import List from sqlalchemy import select -from tornado import escape from controllers.api.constants import ERROR_SHOW_NOT_FOUND from models.script import Script @@ -11,6 +10,7 @@ from rbac.role import Role from schemas.schemas import IntervalSchema, ShowSessionSchema from utils.web.base_controller import BaseAPIController +from utils.web.json_body import get_json_object from utils.web.route import ApiRoute, ApiVersion from utils.web.web_decorators import requires_show @@ -100,7 +100,7 @@ async def post(self): await self.finish({"message": ERROR_SHOW_NOT_FOUND}) return self.requires_role(show, Role.EXECUTE) - data = escape.json_decode(self.request.body) + data = get_json_object(self) status, result = self._start_problem(session, show, data) if status is not None: self.set_status(status) diff --git a/server/controllers/api/v1/user/settings.py b/server/controllers/api/v1/user/settings.py index dbf3fdd5..3cddd327 100644 --- a/server/controllers/api/v1/user/settings.py +++ b/server/controllers/api/v1/user/settings.py @@ -1,13 +1,32 @@ -from tornado import escape - from digi_server.logger import get_logger from models.user import UserSettings from schemas.schemas import UserSettingsSchema from utils.web.base_controller import BaseAPIController +from utils.web.json_body import get_json_object from utils.web.route import ApiRoute, ApiVersion from utils.web.web_decorators import allow_when_password_required, api_authenticated +# Settings a user may change themselves. Anything else (including internal +# ``_``-prefixed columns and non-column attributes) is ignored. +EDITABLE_USER_SETTINGS = frozenset( + { + "enable_script_auto_save", + "script_auto_save_interval", + "cue_position_right", + "script_text_alignment", + "console_log_level", + "character_mru_sort", + "character_combined_dropdown", + "preferred_ui", + "table_page_sizes", + "default_sd_text_colour", + "default_sd_background_colour", + "show_current_cue_footer", + } +) + + @ApiRoute("user/settings", ApiVersion.V1) class UserSettingsController(BaseAPIController): @api_authenticated @@ -28,7 +47,7 @@ async def get(self): @api_authenticated async def patch(self): log = get_logger() - data = escape.json_decode(self.request.body) + data = get_json_object(self) with self.make_session() as session: user_settings = session.get(UserSettings, self.current_user["id"]) if not user_settings: @@ -38,16 +57,11 @@ async def patch(self): session.flush() for k, v in data.items(): - if hasattr(user_settings, k): - if k[0] == "_": - log.warning( - f"User attempted to set protected setting: {k}. Ignoring." - ) - else: - setattr(user_settings, k, v) + if k in EDITABLE_USER_SETTINGS: + setattr(user_settings, k, v) else: log.warning( - f"User attempted to set unknown setting: {k}. Ignoring." + f"User attempted to set non-editable setting: {k}. Ignoring." ) session.commit() diff --git a/server/controllers/api/v2/users/users.py b/server/controllers/api/v2/users/users.py index 71860c35..a583aeb2 100644 --- a/server/controllers/api/v2/users/users.py +++ b/server/controllers/api/v2/users/users.py @@ -1,13 +1,13 @@ from datetime import datetime, timezone from sqlalchemy import select -from tornado import escape from models.user import User from registry.named_locks import NamedLockRegistry from schemas.schemas import UserSchema from services.password_service import PasswordService from utils.web.base_controller import BaseAPIController +from utils.web.json_body import get_json_object from utils.web.route import ApiRoute, ApiVersion from utils.web.web_decorators import ( api_authenticated, @@ -37,7 +37,7 @@ async def post(self): if has_any_users: self.requires_admin() - data = escape.json_decode(self.request.body) + data = get_json_object(self) username = data.get("username", "") if not username: @@ -100,7 +100,7 @@ async def patch(self): await self.finish({"message": "Id missing"}) return - data = escape.json_decode(self.request.body) + data = get_json_object(self) with self.make_session() as session: user: User = session.get(User, int(user_id)) diff --git a/server/test/controllers/api/v1/auth/test_auth.py b/server/test/controllers/api/v1/auth/test_auth.py index af589061..46bd5a7a 100644 --- a/server/test/controllers/api/v1/auth/test_auth.py +++ b/server/test/controllers/api/v1/auth/test_auth.py @@ -1186,7 +1186,7 @@ def test_admin_reset_password_requires_admin(self): headers={"Authorization": f"Bearer {user_token}"}, ) - self.assertEqual(401, response.code) + self.assertEqual(403, response.code) def test_admin_reset_password_user_not_found(self): """Test password reset fails for non-existent user""" diff --git a/server/test/controllers/api/v1/test_db_backups.py b/server/test/controllers/api/v1/test_db_backups.py index 4aa53fec..9827da3d 100644 --- a/server/test/controllers/api/v1/test_db_backups.py +++ b/server/test/controllers/api/v1/test_db_backups.py @@ -61,11 +61,11 @@ def test_get_unauthenticated_returns_401(self): resp = self._fetch_backups() self.assertEqual(401, resp.code) - def test_get_non_admin_returns_401(self): + def test_get_non_admin_returns_403(self): admin_token = self._create_and_login_admin() user_token = self._create_and_login_user(admin_token) resp = self._fetch_backups(token=user_token) - self.assertEqual(401, resp.code) + self.assertEqual(403, resp.code) # ------------------------------------------------------------------ # GET — response shape @@ -129,11 +129,11 @@ def test_delete_unauthenticated_returns_401(self): resp = self._delete_backup(1700000000) self.assertEqual(401, resp.code) - def test_delete_non_admin_returns_401(self): + def test_delete_non_admin_returns_403(self): admin_token = self._create_and_login_admin() user_token = self._create_and_login_user(admin_token) resp = self._delete_backup(1700000000, token=user_token) - self.assertEqual(401, resp.code) + self.assertEqual(403, resp.code) # ------------------------------------------------------------------ # DELETE — validation diff --git a/server/test/controllers/api/v1/test_logs_viewer.py b/server/test/controllers/api/v1/test_logs_viewer.py index 974aa6f8..c721a8d0 100644 --- a/server/test/controllers/api/v1/test_logs_viewer.py +++ b/server/test/controllers/api/v1/test_logs_viewer.py @@ -83,11 +83,11 @@ def test_unauthenticated_returns_401(self): resp = self._fetch_view() self.assertEqual(401, resp.code) - def test_non_admin_returns_401(self): + def test_non_admin_returns_403(self): admin_token = self._create_and_login_admin() user_token = self._create_and_login_user(admin_token) resp = self._fetch_view(token=user_token) - self.assertEqual(401, resp.code) + self.assertEqual(403, resp.code) def test_admin_returns_200(self): token = self._create_and_login_admin() @@ -367,11 +367,11 @@ def test_stream_unauthenticated_returns_401(self): resp = self._fetch_stream_headers() self.assertEqual(401, resp.code) - def test_stream_non_admin_returns_401(self): + def test_stream_non_admin_returns_403(self): admin_token = self._create_and_login_admin() user_token = self._create_and_login_user(admin_token) resp = self._fetch_stream_headers(token=user_token) - self.assertEqual(401, resp.code) + self.assertEqual(403, resp.code) def test_stream_backfill_contains_existing_entries(self): """Entries injected before connection must appear in the first chunk. diff --git a/server/test/controllers/api/v1/test_security_hygiene.py b/server/test/controllers/api/v1/test_security_hygiene.py new file mode 100644 index 00000000..f4299e4c --- /dev/null +++ b/server/test/controllers/api/v1/test_security_hygiene.py @@ -0,0 +1,151 @@ +"""Tests for the security hygiene hardening: JSON body parsing, admin status codes, +RBAC input validation, user settings allow-list and default security headers.""" + +from tornado import escape + +from models.user import UserSettings +from test.conftest import DigiScriptTestCase + + +class TestSecurityHygiene(DigiScriptTestCase): + def _auth(self, token): + return {"Authorization": f"Bearer {token}"} + + def _post(self, path, body, token=None, method="POST"): + return self.fetch( + path, + method=method, + body=body if isinstance(body, str) else escape.json_encode(body), + headers=self._auth(token) if token else {}, + raise_error=False, + ) + + # ─── Security headers ────────────────────────────────────────────────────── + + def test_security_headers_present(self): + resp = self.fetch("/api/v1/health", raise_error=False) + self.assertEqual("nosniff", resp.headers.get("X-Content-Type-Options")) + self.assertEqual("SAMEORIGIN", resp.headers.get("X-Frame-Options")) + self.assertEqual("same-origin", resp.headers.get("Referrer-Policy")) + + def test_security_headers_present_on_error_responses(self): + resp = self.fetch("/api/v1/rbac/user/resources", raise_error=False) + self.assertEqual(401, resp.code) + self.assertEqual("nosniff", resp.headers.get("X-Content-Type-Options")) + + # ─── JSON body helper ────────────────────────────────────────────────────── + + def test_login_invalid_json_returns_400(self): + self.assertEqual(400, self._post("/api/v1/auth/login", "{not json").code) + + def test_login_non_object_json_returns_400(self): + self.assertEqual(400, self._post("/api/v1/auth/login", "[1, 2]").code) + + def test_login_empty_body_returns_400(self): + self.assertEqual(400, self._post("/api/v1/auth/login", "").code) + + def test_create_user_invalid_json_returns_400(self): + self.assertEqual(400, self._post("/api/v1/auth/create", "nope").code) + + def test_v2_create_user_invalid_json_returns_400(self): + self.assertEqual(400, self._post("/api/v2/users", "nope").code) + + def test_change_password_invalid_json_returns_400(self): + token = self._create_and_login_admin() + resp = self._post("/api/v1/auth/change-password", "nope", token, "PATCH") + self.assertEqual(400, resp.code) + + def test_rbac_grant_invalid_json_returns_400(self): + token = self._create_and_login_admin() + self.assertEqual( + 400, self._post("/api/v1/rbac/user/roles/grant", "nope", token).code + ) + + def test_user_settings_patch_non_object_returns_400(self): + token = self._create_and_login_admin() + resp = self._post("/api/v1/user/settings", "[1]", token, "PATCH") + self.assertEqual(400, resp.code) + + def test_system_settings_patch_invalid_json_returns_400(self): + token = self._create_and_login_admin() + resp = self._post("/api/v1/settings", "nope", token, "PATCH") + self.assertEqual(400, resp.code) + + def test_session_start_invalid_json_returns_400(self): + token = self._create_and_login_admin() + resp = self._post("/api/v1/show/sessions/start", "nope", token) + # No show is loaded in this fixture, so requires_show answers first. + self.assertEqual(400, resp.code) + + # ─── require_admin status codes ──────────────────────────────────────────── + + def test_require_admin_unauthenticated_is_401(self): + resp = self._post("/api/v1/rbac/user/roles/grant", {}) + self.assertEqual(401, resp.code) + + def test_require_admin_non_admin_is_403(self): + admin_token = self._create_and_login_admin() + user_token = self._create_and_login_user(admin_token) + resp = self._post("/api/v1/rbac/user/roles/grant", {}, user_token) + self.assertEqual(403, resp.code) + + # ─── RBAC grant / revoke validation ──────────────────────────────────────── + + def _role_body(self, **overrides): + body = { + "resource": "shows", + "object": {"id": 1}, + "user": 1, + "role": 1, + } + body.update(overrides) + return body + + def test_rbac_grant_and_revoke_invalid_input_returns_400(self): + token = self._create_and_login_admin() + bad_bodies = [ + self._role_body(role=999999), + self._role_body(role="admin"), + self._role_body(user="abc"), + self._role_body(object="not-a-dict"), + self._role_body(object={"unrelated": 1}), + self._role_body(resource=["shows"]), + ] + for path in ( + "/api/v1/rbac/user/roles/grant", + "/api/v1/rbac/user/roles/revoke", + ): + for body in bad_bodies: + with self.subTest(path=path, body=body): + resp = self._post(path, body, token) + self.assertEqual(400, resp.code) + + def test_rbac_grant_missing_field_returns_400(self): + token = self._create_and_login_admin() + body = self._role_body() + del body["role"] + resp = self._post("/api/v1/rbac/user/roles/grant", body, token) + self.assertEqual(400, resp.code) + + # ─── User settings allow-list ────────────────────────────────────────────── + + def test_user_settings_patch_sets_allowed_and_ignores_others(self): + token = self._create_and_login_admin() + resp = self._post( + "/api/v1/user/settings", + { + "cue_position_right": True, + "_user_id": 999, + "metadata": "x", + "registry": "x", + "nonexistent": 1, + }, + token, + "PATCH", + ) + self.assertEqual(200, resp.code) + + with self._app.get_db().sessionmaker() as session: + settings = session.scalars(session.query(UserSettings).statement).first() + self.assertTrue(settings.cue_position_right) + self.assertNotEqual(999, settings._user_id) diff --git a/server/test/controllers/api/v1/test_system_info.py b/server/test/controllers/api/v1/test_system_info.py index 3c89428d..2585140a 100644 --- a/server/test/controllers/api/v1/test_system_info.py +++ b/server/test/controllers/api/v1/test_system_info.py @@ -16,11 +16,11 @@ def test_unauthenticated_returns_401(self): resp = self._fetch_system_info() self.assertEqual(401, resp.code) - def test_non_admin_returns_401(self): + def test_non_admin_returns_403(self): admin_token = self._create_and_login_admin() user_token = self._create_and_login_user(admin_token) resp = self._fetch_system_info(token=user_token) - self.assertEqual(401, resp.code) + self.assertEqual(403, resp.code) def test_authenticated_returns_200_with_expected_keys(self): token = self._create_and_login_admin() diff --git a/server/test/controllers/api/v1/test_websocket.py b/server/test/controllers/api/v1/test_websocket.py index aa49990b..59ea545e 100644 --- a/server/test/controllers/api/v1/test_websocket.py +++ b/server/test/controllers/api/v1/test_websocket.py @@ -22,7 +22,7 @@ def test_get_sessions_rejects_non_admin(self): response = self.fetch( "/api/v1/ws/sessions", headers={"Authorization": f"Bearer {user_token}"} ) - self.assertEqual(401, response.code) + self.assertEqual(403, response.code) def test_get_sessions_empty(self): """Test GET /api/v1/ws/sessions with no sessions. diff --git a/server/test/controllers/api/v2/test_users.py b/server/test/controllers/api/v2/test_users.py index decdbb72..8d3b0a9a 100644 --- a/server/test/controllers/api/v2/test_users.py +++ b/server/test/controllers/api/v2/test_users.py @@ -74,7 +74,7 @@ def test_get_users_requires_admin(self): method="GET", headers={"Authorization": f"Bearer {nonadmin_token}"}, ) - self.assertEqual(401, resp.code) + self.assertEqual(403, resp.code) # ─── POST /api/v2/users ──────────────────────────────────────────────────── @@ -183,7 +183,7 @@ def test_patch_requires_admin(self): body=escape.json_encode({"is_admin": True}), headers={"Authorization": f"Bearer {user_token}"}, ) - self.assertEqual(401, resp.code) + self.assertEqual(403, resp.code) def test_patch_missing_id(self): admin_token = self._setup_admin() @@ -265,7 +265,7 @@ def test_delete_requires_admin(self): allow_nonstandard_methods=True, headers={"Authorization": f"Bearer {user_token}"}, ) - self.assertEqual(401, resp.code) + self.assertEqual(403, resp.code) def test_delete_missing_id(self): admin_token = self._setup_admin() diff --git a/server/utils/web/base_controller.py b/server/utils/web/base_controller.py index 0794f217..e1fe4457 100644 --- a/server/utils/web/base_controller.py +++ b/server/utils/web/base_controller.py @@ -45,6 +45,16 @@ def __init__( self.application: DigiScriptServer = self.application self.current_show: Optional[dict] = None + def set_default_headers(self) -> None: + """Add baseline security headers to every response. + + No Content-Security-Policy is set: the SPA and the bundled docs rely on + inline styles/scripts, so a policy strict enough to be useful would break them. + """ + self.set_header("X-Content-Type-Options", "nosniff") + self.set_header("X-Frame-Options", "SAMEORIGIN") + self.set_header("Referrer-Policy", "same-origin") + async def prepare( self, ) -> Optional[Awaitable[None]]: diff --git a/server/utils/web/json_body.py b/server/utils/web/json_body.py new file mode 100644 index 00000000..03cd2a59 --- /dev/null +++ b/server/utils/web/json_body.py @@ -0,0 +1,27 @@ +from __future__ import annotations + +from typing import TYPE_CHECKING, Any + +from tornado import escape +from tornado.web import HTTPError + + +if TYPE_CHECKING: + from tornado.web import RequestHandler + + +def get_json_object(handler: RequestHandler) -> dict[str, Any]: + """Decode the request body as a JSON object. + + :param handler: The request handler whose body should be decoded. + :returns: The decoded JSON object. + :raises HTTPError: With status 400 if the body is not valid JSON, or the + decoded value is not a JSON object (dict). + """ + try: + data = escape.json_decode(handler.request.body) + except (ValueError, TypeError) as exc: + raise HTTPError(400, log_message="Invalid JSON body") from exc + if not isinstance(data, dict): + raise HTTPError(400, log_message="JSON body must be an object") + return data diff --git a/server/utils/web/web_decorators.py b/server/utils/web/web_decorators.py index 295ce37b..db2f41e3 100644 --- a/server/utils/web/web_decorators.py +++ b/server/utils/web/web_decorators.py @@ -33,8 +33,10 @@ def require_admin( ) -> Callable[..., Optional[Awaitable[None]]]: @functools.wraps(method) def wrapper(self: BaseController, *args, **kwargs): - if not self.current_user or not self.current_user["is_admin"]: - raise HTTPError(401, log_message="Not admin user") + if not self.current_user: + raise HTTPError(401, log_message="Not logged in") + if not self.current_user["is_admin"]: + raise HTTPError(403, log_message="Not admin user") return method(self, *args, **kwargs) return wrapper From 207c03a57720372a44991a55da9151b2c073f00d Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Mon, 19 Oct 2026 23:18:19 +0100 Subject: [PATCH 04/12] Move /debug access test next to the existing debug endpoint tests Co-Authored-By: Claude Sonnet 5.5 --- server/test/controllers/api/v1/test_settings.py | 13 ------------- server/test/digi_server/test_digi_server.py | 7 +++++++ 2 files changed, 7 insertions(+), 13 deletions(-) diff --git a/server/test/controllers/api/v1/test_settings.py b/server/test/controllers/api/v1/test_settings.py index b966cc33..f2f77289 100644 --- a/server/test/controllers/api/v1/test_settings.py +++ b/server/test/controllers/api/v1/test_settings.py @@ -107,16 +107,3 @@ def test_broadcast_payload_has_no_paths(self): data = self.io_loop.run_sync(self._app.digi_settings.as_json) for key in self.PATH_KEYS: self.assertNotIn(key, data) - - -class TestDebugEndpoint(DigiScriptTestCase): - def test_debug_requires_admin(self): - self.assertEqual(401, self.fetch("/debug").code) - admin = self._create_and_login_admin() - user = self._create_and_login_user(admin) - self.assertEqual( - 401, self.fetch("/debug", headers={"Authorization": f"Bearer {user}"}).code - ) - self.assertEqual( - 200, self.fetch("/debug", headers={"Authorization": f"Bearer {admin}"}).code - ) diff --git a/server/test/digi_server/test_digi_server.py b/server/test/digi_server/test_digi_server.py index 4f9359e9..ae726a42 100644 --- a/server/test/digi_server/test_digi_server.py +++ b/server/test/digi_server/test_digi_server.py @@ -18,6 +18,13 @@ def test_debug(self): self.assertTrue("status" in response_body) self.assertEqual("OK", response_body["status"]) + def test_debug_requires_admin(self): + self.assertEqual(401, self.fetch("/debug").code) + admin = self._create_and_login_admin() + user = self._create_and_login_user(admin) + response = self.fetch("/debug", headers={"Authorization": f"Bearer {user}"}) + self.assertEqual(401, response.code) + def test_api_debug(self): response = self.fetch("/api/v1/debug") response_body = tornado.escape.json_decode(response.body) From 10c39b195170657eae6b98493ca8c5875ae83f8e Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Mon, 19 Oct 2026 23:19:21 +0100 Subject: [PATCH 05/12] Make log redaction setting authoritative and default it on - WS and REST body logging redact only when log_redaction is enabled; when disabled raw content is logged for debugging - log_redaction now defaults to True (new installs and installs without a saved value) - Document the setting; move logging tests next to the code they cover Co-Authored-By: Claude Sonnet 5.5 --- docs/pages/user_config.md | 6 +++ server/controllers/ws_controller.py | 13 +++-- server/digi_server/settings.py | 8 ++- server/test/controllers/test_ws_controller.py | 19 +++++-- server/test/digi_server/test_settings.py | 11 ++++ server/test/utils/web/test_base_controller.py | 54 +++++++++++++++++++ server/test/utils/web/test_log_redaction.py | 40 -------------- server/utils/web/base_controller.py | 21 ++++---- 8 files changed, 110 insertions(+), 62 deletions(-) create mode 100644 server/test/digi_server/test_settings.py create mode 100644 server/test/utils/web/test_base_controller.py diff --git a/docs/pages/user_config.md b/docs/pages/user_config.md index 3275ba11..4fe3292c 100644 --- a/docs/pages/user_config.md +++ b/docs/pages/user_config.md @@ -76,6 +76,12 @@ Once users have been created, their permissions can be configured by clicking th RBAC configuration determines what shows a user can access and what actions they can perform within those shows. +### Log Redaction + +The **Enable Log Redaction** system setting is on by default. While it is on, passwords, tokens and other credentials are replaced with a placeholder in logged HTTP request bodies, and WebSocket messages are logged as their operation name and size only. + +Turn it off to see the raw HTTP and WebSocket content while debugging. **Warning:** with redaction off, the logs contain credentials and authentication tokens, so only disable it temporarily and treat the log files as sensitive. Installations that already had the setting saved keep their existing value. + ### Log Viewer The **Logs** tab (admin only) provides a real-time view of server and client log entries stored in the in-memory log buffer. diff --git a/server/controllers/ws_controller.py b/server/controllers/ws_controller.py index 7fd2baaf..2b211f5f 100644 --- a/server/controllers/ws_controller.py +++ b/server/controllers/ws_controller.py @@ -470,6 +470,7 @@ async def on_message(self, message: Union[str, bytes]): if self.current_username else self.request.remote_ip ) + raw = message size = len(message) try: @@ -484,10 +485,14 @@ async def on_message(self, message: Union[str, bytes]): ) return - # Never log the payload: AUTHENTICATE / REFRESH_TOKEN carry live JWTs. - get_logger().debug( - f"WebSocket message from {user_part}: {ws_op} ({size} bytes)" - ) + # With redaction on never log the payload: AUTHENTICATE / REFRESH_TOKEN + # carry live JWTs. + if self.application.digi_settings.get_sync("log_redaction"): + get_logger().debug( + f"WebSocket message from {user_part}: {ws_op} ({size} bytes)" + ) + else: + get_logger().debug(f"WebSocket message from {user_part}: {raw}") # Connection boundary: an exception escaping on_message ends Tornado's # read loop without calling on_close, leaving a handler that no longer diff --git a/server/digi_server/settings.py b/server/digi_server/settings.py index 37737242..fa5fa4cc 100644 --- a/server/digi_server/settings.py +++ b/server/digi_server/settings.py @@ -302,10 +302,14 @@ def init_settings(self): self.define( "log_redaction", bool, - False, + True, True, display_name="Enable Log Redaction", - help_text="When enabled, potentially sensitive information will be redacted from logs.", + help_text=( + "When enabled (the default), passwords, tokens and WebSocket message " + "contents are kept out of the logs. Disable only while debugging: " + "logs will then contain credentials and tokens." + ), category="Logging", ) self.define( diff --git a/server/test/controllers/test_ws_controller.py b/server/test/controllers/test_ws_controller.py index 296bb8d4..c889aa5c 100644 --- a/server/test/controllers/test_ws_controller.py +++ b/server/test/controllers/test_ws_controller.py @@ -3512,9 +3512,8 @@ async def test_non_object_and_non_string_op_frames_are_ignored(self): await self._still_responsive(ws, self.admin_id) ws.close() - @gen_test - async def test_ws_payload_and_tokens_are_not_logged(self): - """AUTHENTICATE tokens never reach the log; only op name and size do.""" + async def _auth_logs(self, redaction): + self._app.digi_settings.settings["log_redaction"].set_value(redaction) ws, _ = await self._connect_and_auth() sentinel = self._app.jwt_service.create_access_token( data={"user_id": self.admin_id} @@ -3524,10 +3523,20 @@ async def test_ws_payload_and_tokens_are_not_logged(self): json.dumps({"OP": "AUTHENTICATE", "DATA": {"token": sentinel}}) ) await self._read_until(ws, op="WS_AUTH_SUCCESS") - joined = "\n".join(captured.output) + ws.close() + return sentinel, "\n".join(captured.output) + + @gen_test + async def test_ws_payload_not_logged_when_redaction_on(self): + """With redaction on only the op name and size are logged.""" + sentinel, joined = await self._auth_logs(True) self.assertIn("AUTHENTICATE", joined) self.assertNotIn(sentinel, joined) - ws.close() + + @gen_test + async def test_ws_payload_logged_raw_when_redaction_off(self): + sentinel, joined = await self._auth_logs(False) + self.assertIn(sentinel, joined) @gen_test async def test_update_session_survives_deleted_user(self): diff --git a/server/test/digi_server/test_settings.py b/server/test/digi_server/test_settings.py new file mode 100644 index 00000000..7c8267af --- /dev/null +++ b/server/test/digi_server/test_settings.py @@ -0,0 +1,11 @@ +from test.conftest import DigiScriptTestCase + + +class TestLoggingSettingDefaults(DigiScriptTestCase): + def test_log_level_defaults_to_info(self): + self.assertEqual("INFO", self._app.digi_settings.settings["log_level"].default) + + def test_log_redaction_enabled_by_default(self): + setting = self._app.digi_settings.settings["log_redaction"] + self.assertTrue(setting.default) + self.assertTrue(setting.get_value()) diff --git a/server/test/utils/web/test_base_controller.py b/server/test/utils/web/test_base_controller.py new file mode 100644 index 00000000..82624e34 --- /dev/null +++ b/server/test/utils/web/test_base_controller.py @@ -0,0 +1,54 @@ +import json + +from tornado.httpclient import HTTPRequest +from tornado.testing import gen_test + +from test.conftest import DigiScriptTestCase + + +class TestRequestBodyLogging(DigiScriptTestCase): + def _set_redaction(self, value): + self._app.digi_settings.settings["log_redaction"].set_value(value) + + async def _post_login(self, body): + request = HTTPRequest( + self.get_url("/api/v1/auth/login"), + method="POST", + body=body, + ) + with self.assertLogs(level="DEBUG") as captured: + await self.http_client.fetch(request, raise_error=False) + return "\n".join(captured.output) + + @gen_test + async def test_secrets_hidden_when_redaction_enabled(self): + self._set_redaction(True) + joined = await self._post_login( + json.dumps( + { + "username": "nobody", + "password": "SENTINEL-PASSWORD", + "extra": {"access_token": "SENTINEL-TOKEN"}, + } + ) + ) + self.assertIn("/api/v1/auth/login", joined) + self.assertNotIn("SENTINEL-PASSWORD", joined) + self.assertNotIn("SENTINEL-TOKEN", joined) + + @gen_test + async def test_body_logged_raw_when_redaction_disabled(self): + self._set_redaction(False) + joined = await self._post_login( + json.dumps({"username": "nobody", "password": "SENTINEL-PASSWORD"}) + ) + self.assertIn("SENTINEL-PASSWORD", joined) + + @gen_test + async def test_non_json_body_follows_setting(self): + self._set_redaction(True) + self.assertNotIn( + "SENTINEL-RAW", await self._post_login("password=SENTINEL-RAW") + ) + self._set_redaction(False) + self.assertIn("SENTINEL-RAW", await self._post_login("password=SENTINEL-RAW")) diff --git a/server/test/utils/web/test_log_redaction.py b/server/test/utils/web/test_log_redaction.py index 1f25e8b5..0620b0ee 100644 --- a/server/test/utils/web/test_log_redaction.py +++ b/server/test/utils/web/test_log_redaction.py @@ -1,10 +1,5 @@ -import json import unittest -from tornado.httpclient import HTTPRequest -from tornado.testing import gen_test - -from test.conftest import DigiScriptTestCase from utils.web.log_redaction import REDACTED, redact_sensitive_keys @@ -32,38 +27,3 @@ def test_does_not_mutate_input(self): def test_scalars_pass_through(self): self.assertEqual("x", redact_sensitive_keys("x")) self.assertIsNone(redact_sensitive_keys(None)) - - -class TestRestBodyLogging(DigiScriptTestCase): - @gen_test - async def test_sentinel_secrets_never_logged(self): - body = { - "username": "nobody", - "password": "SENTINEL-PASSWORD", - "extra": {"access_token": "SENTINEL-TOKEN"}, - } - request = HTTPRequest( - self.get_url("/api/v1/auth/login"), - method="POST", - body=json.dumps(body), - ) - with self.assertLogs(level="DEBUG") as captured: - await self.http_client.fetch(request, raise_error=False) - joined = "\n".join(captured.output) - self.assertIn("/api/v1/auth/login", joined) - self.assertNotIn("SENTINEL-PASSWORD", joined) - self.assertNotIn("SENTINEL-TOKEN", joined) - - @gen_test - async def test_non_json_body_not_logged(self): - request = HTTPRequest( - self.get_url("/api/v1/auth/login"), - method="POST", - body="password=SENTINEL-RAW", - ) - with self.assertLogs(level="DEBUG") as captured: - await self.http_client.fetch(request, raise_error=False) - self.assertNotIn("SENTINEL-RAW", "\n".join(captured.output)) - - def test_default_log_level_is_info(self): - self.assertEqual("INFO", self._app.digi_settings.settings["log_level"].default) diff --git a/server/utils/web/base_controller.py b/server/utils/web/base_controller.py index e1a42f52..c9625651 100644 --- a/server/utils/web/base_controller.py +++ b/server/utils/web/base_controller.py @@ -183,22 +183,21 @@ def on_finish(self): try: body = escape.json_decode(self.request.body) except BaseException: - # Not JSON, so it cannot be redacted by key: log only its size. + if self.application.digi_settings.settings["log_redaction"].get_value(): + # Not JSON, so it cannot be redacted by key: log only its size. + logged = f"" + else: + logged = self.request.body get_logger().debug( - f"{self.request.method} {self.request.path} " - f"{user_suffix}", + f"{self.request.method} {self.request.path} {logged}{user_suffix}", extra=self._log_extra(), ) else: - if ( - redacted_data_paths - and self.application.digi_settings.settings[ - "log_redaction" - ].get_value() - ): + if self.application.digi_settings.settings["log_redaction"].get_value(): body = deepcopy(body) - redacted_data_paths.apply(body) - body = redact_sensitive_keys(body) + if redacted_data_paths: + redacted_data_paths.apply(body) + body = redact_sensitive_keys(body) log_method( f"{self.request.method} {self.request.path} {body}{user_suffix}", From cad9f115ff71deaa5480d8dec342c59d0d06dad4 Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Mon, 19 Oct 2026 23:19:48 +0100 Subject: [PATCH 06/12] Redistribute tests into modules mirroring the code under test Co-Authored-By: Claude Sonnet 5.5 --- .../test/controllers/api/v1/auth/test_auth.py | 28 ++++ .../api/v1/show/session/test_sessions.py | 29 ++++ server/test/controllers/api/v1/test_rbac.py | 46 ++++++ .../api/v1/test_security_hygiene.py | 151 ------------------ .../test/controllers/api/v1/test_settings.py | 13 ++ .../controllers/api/v1/user/test_settings.py | 44 +++++ server/test/controllers/api/v2/test_users.py | 8 + server/test/utils/web/test_base_controller.py | 16 ++ server/test/utils/web/test_json_body.py | 35 ++++ server/test/utils/web/test_web_decorators.py | 21 +++ 10 files changed, 240 insertions(+), 151 deletions(-) delete mode 100644 server/test/controllers/api/v1/test_security_hygiene.py create mode 100644 server/test/controllers/api/v1/user/test_settings.py create mode 100644 server/test/utils/web/test_base_controller.py create mode 100644 server/test/utils/web/test_json_body.py diff --git a/server/test/controllers/api/v1/auth/test_auth.py b/server/test/controllers/api/v1/auth/test_auth.py index 46bd5a7a..7fc23457 100644 --- a/server/test/controllers/api/v1/auth/test_auth.py +++ b/server/test/controllers/api/v1/auth/test_auth.py @@ -1249,3 +1249,31 @@ def test_admin_reset_password_missing_user_id(self): self.assertEqual(400, response.code) response_body = escape.json_decode(response.body) self.assertEqual("user_id is required", response_body["message"]) + + +class TestAuthJsonBodyValidation(DigiScriptTestCase): + def _post(self, path, body, token=None, method="POST"): + return self.fetch( + path, + method=method, + body=body, + headers={"Authorization": f"Bearer {token}"} if token else {}, + raise_error=False, + ) + + def test_login_invalid_json_returns_400(self): + self.assertEqual(400, self._post("/api/v1/auth/login", "{not json").code) + + def test_login_non_object_json_returns_400(self): + self.assertEqual(400, self._post("/api/v1/auth/login", "[1, 2]").code) + + def test_login_empty_body_returns_400(self): + self.assertEqual(400, self._post("/api/v1/auth/login", "").code) + + def test_create_user_invalid_json_returns_400(self): + self.assertEqual(400, self._post("/api/v1/auth/create", "nope").code) + + def test_change_password_invalid_json_returns_400(self): + token = self._create_and_login_admin() + resp = self._post("/api/v1/auth/change-password", "nope", token, "PATCH") + self.assertEqual(400, resp.code) diff --git a/server/test/controllers/api/v1/show/session/test_sessions.py b/server/test/controllers/api/v1/show/session/test_sessions.py index d8330506..61d33153 100644 --- a/server/test/controllers/api/v1/show/session/test_sessions.py +++ b/server/test/controllers/api/v1/show/session/test_sessions.py @@ -66,3 +66,32 @@ def test_get_sessions_with_data(self): self.assertEqual(200, response.code) response_body = tornado.escape.json_decode(response.body) self.assertEqual(2, len(response_body["sessions"])) + + def test_start_session_invalid_json_returns_400(self): + """A malformed body reaches the JSON helper (a show is loaded) and gets 400.""" + token = self._create_and_login_admin() + for body in ("nope", "[1]"): + with self.subTest(body=body): + response = self.fetch( + "/api/v1/show/sessions/start", + method="POST", + body=body, + headers={"Authorization": f"Bearer {token}"}, + raise_error=False, + ) + self.assertEqual(400, response.code) + + def test_start_session_valid_json_reaches_handler(self): + """Control for the test above: a valid body gets the handler's own error.""" + token = self._create_and_login_admin() + response = self.fetch( + "/api/v1/show/sessions/start", + method="POST", + body="{}", + headers={"Authorization": f"Bearer {token}"}, + raise_error=False, + ) + self.assertEqual(400, response.code) + self.assertEqual( + "session_id missing", tornado.escape.json_decode(response.body)["message"] + ) diff --git a/server/test/controllers/api/v1/test_rbac.py b/server/test/controllers/api/v1/test_rbac.py index d99642b2..91982bd0 100644 --- a/server/test/controllers/api/v1/test_rbac.py +++ b/server/test/controllers/api/v1/test_rbac.py @@ -110,3 +110,49 @@ def test_get_objects_for_resource(self): self.assertIn("objects", response_body) # Should find the script we created self.assertEqual(1, len(response_body["objects"])) + + +class TestRBACRoleChangeValidation(DigiScriptTestCase): + def _body(self, **overrides): + body = {"resource": "shows", "object": {"id": 1}, "user": 1, "role": 1} + body.update(overrides) + return body + + def _post(self, path, body, token): + return self.fetch( + path, + method="POST", + body=body if isinstance(body, str) else tornado.escape.json_encode(body), + headers={"Authorization": f"Bearer {token}"}, + raise_error=False, + ) + + def test_grant_and_revoke_invalid_input_returns_400(self): + token = self._create_and_login_admin() + bad_bodies = [ + self._body(role=999999), + self._body(role="admin"), + self._body(user="abc"), + self._body(object="not-a-dict"), + self._body(object={"unrelated": 1}), + self._body(resource=["shows"]), + ] + for path in ( + "/api/v1/rbac/user/roles/grant", + "/api/v1/rbac/user/roles/revoke", + ): + for body in bad_bodies: + with self.subTest(path=path, body=body): + self.assertEqual(400, self._post(path, body, token).code) + + def test_grant_missing_field_returns_400(self): + token = self._create_and_login_admin() + body = self._body() + del body["role"] + resp = self._post("/api/v1/rbac/user/roles/grant", body, token) + self.assertEqual(400, resp.code) + + def test_grant_invalid_json_returns_400(self): + token = self._create_and_login_admin() + resp = self._post("/api/v1/rbac/user/roles/grant", "nope", token) + self.assertEqual(400, resp.code) diff --git a/server/test/controllers/api/v1/test_security_hygiene.py b/server/test/controllers/api/v1/test_security_hygiene.py deleted file mode 100644 index f4299e4c..00000000 --- a/server/test/controllers/api/v1/test_security_hygiene.py +++ /dev/null @@ -1,151 +0,0 @@ -"""Tests for the security hygiene hardening: JSON body parsing, admin status codes, -RBAC input validation, user settings allow-list and default security headers.""" - -from tornado import escape - -from models.user import UserSettings -from test.conftest import DigiScriptTestCase - - -class TestSecurityHygiene(DigiScriptTestCase): - def _auth(self, token): - return {"Authorization": f"Bearer {token}"} - - def _post(self, path, body, token=None, method="POST"): - return self.fetch( - path, - method=method, - body=body if isinstance(body, str) else escape.json_encode(body), - headers=self._auth(token) if token else {}, - raise_error=False, - ) - - # ─── Security headers ────────────────────────────────────────────────────── - - def test_security_headers_present(self): - resp = self.fetch("/api/v1/health", raise_error=False) - self.assertEqual("nosniff", resp.headers.get("X-Content-Type-Options")) - self.assertEqual("SAMEORIGIN", resp.headers.get("X-Frame-Options")) - self.assertEqual("same-origin", resp.headers.get("Referrer-Policy")) - - def test_security_headers_present_on_error_responses(self): - resp = self.fetch("/api/v1/rbac/user/resources", raise_error=False) - self.assertEqual(401, resp.code) - self.assertEqual("nosniff", resp.headers.get("X-Content-Type-Options")) - - # ─── JSON body helper ────────────────────────────────────────────────────── - - def test_login_invalid_json_returns_400(self): - self.assertEqual(400, self._post("/api/v1/auth/login", "{not json").code) - - def test_login_non_object_json_returns_400(self): - self.assertEqual(400, self._post("/api/v1/auth/login", "[1, 2]").code) - - def test_login_empty_body_returns_400(self): - self.assertEqual(400, self._post("/api/v1/auth/login", "").code) - - def test_create_user_invalid_json_returns_400(self): - self.assertEqual(400, self._post("/api/v1/auth/create", "nope").code) - - def test_v2_create_user_invalid_json_returns_400(self): - self.assertEqual(400, self._post("/api/v2/users", "nope").code) - - def test_change_password_invalid_json_returns_400(self): - token = self._create_and_login_admin() - resp = self._post("/api/v1/auth/change-password", "nope", token, "PATCH") - self.assertEqual(400, resp.code) - - def test_rbac_grant_invalid_json_returns_400(self): - token = self._create_and_login_admin() - self.assertEqual( - 400, self._post("/api/v1/rbac/user/roles/grant", "nope", token).code - ) - - def test_user_settings_patch_non_object_returns_400(self): - token = self._create_and_login_admin() - resp = self._post("/api/v1/user/settings", "[1]", token, "PATCH") - self.assertEqual(400, resp.code) - - def test_system_settings_patch_invalid_json_returns_400(self): - token = self._create_and_login_admin() - resp = self._post("/api/v1/settings", "nope", token, "PATCH") - self.assertEqual(400, resp.code) - - def test_session_start_invalid_json_returns_400(self): - token = self._create_and_login_admin() - resp = self._post("/api/v1/show/sessions/start", "nope", token) - # No show is loaded in this fixture, so requires_show answers first. - self.assertEqual(400, resp.code) - - # ─── require_admin status codes ──────────────────────────────────────────── - - def test_require_admin_unauthenticated_is_401(self): - resp = self._post("/api/v1/rbac/user/roles/grant", {}) - self.assertEqual(401, resp.code) - - def test_require_admin_non_admin_is_403(self): - admin_token = self._create_and_login_admin() - user_token = self._create_and_login_user(admin_token) - resp = self._post("/api/v1/rbac/user/roles/grant", {}, user_token) - self.assertEqual(403, resp.code) - - # ─── RBAC grant / revoke validation ──────────────────────────────────────── - - def _role_body(self, **overrides): - body = { - "resource": "shows", - "object": {"id": 1}, - "user": 1, - "role": 1, - } - body.update(overrides) - return body - - def test_rbac_grant_and_revoke_invalid_input_returns_400(self): - token = self._create_and_login_admin() - bad_bodies = [ - self._role_body(role=999999), - self._role_body(role="admin"), - self._role_body(user="abc"), - self._role_body(object="not-a-dict"), - self._role_body(object={"unrelated": 1}), - self._role_body(resource=["shows"]), - ] - for path in ( - "/api/v1/rbac/user/roles/grant", - "/api/v1/rbac/user/roles/revoke", - ): - for body in bad_bodies: - with self.subTest(path=path, body=body): - resp = self._post(path, body, token) - self.assertEqual(400, resp.code) - - def test_rbac_grant_missing_field_returns_400(self): - token = self._create_and_login_admin() - body = self._role_body() - del body["role"] - resp = self._post("/api/v1/rbac/user/roles/grant", body, token) - self.assertEqual(400, resp.code) - - # ─── User settings allow-list ────────────────────────────────────────────── - - def test_user_settings_patch_sets_allowed_and_ignores_others(self): - token = self._create_and_login_admin() - resp = self._post( - "/api/v1/user/settings", - { - "cue_position_right": True, - "_user_id": 999, - "metadata": "x", - "registry": "x", - "nonexistent": 1, - }, - token, - "PATCH", - ) - self.assertEqual(200, resp.code) - - with self._app.get_db().sessionmaker() as session: - settings = session.scalars(session.query(UserSettings).statement).first() - self.assertTrue(settings.cue_position_right) - self.assertNotEqual(999, settings._user_id) diff --git a/server/test/controllers/api/v1/test_settings.py b/server/test/controllers/api/v1/test_settings.py index 64a9597c..4d6f1778 100644 --- a/server/test/controllers/api/v1/test_settings.py +++ b/server/test/controllers/api/v1/test_settings.py @@ -64,3 +64,16 @@ def test_jwt_lifetime_as_json_includes_choice_labels(self): self.assertEqual( len(json_repr["choice_labels"]), len(json_repr["choice_options"]) ) + + +class TestSettingsController(DigiScriptTestCase): + def test_patch_invalid_json_returns_400(self): + token = self._create_and_login_admin() + resp = self.fetch( + "/api/v1/settings", + method="PATCH", + body="nope", + headers={"Authorization": f"Bearer {token}"}, + raise_error=False, + ) + self.assertEqual(400, resp.code) diff --git a/server/test/controllers/api/v1/user/test_settings.py b/server/test/controllers/api/v1/user/test_settings.py new file mode 100644 index 00000000..e1066aea --- /dev/null +++ b/server/test/controllers/api/v1/user/test_settings.py @@ -0,0 +1,44 @@ +"""Tests for the /api/v1/user/settings controller.""" + +from tornado import escape + +from models.user import UserSettings +from test.conftest import DigiScriptTestCase + + +class TestUserSettingsController(DigiScriptTestCase): + def _patch(self, body, token): + return self.fetch( + "/api/v1/user/settings", + method="PATCH", + body=body if isinstance(body, str) else escape.json_encode(body), + headers={"Authorization": f"Bearer {token}"}, + raise_error=False, + ) + + def test_patch_non_object_returns_400(self): + token = self._create_and_login_admin() + self.assertEqual(400, self._patch("[1]", token).code) + + def test_patch_invalid_json_returns_400(self): + token = self._create_and_login_admin() + self.assertEqual(400, self._patch("nope", token).code) + + def test_patch_sets_allowed_and_ignores_others(self): + token = self._create_and_login_admin() + resp = self._patch( + { + "cue_position_right": True, + "_user_id": 999, + "metadata": "x", + "registry": "x", + "nonexistent": 1, + }, + token, + ) + self.assertEqual(200, resp.code) + + with self._app.get_db().sessionmaker() as session: + settings = session.scalars(session.query(UserSettings).statement).first() + self.assertTrue(settings.cue_position_right) + self.assertNotEqual(999, settings._user_id) diff --git a/server/test/controllers/api/v2/test_users.py b/server/test/controllers/api/v2/test_users.py index 8d3b0a9a..1d22e0f0 100644 --- a/server/test/controllers/api/v2/test_users.py +++ b/server/test/controllers/api/v2/test_users.py @@ -310,3 +310,11 @@ def test_delete_self_rejected(self): # note: the last-admin delete guard (400 when target is the only admin) suffers the same # race-condition constraint as the PATCH guard — not reachable in a synchronous test. + + +class TestUsersV2JsonBodyValidation(DigiScriptTestCase): + def test_create_user_invalid_json_returns_400(self): + resp = self.fetch( + "/api/v2/users", method="POST", body="nope", raise_error=False + ) + self.assertEqual(400, resp.code) diff --git a/server/test/utils/web/test_base_controller.py b/server/test/utils/web/test_base_controller.py new file mode 100644 index 00000000..bf29b283 --- /dev/null +++ b/server/test/utils/web/test_base_controller.py @@ -0,0 +1,16 @@ +"""Tests for the default response headers set by BaseController.""" + +from test.conftest import DigiScriptTestCase + + +class TestBaseControllerDefaultHeaders(DigiScriptTestCase): + def test_security_headers_present(self): + resp = self.fetch("/api/v1/health", raise_error=False) + self.assertEqual("nosniff", resp.headers.get("X-Content-Type-Options")) + self.assertEqual("SAMEORIGIN", resp.headers.get("X-Frame-Options")) + self.assertEqual("same-origin", resp.headers.get("Referrer-Policy")) + + def test_security_headers_present_on_error_responses(self): + resp = self.fetch("/api/v1/rbac/user/resources", raise_error=False) + self.assertEqual(401, resp.code) + self.assertEqual("nosniff", resp.headers.get("X-Content-Type-Options")) diff --git a/server/test/utils/web/test_json_body.py b/server/test/utils/web/test_json_body.py new file mode 100644 index 00000000..279f354e --- /dev/null +++ b/server/test/utils/web/test_json_body.py @@ -0,0 +1,35 @@ +"""Tests for utils/web/json_body.py.""" + +from unittest.mock import MagicMock + +from tornado.web import HTTPError + +from test.conftest import DigiScriptTestCase +from utils.web.json_body import get_json_object + + +def _handler(body: bytes): + handler = MagicMock() + handler.request.body = body + return handler + + +class TestGetJsonObject(DigiScriptTestCase): + def test_valid_object_returned(self): + self.assertEqual({"a": 1}, get_json_object(_handler(b'{"a": 1}'))) + + def test_invalid_json_raises_400(self): + with self.assertRaises(HTTPError) as ctx: + get_json_object(_handler(b"{not json")) + self.assertEqual(400, ctx.exception.status_code) + + def test_empty_body_raises_400(self): + with self.assertRaises(HTTPError) as ctx: + get_json_object(_handler(b"")) + self.assertEqual(400, ctx.exception.status_code) + + def test_non_object_raises_400(self): + for body in (b"[1, 2]", b'"text"', b"5", b"null"): + with self.subTest(body=body), self.assertRaises(HTTPError) as ctx: + get_json_object(_handler(body)) + self.assertEqual(400, ctx.exception.status_code) diff --git a/server/test/utils/web/test_web_decorators.py b/server/test/utils/web/test_web_decorators.py index b54b9ee2..660b6e7c 100644 --- a/server/test/utils/web/test_web_decorators.py +++ b/server/test/utils/web/test_web_decorators.py @@ -116,3 +116,24 @@ def test_empty_room_passes_through(self): self.assertNotEqual(409, response.code) finally: del self._app.room_manager + + +class TestRequireAdminDecorator(DigiScriptTestCase): + """require_admin: 401 when not logged in, 403 for a logged-in non-admin.""" + + def _grant(self, token=None): + return self.fetch( + "/api/v1/rbac/user/roles/grant", + method="POST", + body="{}", + headers={"Authorization": f"Bearer {token}"} if token else {}, + raise_error=False, + ) + + def test_unauthenticated_is_401(self): + self.assertEqual(401, self._grant().code) + + def test_non_admin_is_403(self): + admin_token = self._create_and_login_admin() + user_token = self._create_and_login_user(admin_token) + self.assertEqual(403, self._grant(user_token).code) From 603542e517e72453f55624ba68090559245b923e Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Tue, 20 Oct 2026 13:26:23 +0100 Subject: [PATCH 07/12] Reduce cognitive complexity of REST body logging and WS session op dispatch Behaviour unchanged; addresses SonarCloud S3776 findings. Co-Authored-By: Claude Sonnet 5.5 --- server/controllers/ws_controller.py | 79 ++++++++++++++++------------- server/utils/web/base_controller.py | 67 +++++++++++++++--------- 2 files changed, 89 insertions(+), 57 deletions(-) diff --git a/server/controllers/ws_controller.py b/server/controllers/ws_controller.py index 2b211f5f..2db3b21f 100644 --- a/server/controllers/ws_controller.py +++ b/server/controllers/ws_controller.py @@ -545,47 +545,58 @@ async def _handle_session_op(self, ws_op: str, message: dict) -> None: elif ws_op == "REFRESH_CLIENT": self._resume_client(message.get("DATA")) elif ws_op in self._LEADER_OP_HANDLERS: - show_session = ( - session.get(ShowSession, show.current_session_id) - if show and show.current_session_id - else None - ) - # Ownership rule: only the authenticated show user on its own row. - if self._is_leader(session, show_session): - data = message.get("DATA") - if not isinstance(data, dict): - get_logger().warning(f"Ignored {ws_op}: DATA must be an object") - return - handler = getattr(self, self._LEADER_OP_HANDLERS[ws_op]) - await handler(session, show_session, entry, data) - else: - get_logger().debug( - f"Ignored {ws_op} from client " - f"{self.__getattribute__('internal_id')} (user " - f"{self.current_user_id}): not the live-show leader" - ) + await self._handle_leader_op(session, show, entry, ws_op, message) elif ws_op == "LIVE_SHOW_JUMP_TO_PAGE": - show_session = ( - session.get(ShowSession, show.current_session_id) - if show and show.current_session_id - else None - ) - if show_session and self._user_has_show_execute_access(session, show): - await self._op_jump_to_page( - session, show_session, entry, message.get("DATA") - ) - else: - get_logger().debug( - f"Ignored {ws_op} from client " - f"{self.__getattribute__('internal_id')} (user " - f"{self.current_user_id}): no show execute access" - ) + await self._handle_jump_op(session, show, entry, ws_op, message) else: get_logger().warning( f"Unknown OP {ws_op} received from " f"WebSocket connection {self.request.remote_ip}" ) + @staticmethod + def _live_show_session(session, show: Optional[Show]) -> Optional[ShowSession]: + """Return the show's current live ShowSession, or None.""" + if show and show.current_session_id: + return session.get(ShowSession, show.current_session_id) + return None + + async def _handle_leader_op( + self, session, show: Optional[Show], entry, ws_op: str, message: dict + ) -> None: + """Run a leader-only live-show op if this connection is the leader.""" + show_session = self._live_show_session(session, show) + # Ownership rule: only the authenticated show user on its own row. + if not self._is_leader(session, show_session): + get_logger().debug( + f"Ignored {ws_op} from client " + f"{self.__getattribute__('internal_id')} (user " + f"{self.current_user_id}): not the live-show leader" + ) + return + data = message.get("DATA") + if not isinstance(data, dict): + get_logger().warning(f"Ignored {ws_op}: DATA must be an object") + return + handler = getattr(self, self._LEADER_OP_HANDLERS[ws_op]) + await handler(session, show_session, entry, data) + + async def _handle_jump_op( + self, session, show: Optional[Show], entry, ws_op: str, message: dict + ) -> None: + """Run ``LIVE_SHOW_JUMP_TO_PAGE`` if the user has show EXECUTE access.""" + show_session = self._live_show_session(session, show) + if show_session and self._user_has_show_execute_access(session, show): + await self._op_jump_to_page( + session, show_session, entry, message.get("DATA") + ) + return + get_logger().debug( + f"Ignored {ws_op} from client " + f"{self.__getattribute__('internal_id')} (user " + f"{self.current_user_id}): no show execute access" + ) + def _resume_client(self, new_uuid: Any) -> None: """Handle ``REFRESH_CLIENT``: a reconnecting page resumes its old uuid. diff --git a/server/utils/web/base_controller.py b/server/utils/web/base_controller.py index c9625651..b5cf81a3 100644 --- a/server/utils/web/base_controller.py +++ b/server/utils/web/base_controller.py @@ -21,6 +21,9 @@ if TYPE_CHECKING: from digi_server.app_server import DigiScriptServer +# Returned by BaseAPIController._loggable_body when a body is not valid JSON. +_NON_JSON = object() + class DatabaseMixin: """Mixin providing database session management (replaces tornado_sqlalchemy.SessionMixin).""" @@ -165,6 +168,39 @@ def _log_extra(self) -> dict: extra["user_id"] = self.current_user.get("id") return extra + def _redaction_enabled(self) -> bool: + """Return True if the ``log_redaction`` setting is on.""" + return bool( + self.application.digi_settings.settings["log_redaction"].get_value() + ) + + def _loggable_raw_body(self) -> Any: + """Return a non-JSON request body in the form allowed by ``log_redaction``. + + With redaction on only its size is returned, as it cannot be redacted by key. + """ + if self._redaction_enabled(): + return f"" + return self.request.body + + def _loggable_body(self, redacted_data_paths) -> Any: + """Decode the JSON request body, redacted if ``log_redaction`` is on. + + :param redacted_data_paths: Decorator-supplied patch of paths to redact, + or None. + :returns: The body, or the ``_NON_JSON`` sentinel if it is not valid JSON. + """ + try: + body = escape.json_decode(self.request.body) + except BaseException: + return _NON_JSON + if self._redaction_enabled(): + body = deepcopy(body) + if redacted_data_paths: + redacted_data_paths.apply(body) + body = redact_sensitive_keys(body) + return body + def on_finish(self): from utils.web.route import Route # noqa: PLC0415 @@ -180,28 +216,13 @@ def on_finish(self): method_name = self.request.method.lower() handler_method = getattr(self, method_name, None) redacted_data_paths = getattr(handler_method, "_redacted_data_paths", None) - try: - body = escape.json_decode(self.request.body) - except BaseException: - if self.application.digi_settings.settings["log_redaction"].get_value(): - # Not JSON, so it cannot be redacted by key: log only its size. - logged = f"" - else: - logged = self.request.body - get_logger().debug( - f"{self.request.method} {self.request.path} {logged}{user_suffix}", - extra=self._log_extra(), - ) - else: - if self.application.digi_settings.settings["log_redaction"].get_value(): - body = deepcopy(body) - if redacted_data_paths: - redacted_data_paths.apply(body) - body = redact_sensitive_keys(body) - - log_method( - f"{self.request.method} {self.request.path} {body}{user_suffix}", - extra=self._log_extra(), - ) + logged = self._loggable_body(redacted_data_paths) + if logged is _NON_JSON: + log_method = get_logger().debug + logged = self._loggable_raw_body() + log_method( + f"{self.request.method} {self.request.path} {logged}{user_suffix}", + extra=self._log_extra(), + ) super().on_finish() From 1c91d9824b56f9028843c8d3ce6cedfd8e39c2f1 Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Tue, 20 Oct 2026 13:42:55 +0100 Subject: [PATCH 08/12] Merge dev; non-admin show delete now returns 403 Co-Authored-By: Claude Sonnet 5.5 --- server/test/controllers/api/v1/show/test_shows.py | 2 +- server/test/utils/web/test_base_controller.py | 1 + 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/server/test/controllers/api/v1/show/test_shows.py b/server/test/controllers/api/v1/show/test_shows.py index e70df019..58716411 100644 --- a/server/test/controllers/api/v1/show/test_shows.py +++ b/server/test/controllers/api/v1/show/test_shows.py @@ -450,7 +450,7 @@ def test_delete_show_non_admin(self): session.commit() token = self._app.jwt_service.create_access_token({"user_id": user_id}) response = self._delete(show_b_id, token=token) - self.assertEqual(401, response.code) + self.assertEqual(403, response.code) with self._app.get_db().sessionmaker() as session: self.assertIsNotNone(session.get(Show, show_b_id)) diff --git a/server/test/utils/web/test_base_controller.py b/server/test/utils/web/test_base_controller.py index 98d366cf..643fd788 100644 --- a/server/test/utils/web/test_base_controller.py +++ b/server/test/utils/web/test_base_controller.py @@ -4,6 +4,7 @@ from tornado.httpclient import HTTPRequest from tornado.testing import gen_test + from test.conftest import DigiScriptTestCase From abd282e3db178844b39fb4b205c828e684540407 Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Tue, 20 Oct 2026 13:47:00 +0100 Subject: [PATCH 09/12] Address review: fix redaction crash on absent decorated path, log malformed WS frames per setting - Key-based redaction first; tolerate decorated paths missing from the body - Malformed WS frames log exception text and content per log_redaction - Split BEGIN_INTERVAL warnings, warn on non-object script-room DATA - Redact confirmPassword generically - Tests for absent-path logging, bool interval guards, saved settings kept - Docs: note Log Level must be DEBUG to see raw content Co-Authored-By: Claude Sonnet 5.5 --- docs/pages/user_config.md | 4 +-- server/controllers/ws_controller.py | 17 +++++++++--- server/test/controllers/test_ws_controller.py | 27 ++++++++++++++++--- server/test/digi_server/test_settings.py | 23 ++++++++++++++++ server/test/utils/web/test_base_controller.py | 26 ++++++++++++++++++ server/utils/web/base_controller.py | 10 +++++-- server/utils/web/log_redaction.py | 2 ++ 7 files changed, 98 insertions(+), 11 deletions(-) diff --git a/docs/pages/user_config.md b/docs/pages/user_config.md index 4fe3292c..d22164cc 100644 --- a/docs/pages/user_config.md +++ b/docs/pages/user_config.md @@ -80,7 +80,7 @@ RBAC configuration determines what shows a user can access and what actions they The **Enable Log Redaction** system setting is on by default. While it is on, passwords, tokens and other credentials are replaced with a placeholder in logged HTTP request bodies, and WebSocket messages are logged as their operation name and size only. -Turn it off to see the raw HTTP and WebSocket content while debugging. **Warning:** with redaction off, the logs contain credentials and authentication tokens, so only disable it temporarily and treat the log files as sensitive. Installations that already had the setting saved keep their existing value. +Turn it off to see the raw HTTP and WebSocket content while debugging. Request bodies and WebSocket messages are logged at debug level, so also set **Log Level** to `DEBUG` (the default is `INFO`). **Warning:** with redaction off, the logs contain credentials and authentication tokens, so only disable it temporarily and treat the log files as sensitive. A value you have saved is never changed by a later change to a setting's default. ### Log Viewer @@ -88,7 +88,7 @@ The **Logs** tab (admin only) provides a real-time view of server and client log #### Sources -- **Server** — Application-level logs from the DigiScript backend: HTTP request access logs, request body debug logs, WebSocket connection events, and general application messages. +- **Server** — Application-level logs from the DigiScript backend: HTTP request access logs, request body and WebSocket message debug logs (only shown when the Log Level is `DEBUG`), WebSocket connection events, and general application messages. - **Client** — Logs forwarded from connected browser clients via the `/api/v1/logs/batch` endpoint. #### Username Attribution diff --git a/server/controllers/ws_controller.py b/server/controllers/ws_controller.py index 2db3b21f..7fa892eb 100644 --- a/server/controllers/ws_controller.py +++ b/server/controllers/ws_controller.py @@ -479,9 +479,13 @@ async def on_message(self, message: Union[str, bytes]): if not isinstance(ws_op, str): raise TypeError("OP must be a string") except (json.JSONDecodeError, KeyError, TypeError) as e: + if self.application.digi_settings.get_sync("log_redaction"): + content = f"<{size} bytes>" + else: + content = raw get_logger().warning( - f"Malformed WS message ({size} bytes) from " - f"{self.request.remote_ip}: {type(e).__name__}" + f"Malformed WS message from {self.request.remote_ip}: " + f"{type(e).__name__}: {e} {content}" ) return @@ -681,9 +685,13 @@ async def _op_begin_interval(self, session, show_session, entry, data) -> None: """Leader op ``BEGIN_INTERVAL``: start an interval after the given act.""" act_id = data.get("actId") length = data.get("length") + if not entry: + get_logger().warning( + "Ignored BEGIN_INTERVAL: no session entry for this connection" + ) + return if ( - not entry - or isinstance(act_id, bool) + isinstance(act_id, bool) or not isinstance(act_id, int) or isinstance(length, bool) or not isinstance(length, (int, float)) @@ -875,6 +883,7 @@ async def _handle_script_room_op(self, ws_op: str, message: dict): data = message.get("DATA") if not isinstance(data, dict): + get_logger().warning(f"{ws_op}: DATA is not an object; treating as empty") data = {} # Everything that touches the shared draft only exists in collaborative mode; diff --git a/server/test/controllers/test_ws_controller.py b/server/test/controllers/test_ws_controller.py index c889aa5c..6ccb4912 100644 --- a/server/test/controllers/test_ws_controller.py +++ b/server/test/controllers/test_ws_controller.py @@ -3496,14 +3496,35 @@ def latest(): await ws_l.write_message( json.dumps({"OP": "SCRIPT_SCROLL", "DATA": {"current_line": ["x"]}}) ) - await ws_l.write_message( - json.dumps({"OP": "BEGIN_INTERVAL", "DATA": {"actId": "a", "length": 1}}) - ) + for bad_interval in ( + {"actId": "a", "length": 1}, + {"actId": True, "length": 1}, + {"actId": 1, "length": True}, + ): + await ws_l.write_message( + json.dumps({"OP": "BEGIN_INTERVAL", "DATA": bad_interval}) + ) await ws_l.write_message(json.dumps({"OP": "LIVE_SHOW_JUMP_TO_PAGE"})) await self._still_responsive(ws_l, self.admin_id) self.assertEqual(before, latest()) + with self._app.get_db().sessionmaker() as session: + self.assertEqual([], session.scalars(select(Interval)).all()) ws_l.close() + @gen_test + async def test_malformed_frame_content_logging_follows_redaction_setting(self): + ws, _ = await self._connect_and_auth(self.admin_id) + for redaction, expect_raw in ((True, False), (False, True)): + self._app.digi_settings.settings["log_redaction"].set_value(redaction) + with self.assertLogs(get_logger(), level="WARNING") as captured: + await ws.write_message('{"NOOP": "SENTINEL-FRAME"}') + await self._still_responsive(ws, self.admin_id) + get_logger().warning("marker") + joined = "\n".join(captured.output) + self.assertIn("Malformed WS message", joined) + self.assertEqual(expect_raw, "SENTINEL-FRAME" in joined) + ws.close() + @gen_test async def test_non_object_and_non_string_op_frames_are_ignored(self): ws, _ = await self._connect_and_auth(self.admin_id) diff --git a/server/test/digi_server/test_settings.py b/server/test/digi_server/test_settings.py index 7c8267af..aa2dbd39 100644 --- a/server/test/digi_server/test_settings.py +++ b/server/test/digi_server/test_settings.py @@ -1,3 +1,5 @@ +import json + from test.conftest import DigiScriptTestCase @@ -9,3 +11,24 @@ def test_log_redaction_enabled_by_default(self): setting = self._app.digi_settings.settings["log_redaction"] self.assertTrue(setting.default) self.assertTrue(setting.get_value()) + + +class TestSavedLoggingSettingsAreKept(DigiScriptTestCase): + """A value already saved in the settings file wins over a changed default.""" + + def get_app(self): + with open(self.settings_path, encoding="UTF-8") as file_pointer: + saved = json.load(file_pointer) + saved["log_redaction"] = False + saved["log_level"] = "DEBUG" + with open(self.settings_path, "w", encoding="UTF-8") as file_pointer: + json.dump(saved, file_pointer) + return super().get_app() + + def test_saved_log_redaction_is_not_overridden(self): + setting = self._app.digi_settings.settings["log_redaction"] + self.assertFalse(setting.get_value()) + + def test_saved_log_level_is_not_overridden(self): + setting = self._app.digi_settings.settings["log_level"] + self.assertEqual("DEBUG", setting.get_value()) diff --git a/server/test/utils/web/test_base_controller.py b/server/test/utils/web/test_base_controller.py index 82624e34..730726c9 100644 --- a/server/test/utils/web/test_base_controller.py +++ b/server/test/utils/web/test_base_controller.py @@ -52,3 +52,29 @@ async def test_non_json_body_follows_setting(self): ) self._set_redaction(False) self.assertIn("SENTINEL-RAW", await self._post_login("password=SENTINEL-RAW")) + + @gen_test + async def test_decorated_path_absent_from_body_still_logs_redacted(self): + """A body missing a decorated redaction path (optional old_password) must + still be logged, with its other secrets redacted, and must not error. + """ + self._set_redaction(True) + request = HTTPRequest( + self.get_url("/api/v1/auth/change-password"), + method="PATCH", + body=json.dumps({"new_password": "SENTINEL-NEW"}), + ) + with self.assertLogs(level="DEBUG") as captured: + await self.http_client.fetch(request, raise_error=False) + joined = "\n".join(captured.output) + self.assertIn("/api/v1/auth/change-password", joined) + self.assertNotIn("SENTINEL-NEW", joined) + self.assertNotIn("Uncaught exception", joined) + + @gen_test + async def test_confirm_password_redacted_without_decorator(self): + self._set_redaction(True) + joined = await self._post_login( + json.dumps({"username": "x", "confirmPassword": "SENTINEL-CONFIRM"}) + ) + self.assertNotIn("SENTINEL-CONFIRM", joined) diff --git a/server/utils/web/base_controller.py b/server/utils/web/base_controller.py index b5cf81a3..e38a7403 100644 --- a/server/utils/web/base_controller.py +++ b/server/utils/web/base_controller.py @@ -4,6 +4,7 @@ from typing import TYPE_CHECKING, Any, Awaitable, Optional import bcrypt +from jsonpath import JSONPatchError from sqlalchemy import select from tornado import escape, httputil from tornado.ioloop import IOLoop @@ -196,9 +197,14 @@ def _loggable_body(self, redacted_data_paths) -> Any: return _NON_JSON if self._redaction_enabled(): body = deepcopy(body) - if redacted_data_paths: - redacted_data_paths.apply(body) body = redact_sensitive_keys(body) + if redacted_data_paths: + try: + redacted_data_paths.apply(body) + except JSONPatchError: + # A decorated path is absent from this body (e.g. the optional + # old_password); there is nothing at that path to redact. + pass return body def on_finish(self): diff --git a/server/utils/web/log_redaction.py b/server/utils/web/log_redaction.py index 01733751..9bbd21aa 100644 --- a/server/utils/web/log_redaction.py +++ b/server/utils/web/log_redaction.py @@ -11,6 +11,8 @@ SENSITIVE_KEYS = frozenset( { "password", + "confirmpassword", + "confirm_password", "new_password", "old_password", "current_password", From 3a635055e134970aa224b8bae55baaa2f508ae75 Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Wed, 21 Oct 2026 00:18:12 +0100 Subject: [PATCH 10/12] Mark sensitive settings with a define() kwarg instead of a key allow-list Co-Authored-By: Claude Sonnet 5.5 --- server/digi_server/settings.py | 39 +++++++++++++++++----------------- 1 file changed, 19 insertions(+), 20 deletions(-) diff --git a/server/digi_server/settings.py b/server/digi_server/settings.py index cc076ac9..654c86d9 100644 --- a/server/digi_server/settings.py +++ b/server/digi_server/settings.py @@ -55,6 +55,7 @@ def __init__( hide_from_ui: bool = False, choice_options: Optional[list] = None, choice_labels: Optional[list] = None, + sensitive: bool = False, ): if val_type not in self.ALLOWED_TYPES: raise RuntimeError( @@ -110,6 +111,8 @@ def __init__( self.display_name = display_name self.help_text = help_text self.hide_from_ui = hide_from_ui + # Sensitive settings (e.g. server filesystem paths) are only disclosed to admins. + self.sensitive = sensitive self.choice_options = choice_options self.choice_labels = choice_labels @@ -170,20 +173,6 @@ def as_json(self): } -#: Settings holding server filesystem locations. They are only disclosed to -#: administrators; everyone else (and every broadcast) gets them omitted. -SENSITIVE_SETTINGS = frozenset( - { - "db_path", - "log_path", - "db_log_path", - "client_log_path", - "compiled_script_path", - "draft_script_path", - } -) - - class Settings: def __init__(self, application: DigiScriptServer, settings_path=None): self._application = application @@ -236,6 +225,7 @@ def init_settings(self): False, nullable=False, display_name="Database Path", + sensitive=True, ) self.define( "current_show", @@ -294,6 +284,7 @@ def init_settings(self): self._application.regen_logging, display_name="Application Log Path", category="Logging", + sensitive=True, ) self.define( "max_log_mb", @@ -343,6 +334,7 @@ def init_settings(self): self._application.regen_logging, display_name="Database Log Path", category="DB Logging", + sensitive=True, ) self.define( "db_max_log_mb", @@ -369,6 +361,7 @@ def init_settings(self): False, display_name="Compiled Script Path", help_text="Directory used to store compiled scripts.", + sensitive=True, ) self.define( "draft_script_path", @@ -377,6 +370,7 @@ def init_settings(self): False, display_name="Draft Script Path", help_text="Directory used to store collaborative editing draft files.", + sensitive=True, ) self.define( "client_log_enabled", @@ -407,6 +401,7 @@ def init_settings(self): display_name="Client Log Path", help_text="Path to the log file for client-side log messages.", category="Client Logging", + sensitive=True, ) self.define( "client_max_log_mb", @@ -478,6 +473,7 @@ def define( choice_options: Optional[list] = None, choice_labels: Optional[list] = None, category: str = "General", + sensitive: bool = False, ): if key in self.settings: raise KeyError(f"Setting {key} is already defined") @@ -494,6 +490,7 @@ def define( hide_from_ui, choice_options, choice_labels, + sensitive, ) if category not in self.categories: self.categories[category] = [key] @@ -616,13 +613,14 @@ def _json(self): async def as_json(self, include_sensitive: bool = False): """Return all setting values plus the server version. - :param include_sensitive: Include the filesystem path settings in - :data:`SENSITIVE_SETTINGS`. Only pass True for administrators. + :param include_sensitive: Include settings defined with + ``sensitive=True`` (server filesystem paths). Only pass True for + administrators. """ async with self.lock: settings_json = {} for key, value in self.settings.items(): - if not include_sensitive and key in SENSITIVE_SETTINGS: + if not include_sensitive and value.sensitive: continue settings_json[key] = value.get_value() settings_json["version"] = _get_version() @@ -631,13 +629,14 @@ async def as_json(self, include_sensitive: bool = False): async def raw_json(self, include_sensitive: bool = False): """Return full setting metadata (type, default, help text, ...). - :param include_sensitive: Include the filesystem path settings in - :data:`SENSITIVE_SETTINGS`. Only pass True for administrators. + :param include_sensitive: Include settings defined with + ``sensitive=True`` (server filesystem paths). Only pass True for + administrators. """ async with self.lock: settings_json = {} for key, value in self.settings.items(): - if not include_sensitive and key in SENSITIVE_SETTINGS: + if not include_sensitive and value.sensitive: continue settings_json[key] = value.as_json() return json.loads(json.dumps(settings_json)) From 954a0be4343f90e8c9dc3eeaa448092242161192 Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Wed, 21 Oct 2026 00:26:17 +0100 Subject: [PATCH 11/12] Shrink the client logger change to cut new-code duplication Co-Authored-By: Claude Sonnet 5.5 --- client-v3/src/js/logger.ts | 16 ++++++---------- client/src/js/logger.ts | 16 ++++++---------- 2 files changed, 12 insertions(+), 20 deletions(-) diff --git a/client-v3/src/js/logger.ts b/client-v3/src/js/logger.ts index be45f57d..246b8acd 100644 --- a/client-v3/src/js/logger.ts +++ b/client-v3/src/js/logger.ts @@ -19,6 +19,7 @@ let flushTimer: ReturnType | null = null; function enqueueLog(level: string, message: string, extra: Record): void { logQueue.push({ level, message, extra }); + if (logQueue.length > MAX_QUEUE_SIZE) logQueue.shift(); if (logQueue.length >= MAX_QUEUE_SIZE) { flushQueue(); return; @@ -33,20 +34,15 @@ function flushQueue() { flushTimer = null; if (logQueue.length === 0) return; - // The server only accepts log posts from logged-in users. Before login, keep the - // most recent entries queued (bounded) and send them once a token exists. + // The server only accepts log posts from logged-in users, so entries stay queued + // (capped in enqueueLog) until a token exists. const token = useUserStore().authToken; - if (!token) { - if (logQueue.length > MAX_QUEUE_SIZE) logQueue.splice(0, logQueue.length - MAX_QUEUE_SIZE); - return; - } + if (!token) return; const batch = logQueue.splice(0); - const headers: Record = { - 'Content-Type': 'application/json', - Authorization: `Bearer ${token}`, - }; + const headers: Record = { 'Content-Type': 'application/json' }; + if (token) headers['Authorization'] = `Bearer ${token}`; fetch(makeURL('/api/v1/logs/batch'), { method: 'POST', diff --git a/client/src/js/logger.ts b/client/src/js/logger.ts index 3185ee60..544d2329 100644 --- a/client/src/js/logger.ts +++ b/client/src/js/logger.ts @@ -22,6 +22,7 @@ let flushTimer: ReturnType | null = null; */ function enqueueLog(level: string, message: string, extra: Record): void { logQueue.push({ level, message, extra }); + if (logQueue.length > MAX_QUEUE_SIZE) logQueue.shift(); if (logQueue.length >= MAX_QUEUE_SIZE) { flushQueue(); return; @@ -39,20 +40,15 @@ function flushQueue() { flushTimer = null; if (logQueue.length === 0) return; - // The server only accepts log posts from logged-in users. Before login, keep the - // most recent entries queued (bounded) and send them once a token exists. + // The server only accepts log posts from logged-in users, so entries stay queued + // (capped in enqueueLog) until a token exists. const token = store.getters.AUTH_TOKEN; - if (!token) { - if (logQueue.length > MAX_QUEUE_SIZE) logQueue.splice(0, logQueue.length - MAX_QUEUE_SIZE); - return; - } + if (!token) return; const batch = logQueue.splice(0); - const headers: Record = { - 'Content-Type': 'application/json', - Authorization: `Bearer ${token}`, - }; + const headers: Record = { 'Content-Type': 'application/json' }; + if (token) headers['Authorization'] = `Bearer ${token}`; fetch(makeURL('/api/v1/logs/batch'), { method: 'POST', From a7db686a4d56c1dc12bcb9b9ba8aa2dceed2a327 Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Wed, 21 Oct 2026 01:05:21 +0100 Subject: [PATCH 12/12] Address review: filter file-reload broadcast, harden log parsing, refetch settings on login Co-Authored-By: Claude Sonnet 5.5 --- client-v3/src/js/logger.test.ts | 62 +++++++++++++ client-v3/src/stores/user.ts | 2 + client/src/js/logger.test.ts | 65 ++++++++++++++ client/src/store/modules/user/user.ts | 3 + server/controllers/api/v1/logging.py | 90 ++++++++++++++----- server/digi_server/settings.py | 30 ++++--- .../test/controllers/api/v1/test_logging.py | 75 ++++++++++++++-- .../test/controllers/api/v1/test_settings.py | 20 +++++ 8 files changed, 306 insertions(+), 41 deletions(-) create mode 100644 client-v3/src/js/logger.test.ts create mode 100644 client/src/js/logger.test.ts diff --git a/client-v3/src/js/logger.test.ts b/client-v3/src/js/logger.test.ts new file mode 100644 index 00000000..49e6427c --- /dev/null +++ b/client-v3/src/js/logger.test.ts @@ -0,0 +1,62 @@ +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; + +const userState: { authToken: string | null } = { authToken: null }; + +vi.mock('@/stores/user', () => ({ useUserStore: () => userState })); +vi.mock('@/stores/system', () => ({ + useSystemStore: () => ({ settings: { client_log_enabled: true, client_log_level: 'DEBUG' } }), +})); + +describe('remote logger', () => { + const fetchMock = vi.fn(() => Promise.resolve(new Response('{}'))); + + beforeEach(async () => { + vi.useFakeTimers(); + vi.resetModules(); + fetchMock.mockClear(); + vi.stubGlobal('fetch', fetchMock); + userState.authToken = null; + const { initRemoteLogging } = await import('./logger'); + initRemoteLogging(); + }); + + afterEach(() => { + vi.useRealTimers(); + vi.unstubAllGlobals(); + }); + + it('holds log entries until a token exists, then sends them with it', async () => { + const log = (await import('loglevel')).default; + log.error('before login'); + await vi.advanceTimersByTimeAsync(2000); + expect(fetchMock).not.toHaveBeenCalled(); + + userState.authToken = 'tok'; + log.error('after login'); + await vi.advanceTimersByTimeAsync(2000); + + expect(fetchMock).toHaveBeenCalledTimes(1); + const [, init] = fetchMock.mock.calls[0] as unknown as [string, RequestInit]; + expect((init.headers as Record).Authorization).toBe('Bearer tok'); + const messages = JSON.parse(init.body as string).batch.map( + (e: { message: string }) => e.message + ); + expect(messages).toEqual(expect.arrayContaining(['before login', 'after login'])); + }); + + it('keeps only the most recent 50 entries while logged out', async () => { + const log = (await import('loglevel')).default; + for (let i = 0; i < 80; i++) log.error(`entry ${i}`); + + userState.authToken = 'tok'; + await vi.advanceTimersByTimeAsync(2000); + log.error('final'); + await vi.advanceTimersByTimeAsync(2000); + + const [, init] = fetchMock.mock.calls[0] as unknown as [string, RequestInit]; + const batch = JSON.parse(init.body as string).batch as { message: string }[]; + expect(batch.length).toBeLessThanOrEqual(50); + expect(batch.map((e) => e.message)).not.toContain('entry 0'); + expect(batch.map((e) => e.message)).toContain('final'); + }); +}); diff --git a/client-v3/src/stores/user.ts b/client-v3/src/stores/user.ts index 05fbe2c4..0775d4e7 100644 --- a/client-v3/src/stores/user.ts +++ b/client-v3/src/stores/user.ts @@ -57,6 +57,7 @@ export const useUserStore = defineStore('user', { try { await useSystemStore().getRbacRoles(); + await useSystemStore().getRawSettings(); await this.getCurrentUser(); await this.getCurrentRbac(); await this.getUserSettings(); @@ -94,6 +95,7 @@ export const useUserStore = defineStore('user', { this.userSettings = {}; this.stageDirectionStyleOverrides = []; this.cueColourOverrides = []; + void useSystemStore().getRawSettings(); // drop admin-only values from the cache // Mark the open WebSocket as waiting for authentication (as the legacy // client's CLEAR_WS_AUTHENTICATION does), so the next in-app login diff --git a/client/src/js/logger.test.ts b/client/src/js/logger.test.ts new file mode 100644 index 00000000..f68b208b --- /dev/null +++ b/client/src/js/logger.test.ts @@ -0,0 +1,65 @@ +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; + +const getters: Record = {}; + +vi.mock('@/store/store', () => ({ default: { getters, watch: vi.fn() } })); + +describe('remote logger', () => { + const fetchMock = vi.fn(() => Promise.resolve(new Response('{}'))); + let log: typeof import('loglevel').default; + + const sentBatches = () => + fetchMock.mock.calls.map((call) => { + const [, init] = call as unknown as [string, RequestInit]; + return { + auth: (init.headers as Record).Authorization, + messages: (JSON.parse(init.body as string).batch as { message: string }[]).map( + (e) => e.message + ), + }; + }); + + beforeEach(async () => { + vi.useFakeTimers(); + vi.resetModules(); + fetchMock.mockClear(); + vi.stubGlobal('fetch', fetchMock); + getters.AUTH_TOKEN = null; + getters.SETTINGS = { client_log_enabled: true, client_log_level: 'DEBUG' }; + await (await import('./logger')).initRemoteLogging(); + log = (await import('loglevel')).default; + }); + + afterEach(() => { + vi.useRealTimers(); + vi.unstubAllGlobals(); + }); + + it('does not post while logged out and flushes the held entries after login', async () => { + log.error('queued while logged out'); + await vi.advanceTimersByTimeAsync(2000); + expect(fetchMock).not.toHaveBeenCalled(); + + getters.AUTH_TOKEN = 'tok'; + log.error('logged in'); + await vi.advanceTimersByTimeAsync(2000); + + const [batch] = sentBatches(); + expect(batch.auth).toBe('Bearer tok'); + expect(batch.messages).toEqual( + expect.arrayContaining(['queued while logged out', 'logged in']) + ); + }); + + it('caps the logged-out queue at the 50 most recent entries', async () => { + for (let i = 0; i < 80; i++) log.error(`entry ${i}`); + getters.AUTH_TOKEN = 'tok'; + log.error('final'); + await vi.advanceTimersByTimeAsync(2000); + + const [batch] = sentBatches(); + expect(batch.messages.length).toBeLessThanOrEqual(50); + expect(batch.messages).not.toContain('entry 0'); + expect(batch.messages).toContain('final'); + }); +}); diff --git a/client/src/store/modules/user/user.ts b/client/src/store/modules/user/user.ts index 2a6ac182..bde2e139 100644 --- a/client/src/store/modules/user/user.ts +++ b/client/src/store/modules/user/user.ts @@ -116,6 +116,7 @@ const module: Module = { await context.commit('SET_AUTH_TOKEN', data.access_token); } await context.dispatch('GET_RBAC_ROLES'); + await context.dispatch('GET_RAW_SETTINGS'); await context.dispatch('GET_CURRENT_USER'); await context.dispatch('GET_CURRENT_RBAC'); await context.dispatch('GET_USER_SETTINGS'); @@ -150,6 +151,8 @@ const module: Module = { await context.commit('SET_USER_SETTINGS', []); await context.commit('SET_STAGE_DIRECTION_STYLE_OVERRIDES', []); await context.commit('CLEAR_WS_AUTHENTICATION'); + // Re-fetch (now anonymous) so admin-only values are dropped from the cache. + context.dispatch('GET_RAW_SETTINGS'); if (token) { try { const response = await fetch(makeURL('/api/v1/auth/logout'), { diff --git a/server/controllers/api/v1/logging.py b/server/controllers/api/v1/logging.py index cf87657d..1502ae23 100644 --- a/server/controllers/api/v1/logging.py +++ b/server/controllers/api/v1/logging.py @@ -1,6 +1,6 @@ import json import time -from typing import Any, Dict, List, Optional +from typing import Any, Dict, List, NamedTuple, Optional, Tuple from tornado import escape, httputil @@ -22,11 +22,19 @@ RATE_LIMIT_WINDOW_SECONDS = 60.0 +class _Window(NamedTuple): + """A client's current rate-limit window.""" + + start: float + used: int + + class ClientLogRateLimiter: """Fixed-window, per-IP limiter on the number of client log entries. One instance lives on the application object, so no state is shared between - application instances (or test workers). + application instances (or test workers). Clients are keyed by raw IP address, + so users sharing an IP (NAT, proxy) share one budget. """ def __init__( @@ -34,30 +42,41 @@ def __init__( limit: int = RATE_LIMIT_ENTRIES, window: float = RATE_LIMIT_WINDOW_SECONDS, ): + """ + :param limit: Entries allowed per window; must be positive. + :param window: Window length in seconds; must be positive. + :raises ValueError: If *limit* or *window* is not positive. + """ + if limit <= 0 or window <= 0: + raise ValueError("limit and window must be positive") self.limit = limit self.window = window - self._windows: Dict[str, tuple] = {} + self._windows: Dict[str, _Window] = {} - def check(self, key: str, cost: int, now: Optional[float] = None) -> float: + def check( + self, key: str, cost: int, now: Optional[float] = None + ) -> Optional[float]: """Try to consume *cost* entries for *key*. :param key: The client identifier (IP address). :param cost: Number of entries in the request. :param now: Current monotonic time; defaults to ``time.monotonic()``. - :returns: 0 if allowed, otherwise the seconds until the window resets. + :returns: None if allowed, otherwise the seconds (at least 1) until the + window resets. """ now = time.monotonic() if now is None else now - # Drop expired windows so the dict stays bounded by active clients. + # Runs on every call (not periodically): this bounds memory and is also what + # resets a key's window once it has expired. expired = [ - ip for ip, (start, _) in self._windows.items() if now - start >= self.window + ip for ip, win in self._windows.items() if now - win.start >= self.window ] for ip in expired: del self._windows[ip] - start, used = self._windows.get(key, (now, 0)) - if used + cost > self.limit: - return max(self.window - (now - start), 1.0) - self._windows[key] = (start, used + cost) - return 0.0 + win = self._windows.get(key, _Window(now, 0)) + if win.used + cost > self.limit: + return max(self.window - (now - win.start), 1.0) + self._windows[key] = _Window(win.start, win.used + cost) + return None def _clean_text(value: Any, limit: int) -> str: @@ -68,16 +87,24 @@ def _clean_text(value: Any, limit: int) -> str: return text.replace("\r", "\\r").replace("\n", "\\n") -def _clean_extra(value: Any) -> Dict: - """Return *value* if it is a small JSON-serialisable dict, else a stand-in.""" +def _clean_extra(value: Any) -> Tuple[Dict, Optional[str]]: + """Sanitise an entry's client-supplied ``extra``. + + :param value: The raw ``extra`` value. + :returns: A ``(extra, omitted_reason)`` pair. A small JSON-serialisable dict is + returned as-is with no reason. Non-dict input is dropped silently + (``{}``, no reason). An oversized or non-serialisable dict is replaced by + ``{}`` with a reason, which the caller records under a server-controlled + key so a client cannot forge it. + """ if not isinstance(value, dict): - return {} + return {}, None try: if len(json.dumps(value, default=str)) > MAX_EXTRA_LENGTH: - return {"extra": "[omitted: too large]"} - except (TypeError, ValueError): - return {"extra": "[omitted: not serialisable]"} - return {str(k): v for k, v in value.items()} + return {}, "too large" + except (TypeError, ValueError, RecursionError): + return {}, "not serialisable" + return {str(k): v for k, v in value.items()}, None class ClientLoggingBase(BaseAPIController): @@ -102,7 +129,7 @@ def process_logs(self, entries: List[Any]): limiter = ClientLogRateLimiter() self.application.client_log_limiter = limiter retry_after = limiter.check(self.request.remote_ip or "unknown", len(entries)) - if retry_after: + if retry_after is not None: self.set_status(429) self.set_header("Retry-After", str(int(retry_after) + 1)) self.write({"message": "Too many log entries"}) @@ -119,12 +146,18 @@ def process_logs(self, entries: List[Any]): request_extra["user_id"] = self.current_user.get("id") request_extra["username"] = self.current_user.get("username") + dropped = 0 for entry in entries: if not isinstance(entry, dict): + dropped += 1 continue level = _clean_text(entry.get("level", "INFO"), 16).upper() message = _clean_text(entry.get("message", ""), MAX_MESSAGE_LENGTH) - extra = {**_clean_extra(entry.get("extra")), **request_extra} + client_extra, omitted = _clean_extra(entry.get("extra")) + # Server-set keys come last so a client cannot forge them. + extra = {**client_extra, **request_extra} + if omitted: + extra["extra_omitted"] = omitted log_level = map_client_level(level) @@ -145,6 +178,12 @@ def process_logs(self, entries: List[Any]): }, ) + if dropped: + get_logger().warning( + f"Dropped {dropped} malformed client log entries from " + f"{request_extra['remote_ip']}" + ) + self.set_status(200) self.write({"status": "OK"}) @@ -163,7 +202,7 @@ async def post(self): try: data = escape.json_decode(self.request.body) - except ValueError: + except (ValueError, RecursionError): self.set_status(400) self.write({"message": "Invalid JSON"}) return @@ -203,9 +242,14 @@ async def post(self): try: data = escape.json_decode(self.request.body) - except ValueError: + except (ValueError, RecursionError): self.set_status(400) self.write({"message": "Invalid JSON"}) return + if not isinstance(data, dict): + self.set_status(400) + self.write({"message": "Expected a JSON object log entry"}) + return + self.process_logs([data]) diff --git a/server/digi_server/settings.py b/server/digi_server/settings.py index 654c86d9..426c43a0 100644 --- a/server/digi_server/settings.py +++ b/server/digi_server/settings.py @@ -111,7 +111,8 @@ def __init__( self.display_name = display_name self.help_text = help_text self.hide_from_ui = hide_from_ui - # Sensitive settings (e.g. server filesystem paths) are only disclosed to admins. + # Sensitive settings (e.g. server filesystem paths) are only ever disclosed to + # admins: every payload sent to other users or broadcast omits them. self.sensitive = sensitive self.choice_options = choice_options self.choice_labels = choice_labels @@ -501,13 +502,22 @@ def file_deleted(self): get_logger().info("Settings file deleted; recreating from in memory settings") self._save() + def _values(self, include_sensitive: bool) -> dict: + """Return the current value of every setting, omitting sensitive ones unless asked. + + :param include_sensitive: Include settings defined with ``sensitive=True``. + """ + return { + key: value.get_value() + for key, value in self.settings.items() + if include_sensitive or not value.sensitive + } + def auto_reload_changes(self): get_logger().info("Settings file changed; auto reloading") self._load(spawn_callbacks=True) - settings_json = {} - for key, value in self.settings.items(): - settings_json[key] = value.get_value() + settings_json = self._values(include_sensitive=False) for client in self._application.clients.copy(): client.write_message( @@ -613,24 +623,18 @@ def _json(self): async def as_json(self, include_sensitive: bool = False): """Return all setting values plus the server version. - :param include_sensitive: Include settings defined with - ``sensitive=True`` (server filesystem paths). Only pass True for + :param include_sensitive: Include sensitive settings. Only pass True for administrators. """ async with self.lock: - settings_json = {} - for key, value in self.settings.items(): - if not include_sensitive and value.sensitive: - continue - settings_json[key] = value.get_value() + settings_json = self._values(include_sensitive) settings_json["version"] = _get_version() return json.loads(json.dumps(settings_json)) async def raw_json(self, include_sensitive: bool = False): """Return full setting metadata (type, default, help text, ...). - :param include_sensitive: Include settings defined with - ``sensitive=True`` (server filesystem paths). Only pass True for + :param include_sensitive: Include sensitive settings. Only pass True for administrators. """ async with self.lock: diff --git a/server/test/controllers/api/v1/test_logging.py b/server/test/controllers/api/v1/test_logging.py index 725f61be..20823757 100644 --- a/server/test/controllers/api/v1/test_logging.py +++ b/server/test/controllers/api/v1/test_logging.py @@ -102,15 +102,69 @@ def test_oversized_extra_replaced(self): self.assertIn("too large", out) self.assertNotIn("yyyyyyyyyy", out) - def test_non_string_fields_coerced(self): + def test_non_string_fields_coerced_and_malformed_entries_dropped(self): token = self._create_and_login_admin() batch = [ {"level": 5, "message": {"a": 1}, "extra": "not-a-dict"}, {"level": None, "message": None, "extra": [1, 2]}, "not-an-object", ] - response = self._post("/api/v1/logs/batch", {"batch": batch}, token) + with self.assertLogs(get_logger("Client"), level="DEBUG") as client_logs: + with self.assertLogs(get_logger(), level="WARNING") as server_logs: + response = self._post("/api/v1/logs/batch", {"batch": batch}, token) self.assertEqual(200, response.code) + self.assertEqual(2, len(client_logs.records)) + self.assertIn("{'a': 1}", client_logs.records[0].getMessage()) + self.assertIn("None", client_logs.records[1].getMessage()) + self.assertTrue(any("Dropped 1 malformed" in m for m in server_logs.output)) + + def test_client_extra_cannot_forge_server_omission_marker(self): + token = self._create_and_login_admin() + with self.assertLogs(get_logger("Client"), level="DEBUG") as logs: + self._post( + "/api/v1/logs", + {"message": "m", "extra": {"extra_omitted": "too large"}}, + token, + ) + # A client-supplied key of the same name is its own data, not a server marker: + # the server only ever adds the marker for entries it actually reduced. + self.assertEqual(1, logs.records[0].getMessage().count("extra_omitted")) + + def test_oversize_entry_does_not_affect_sibling_entries(self): + token = self._create_and_login_admin() + batch = [ + {"message": "A" * (MAX_MESSAGE_LENGTH * 2), "extra": {"k": "y" * 100000}}, + {"message": "small sibling", "extra": {"k": "v"}}, + ] + with self.assertLogs(get_logger("Client"), level="DEBUG") as logs: + self._post("/api/v1/logs/batch", {"batch": batch}, token) + self.assertIn("[truncated]", logs.records[0].getMessage()) + self.assertIn("too large", logs.records[0].getMessage()) + sibling = logs.records[1].getMessage() + self.assertIn("small sibling", sibling) + self.assertNotIn("truncated", sibling) + self.assertNotIn("extra_omitted", sibling) + + def test_empty_batch_accepted(self): + token = self._create_and_login_admin() + response = self._post("/api/v1/logs/batch", {"batch": []}, token) + self.assertEqual(200, response.code) + + def test_single_entry_must_be_an_object(self): + token = self._create_and_login_admin() + for body in ("42", '"x"', "[1, 2, 3]"): + response = self._post("/api/v1/logs", None, token, body=body) + self.assertEqual(400, response.code) + + def test_deeply_nested_json_returns_400(self): + token = self._create_and_login_admin() + nested = "[" * 200000 + "1" + "]" * 200000 + response = self._post("/api/v1/logs", None, token, body=nested) + self.assertEqual(400, response.code) + response = self._post( + "/api/v1/logs/batch", None, token, body='{"batch":' + nested + "}" + ) + self.assertEqual(400, response.code) def test_rate_limit_returns_429(self): token = self._create_and_login_admin() @@ -124,7 +178,18 @@ def test_rate_limit_returns_429(self): def test_rate_limiter_window_resets_and_prunes(self): limiter = ClientLogRateLimiter(limit=2, window=10) - self.assertEqual(0, limiter.check("a", 2, now=0)) - self.assertGreater(limiter.check("a", 1, now=1), 0) - self.assertEqual(0, limiter.check("b", 1, now=11)) + self.assertIsNone(limiter.check("a", 2, now=0)) + self.assertGreaterEqual(limiter.check("a", 1, now=1), 1.0) + self.assertIsNone(limiter.check("b", 1, now=11)) self.assertNotIn("a", limiter._windows) + + def test_rate_limiter_budgets_are_per_ip(self): + limiter = ClientLogRateLimiter(limit=2, window=10) + self.assertIsNone(limiter.check("a", 2, now=0)) + self.assertIsNotNone(limiter.check("a", 1, now=1)) + self.assertIsNone(limiter.check("b", 2, now=1)) + + def test_rate_limiter_rejects_non_positive_configuration(self): + for kwargs in ({"limit": 0}, {"limit": -1}, {"window": 0}): + with self.assertRaises(ValueError): + ClientLogRateLimiter(**kwargs) diff --git a/server/test/controllers/api/v1/test_settings.py b/server/test/controllers/api/v1/test_settings.py index b9f38c70..4f82dc27 100644 --- a/server/test/controllers/api/v1/test_settings.py +++ b/server/test/controllers/api/v1/test_settings.py @@ -103,6 +103,26 @@ def test_settings_show_paths_to_admin(self): for key in self.PATH_KEYS: self.assertIn(key, data) + def test_file_reload_broadcast_has_no_paths(self): + class FakeClient: + def __init__(self): + self.messages = [] + + def write_message(self, message): + self.messages.append(message) + + client = FakeClient() + self._app.clients.append(client) + try: + self._app.digi_settings.auto_reload_changes() + finally: + self._app.clients.remove(client) + self.assertEqual(1, len(client.messages)) + data = client.messages[0]["DATA"] + for key in self.PATH_KEYS: + self.assertNotIn(key, data) + self.assertIn("client_log_enabled", data) + def test_broadcast_payload_has_no_paths(self): data = self.io_loop.run_sync(self._app.digi_settings.as_json) for key in self.PATH_KEYS: