diff --git a/docs/pages/user_config.md b/docs/pages/user_config.md index c98c5b12..104365cf 100644 --- a/docs/pages/user_config.md +++ b/docs/pages/user_config.md @@ -98,7 +98,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. 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 25093cf8..0a6b2f96 100644 --- a/server/digi_server/app_server.py +++ b/server/digi_server/app_server.py @@ -347,10 +347,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 - observe_http_request(handler) + self._observe_metrics(handler, access_log) if handler.request.path in Route.ignored_logging_routes(): return @@ -361,8 +397,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..38962e12 100644 --- a/server/test/digi_server/test_digi_server.py +++ b/server/test/digi_server/test_digi_server.py @@ -1,10 +1,15 @@ import ast +import asyncio 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.websocket import websocket_connect +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 +95,106 @@ 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_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") + 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://") + 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): + 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: + 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():