From 2b2d4a72ae5c6b63c80d43af9fb3f2d44b7b2f25 Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Mon, 19 Oct 2026 21:19:39 +0100 Subject: [PATCH 1/5] 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 10c39b195170657eae6b98493ca8c5875ae83f8e Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Mon, 19 Oct 2026 23:19:21 +0100 Subject: [PATCH 2/5] 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 603542e517e72453f55624ba68090559245b923e Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Tue, 20 Oct 2026 13:26:23 +0100 Subject: [PATCH 3/5] 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 abd282e3db178844b39fb4b205c828e684540407 Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Tue, 20 Oct 2026 13:47:00 +0100 Subject: [PATCH 4/5] 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 47b5cef0de99bdd1aae3f6867e55f24c8a914df2 Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Tue, 20 Oct 2026 23:51:50 +0100 Subject: [PATCH 5/5] Apply decorated redaction paths independently and only to dict/list bodies Co-Authored-By: Claude Sonnet 5.5 --- server/test/utils/web/test_base_controller.py | 10 ++++++++ server/test/utils/web/test_log_redaction.py | 25 ++++++++++++++++++- server/utils/web/base_controller.py | 10 ++------ server/utils/web/log_redaction.py | 24 ++++++++++++++++++ 4 files changed, 60 insertions(+), 9 deletions(-) diff --git a/server/test/utils/web/test_base_controller.py b/server/test/utils/web/test_base_controller.py index 730726c9..ca8c72f9 100644 --- a/server/test/utils/web/test_base_controller.py +++ b/server/test/utils/web/test_base_controller.py @@ -71,6 +71,16 @@ async def test_decorated_path_absent_from_body_still_logs_redacted(self): self.assertNotIn("SENTINEL-NEW", joined) self.assertNotIn("Uncaught exception", joined) + @gen_test + async def test_json_string_body_does_not_break_logging(self): + """A body that decodes to a bare JSON string is still logged and does not + raise in on_finish (the handler's own rejection of it is separate). + """ + self._set_redaction(True) + joined = await self._post_login('"{"') + self.assertIn("DEBUG:DigiScript:POST /api/v1/auth/login", joined) + self.assertNotIn("on_finish", joined) + @gen_test async def test_confirm_password_redacted_without_decorator(self): self._set_redaction(True) diff --git a/server/test/utils/web/test_log_redaction.py b/server/test/utils/web/test_log_redaction.py index 0620b0ee..a4e5fdc4 100644 --- a/server/test/utils/web/test_log_redaction.py +++ b/server/test/utils/web/test_log_redaction.py @@ -1,6 +1,12 @@ import unittest -from utils.web.log_redaction import REDACTED, redact_sensitive_keys +from jsonpath import JSONPatch + +from utils.web.log_redaction import ( + REDACTED, + apply_path_redactions, + redact_sensitive_keys, +) class TestRedactSensitiveKeys(unittest.TestCase): @@ -27,3 +33,20 @@ 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 TestApplyPathRedactions(unittest.TestCase): + def _patch(self, *paths): + patch = JSONPatch() + for path in paths: + patch.replace(path, REDACTED) + return patch + + def test_missing_path_does_not_stop_later_paths(self): + body = {"new_password": "secret"} + apply_path_redactions(self._patch("/old_password", "/new_password"), body) + self.assertEqual({"new_password": REDACTED}, body) + + def test_non_container_body_is_ignored(self): + for body in ("{", 5, None): + apply_path_redactions(self._patch("/password"), body) diff --git a/server/utils/web/base_controller.py b/server/utils/web/base_controller.py index e38a7403..713ef4e1 100644 --- a/server/utils/web/base_controller.py +++ b/server/utils/web/base_controller.py @@ -4,7 +4,6 @@ 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 @@ -16,7 +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 +from utils.web.log_redaction import apply_path_redactions, redact_sensitive_keys if TYPE_CHECKING: @@ -199,12 +198,7 @@ def _loggable_body(self, redacted_data_paths) -> Any: body = deepcopy(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 + apply_path_redactions(redacted_data_paths, body) return body def on_finish(self): diff --git a/server/utils/web/log_redaction.py b/server/utils/web/log_redaction.py index 9bbd21aa..3db8f523 100644 --- a/server/utils/web/log_redaction.py +++ b/server/utils/web/log_redaction.py @@ -4,6 +4,8 @@ from typing import Any +from jsonpath import JSONPatch, JSONPatchError + REDACTED = "<-- REDACTED -->" @@ -46,3 +48,25 @@ def redact_sensitive_keys(value: Any) -> Any: if isinstance(value, list): return [redact_sensitive_keys(item) for item in value] return value + + +def apply_path_redactions(patch: JSONPatch, body: Any) -> None: + """Apply each operation of a redaction *patch* to *body* independently, in place. + + A path absent from the body is skipped without stopping the remaining paths + (``JSONPatch.apply`` would abort at the first failure). Bodies that are not a + dict or list are left alone: ``JSONPatch`` would treat a string as serialized + JSON and raise on it. + + :param patch: Patch of ``replace`` operations built by ``redact_data_paths``. + :param body: Decoded JSON request body, modified in place. + """ + if not isinstance(body, (dict, list)): + return + for operation in patch.ops: + single = JSONPatch() + single.ops.append(operation) + try: + single.apply(body) + except JSONPatchError: + continue