From 753669b03ee2c829f2829994b6eae1998344c917 Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Thu, 22 Oct 2026 18:32:10 +0100 Subject: [PATCH 1/3] Record HTTP request metrics and demote successful access logs to DEBUG DigiScriptServer.log_request overrode PrometheusMixIn.log_request without calling observe_request, so tornado_http_requests_total and tornado_http_request_duration_seconds never had samples. Observe requests before the ignored-route early return (guarded so metrics can't break requests), and log 1xx-3xx at DEBUG, 4xx at WARNING, 5xx at ERROR. Co-Authored-By: Claude Sonnet 5.5 --- docs/pages/user_config.md | 2 +- server/digi_server/app_server.py | 11 +++- server/test/digi_server/test_digi_server.py | 59 +++++++++++++++++++++ 3 files changed, 69 insertions(+), 3 deletions(-) diff --git a/docs/pages/user_config.md b/docs/pages/user_config.md index 76105c35..612d6018 100644 --- a/docs/pages/user_config.md +++ b/docs/pages/user_config.md @@ -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 and WebSocket message debug logs (only shown when the Log Level is `DEBUG`), WebSocket connection events, and general application messages. +- **Server** — Application-level logs from the DigiScript backend: HTTP request access logs (successful 1xx-3xx responses are logged at `DEBUG`, client errors at `WARNING`, server errors at `ERROR`), 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/digi_server/app_server.py b/server/digi_server/app_server.py index f8c59cb6..5b4b008c 100644 --- a/server/digi_server/app_server.py +++ b/server/digi_server/app_server.py @@ -346,7 +346,12 @@ class AlembicVersion(self._db.Model): def log_request(self, handler): from tornado.log import access_log # noqa: PLC0415 - observe_http_request(handler) + try: + self.observe_request(handler) + observe_http_request(handler) + except Exception: + # Metrics must never break request handling. + access_log.debug("Failed to record HTTP request metrics", exc_info=True) if handler.request.path in Route.ignored_logging_routes(): return @@ -357,8 +362,10 @@ def log_request(self, handler): username = handler.current_user.get("username") user_id = handler.current_user.get("id") + # Successful/redirect/informational responses (including 304 polling and + # 101 websocket upgrades) are noisy, so they only appear at DEBUG. if handler.get_status() < 400: - log_method = access_log.info + log_method = access_log.debug elif handler.get_status() < 500: log_method = access_log.warning else: diff --git a/server/test/digi_server/test_digi_server.py b/server/test/digi_server/test_digi_server.py index bbd51ee0..3696eb99 100644 --- a/server/test/digi_server/test_digi_server.py +++ b/server/test/digi_server/test_digi_server.py @@ -1,10 +1,13 @@ import ast from pathlib import Path +from unittest.mock import patch import tornado.escape from sqlalchemy import func, select from tornado.testing import gen_test +from tornado_prometheus import requests_total +from controllers.controllers import ApiDebugController from models.session import Session from models.settings import SystemSettings from models.user import User @@ -90,6 +93,62 @@ def test_request_without_body_not_observed(self): self.fetch("/api/v1/nonexistent") self.assertEqual(before, self._body_count("ApiFallback", "GET")) + def test_http_request_metrics_exposed(self): + """Handled requests produce tornado_http_* samples on /debug/metrics.""" + self.fetch("/api/v1/debug") + self.fetch("/api/v1/nonexistent") + body = self.fetch("/debug/metrics").body.decode() + self.assertRegex(body, r"(?m)^tornado_http_requests_total\{.*\} [1-9]") + self.assertRegex( + body, + r"(?m)^tornado_http_request_duration_seconds_count\{.*\} [1-9]", + ) + + def test_ignored_logging_route_counted_but_not_logged(self): + """Ignored-logging routes are observed in metrics but emit no access log.""" + before = self._request_count("DebugMetricsController") + with self.assertNoLogs("tornado.access", level="DEBUG"): + response = self.fetch("/debug/metrics") + self.assertEqual(200, response.code) + self.assertEqual(before + 1, self._request_count("DebugMetricsController")) + + def test_metrics_failure_does_not_break_request(self): + """A failing metrics observer is swallowed and the request still succeeds.""" + with patch.object( + self._app, "observe_request", side_effect=RuntimeError("boom") + ): + response = self.fetch("/api/v1/debug") + self.assertEqual(200, response.code) + + def test_access_log_levels(self): + """2xx logs at DEBUG, 4xx at WARNING and 5xx at ERROR.""" + with self.assertLogs("tornado.access", level="DEBUG") as ok: + self.fetch("/api/v1/debug") + self.assertEqual(["DEBUG"], [r.levelname for r in ok.records]) + self.assertIn("200 GET /api/v1/debug", ok.records[0].getMessage()) + + with self.assertLogs("tornado.access", level="DEBUG") as warn: + self.fetch("/api/v1/nonexistent") + self.assertEqual(["WARNING"], [r.levelname for r in warn.records]) + + with ( + patch.object(ApiDebugController, "get", side_effect=RuntimeError("x")), + self.assertLogs("tornado.access", level="DEBUG") as err, + ): + self.fetch("/api/v1/debug") + self.assertEqual(["ERROR"], [r.levelname for r in err.records]) + + def _request_count(self, handler): + total = 0 + for metric in requests_total.collect(): + for sample in metric.samples: + if ( + sample.name.endswith("_total") + and sample.labels.get("handler") == handler + ): + total += sample.value + return total + @staticmethod def _body_count(handler, method): for metric in http_request_body_bytes.collect(): From d76f3dcc1b820b348f65a866437982f8469fc239 Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Thu, 22 Oct 2026 23:14:48 +0100 Subject: [PATCH 2/3] Make metrics observers independent, rate-limit failure warnings, keep WS 101 out of 5xx tornado_prometheus.classify_status_code buckets anything outside 200-499 as 5xx, so every WebSocket upgrade (101) was counted as a server error. Skip observe_request for 1xx. Run each observer independently and warn (with traceback) at most once per minute on failure, DEBUG otherwise. Co-Authored-By: Claude Sonnet 5.5 --- docs/pages/user_config.md | 2 +- server/digi_server/app_server.py | 43 ++++++++++++++++++--- server/test/digi_server/test_digi_server.py | 36 +++++++++++++++++ 3 files changed, 74 insertions(+), 7 deletions(-) diff --git a/docs/pages/user_config.md b/docs/pages/user_config.md index 612d6018..55d7f083 100644 --- a/docs/pages/user_config.md +++ b/docs/pages/user_config.md @@ -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 (successful 1xx-3xx responses are logged at `DEBUG`, client errors at `WARNING`, server errors at `ERROR`), request body and WebSocket message debug logs (only shown when the Log Level is `DEBUG`), WebSocket connection events, and general application messages. +- **Server** — Application-level logs from the DigiScript backend: HTTP request access logs (successful 1xx-3xx responses are logged at `DEBUG`, client errors at `WARNING`, server errors at `ERROR`), request body and WebSocket message debug logs (only shown when the Log Level is `DEBUG`), WebSocket connection events, and general application messages. HTTP request metrics (`tornado_http_requests_total`, `tornado_http_request_duration_seconds`) are exposed on `/debug/metrics`; WebSocket upgrades (HTTP 101) are not counted in the request-status series. - **Client** — Logs forwarded from connected browser clients via the `/api/v1/logs/batch` endpoint. #### Username Attribution diff --git a/server/digi_server/app_server.py b/server/digi_server/app_server.py index 5b4b008c..b5637ffa 100644 --- a/server/digi_server/app_server.py +++ b/server/digi_server/app_server.py @@ -343,15 +343,46 @@ class AlembicVersion(self._db.Model): login_url="/login", ) + _METRICS_WARN_INTERVAL = 60.0 + _last_metrics_warning = float("-inf") + + def _observe_metrics(self, handler, access_log): + """ + Record Prometheus metrics for a finished request. + + Each observer runs independently so one failing does not skip the other, + and failures never propagate into request handling. A failure is warned + about at most once per ``_METRICS_WARN_INTERVAL`` seconds (with the + traceback) and logged at DEBUG otherwise, so a persistent regression is + visible at INFO without per-request spam. + + Informational (1xx) responses, i.e. the 101 of a WebSocket upgrade, are + not fed to ``observe_request``: ``tornado_prometheus`` classifies any + status outside 200-499 as ``5xx``, which would count every WebSocket + connect as a server error. + + :param handler: The finished request handler. + :param access_log: The ``tornado.access`` logger. + """ + observers = [observe_http_request] + if handler.get_status() >= 200: + observers.insert(0, self.observe_request) + for observe in observers: + try: + observe(handler) + except Exception: + now = time.monotonic() + if now - self._last_metrics_warning >= self._METRICS_WARN_INTERVAL: + self._last_metrics_warning = now + log = access_log.warning + else: + log = access_log.debug + log("Failed to record HTTP request metrics", exc_info=True) + def log_request(self, handler): from tornado.log import access_log # noqa: PLC0415 - try: - self.observe_request(handler) - observe_http_request(handler) - except Exception: - # Metrics must never break request handling. - access_log.debug("Failed to record HTTP request metrics", exc_info=True) + self._observe_metrics(handler, access_log) if handler.request.path in Route.ignored_logging_routes(): return diff --git a/server/test/digi_server/test_digi_server.py b/server/test/digi_server/test_digi_server.py index 3696eb99..d295ccf8 100644 --- a/server/test/digi_server/test_digi_server.py +++ b/server/test/digi_server/test_digi_server.py @@ -3,8 +3,10 @@ from unittest.mock import patch import tornado.escape +import tornado.gen from sqlalchemy import func, select from tornado.testing import gen_test +from tornado.websocket import websocket_connect from tornado_prometheus import requests_total from controllers.controllers import ApiDebugController @@ -120,6 +122,40 @@ def test_metrics_failure_does_not_break_request(self): response = self.fetch("/api/v1/debug") self.assertEqual(200, response.code) + def test_metrics_failure_warns_once_and_other_observer_runs(self): + """Failures are warned about once per interval and observers are independent.""" + before = self._body_count("ApiFallback", "POST") + with ( + patch.object(self._app, "observe_request", side_effect=RuntimeError("x")), + self.assertLogs("tornado.access", level="DEBUG") as logs, + ): + self.fetch("/api/v1/nonexistent", method="POST", body="x" * 10) + self.fetch("/api/v1/nonexistent", method="POST", body="x" * 10) + failures = [r for r in logs.records if "Failed to record" in r.getMessage()] + self.assertEqual(["WARNING", "DEBUG"], [r.levelname for r in failures]) + self.assertIsNotNone(failures[0].exc_info) + self.assertEqual(before + 2, self._body_count("ApiFallback", "POST")) + + @gen_test + async def test_websocket_upgrade_not_counted_as_5xx(self): + """A 101 upgrade must not land in the 5xx series (tornado_prometheus quirk).""" + before_5xx = self._status_count("5xx") + ws_url = self.get_url("/api/v1/ws").replace("http://", "ws://") + ws = await websocket_connect(ws_url) + ws.close() + await tornado.gen.sleep(0.2) + self.assertEqual(before_5xx, self._status_count("5xx")) + + def _status_count(self, status): + total = 0 + for metric in requests_total.collect(): + for sample in metric.samples: + if sample.name.endswith("_total") and ( + sample.labels.get("status") == status + ): + total += sample.value + return total + def test_access_log_levels(self): """2xx logs at DEBUG, 4xx at WARNING and 5xx at ERROR.""" with self.assertLogs("tornado.access", level="DEBUG") as ok: From 85b1c758b19dd8c39dc8ad9c67f50113cbf6b3a4 Mon Sep 17 00:00:00 2001 From: Tim Bradgate Date: Thu, 22 Oct 2026 23:50:43 +0100 Subject: [PATCH 3/3] Wait on request completion instead of a fixed sleep in WS 5xx test Co-Authored-By: Claude Sonnet 5.5 --- server/test/digi_server/test_digi_server.py | 18 ++++++++++++++---- 1 file changed, 14 insertions(+), 4 deletions(-) diff --git a/server/test/digi_server/test_digi_server.py b/server/test/digi_server/test_digi_server.py index d295ccf8..38962e12 100644 --- a/server/test/digi_server/test_digi_server.py +++ b/server/test/digi_server/test_digi_server.py @@ -1,9 +1,9 @@ import ast +import asyncio from pathlib import Path from unittest.mock import patch import tornado.escape -import tornado.gen from sqlalchemy import func, select from tornado.testing import gen_test from tornado.websocket import websocket_connect @@ -140,10 +140,20 @@ def test_metrics_failure_warns_once_and_other_observer_runs(self): async def test_websocket_upgrade_not_counted_as_5xx(self): """A 101 upgrade must not land in the 5xx series (tornado_prometheus quirk).""" before_5xx = self._status_count("5xx") + upgrade_logged = asyncio.Event() + original = self._app.log_request + + def log_request(handler): + original(handler) + if handler.get_status() == 101: + upgrade_logged.set() + ws_url = self.get_url("/api/v1/ws").replace("http://", "ws://") - ws = await websocket_connect(ws_url) - ws.close() - await tornado.gen.sleep(0.2) + with patch.object(self._app, "log_request", side_effect=log_request): + ws = await websocket_connect(ws_url) + ws.close() + # Wait (bounded) for the server to finish handling the upgrade. + await asyncio.wait_for(upgrade_logged.wait(), timeout=10) self.assertEqual(before_5xx, self._status_count("5xx")) def _status_count(self, status):