Fix missing HTTP request metrics; demote success access logs to DEBUG

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

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:

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():