From d1f1968317a21bfcb0a47c3b9c01530177cd311e Mon Sep 17 00:00:00 2001
From: Thomas Faour <tom@tfao.ca>
Date: Tue, 28 Jul 2026 03:24:13 +0000
Subject: [PATCH] Log device-facing /frame/* requests in the server log

The admin log viewer only ever showed exceptions from device.py, not
successful requests -- no way to see a request that was slow-but-200,
or a device probing with a stale/wrong token. Adds a middleware that
logs method, path, device id (never the token), status, and wall time
for every /frame/* request.
---
 server/app/main.py              | 25 +++++++++++++++++++++++++
 server/tests/test_admin_logs.py | 15 +++++++++++++++
 2 files changed, 40 insertions(+)

diff --git a/server/app/main.py b/server/app/main.py
index f096a48..2f09b8f 100644
--- a/server/app/main.py
+++ b/server/app/main.py
@@ -16,6 +16,7 @@ pre-database config.json deployment on first boot."""
 from __future__ import annotations
 
 import logging
+import time
 
 from fastapi import FastAPI, Request
 from fastapi.responses import FileResponse, HTMLResponse, RedirectResponse
@@ -48,6 +49,30 @@ migration.run_migrations()
 app = FastAPI(title="ESPresso Frame Server")
 templates = Jinja2Templates(directory="app/templates")
 
+
+@app.middleware("http")
+async def log_device_requests(request: Request, call_next):
+    """Access log for the firmware-facing /frame/* protocol -- the admin
+    log viewer otherwise only ever shows exceptions (device.py logs
+    those, not successful requests), so a slow-but-200 request or a
+    device hammering a stale/wrong token leaves no trace at all. Logs
+    the device id (query param, not the token -- never log credentials)
+    and wall time, which is exactly what's needed to spot a request that
+    blew past the firmware's fixed HTTP timeout without technically
+    failing server-side."""
+    if not request.url.path.startswith("/frame/"):
+        return await call_next(request)
+    start = time.monotonic()
+    device_id = request.query_params.get("id", "") or "-"
+    response = await call_next(request)
+    elapsed_ms = (time.monotonic() - start) * 1000
+    logger.info(
+        "%s %s id=%s -> %d (%.0fms)",
+        request.method, request.url.path, device_id, response.status_code, elapsed_ms,
+    )
+    return response
+
+
 app.mount("/static", StaticFiles(directory="app/static"), name="static")
 
 app.include_router(device.router)
diff --git a/server/tests/test_admin_logs.py b/server/tests/test_admin_logs.py
index 9185f5d..1b5f9e6 100644
--- a/server/tests/test_admin_logs.py
+++ b/server/tests/test_admin_logs.py
@@ -8,6 +8,7 @@ from __future__ import annotations
 import logging
 
 from app.logging_setup import LOG_PATH
+from app.models import Frame
 
 from .conftest import login, make_user
 
@@ -52,6 +53,20 @@ def test_admin_can_download_log_file(client, db_session):
     assert b"marker-line-for-download" in resp.content
 
 
+def test_device_requests_are_logged(client, db_session):
+    _setup_admin_and_user(client, db_session)
+    frame = db_session.get(Frame, 1)
+    frame.device_id = "aabbccddeeff"
+    db_session.commit()
+    resp = client.get(f"/frame/config?id={frame.device_id}&token={frame.device_token}")
+    assert resp.status_code == 200
+
+    login(client, "alice", "hunter22")
+    log_resp = client.get("/admin/logs")
+    # Jinja HTML-escapes the rendered <pre>, so "->" becomes "-&gt;".
+    assert f"GET /frame/config id={frame.device_id} -&gt; 200" in log_resp.text
+
+
 def test_download_404s_before_any_log_written(client, db_session, monkeypatch):
     _setup_admin_and_user(client, db_session)
     login(client, "alice", "hunter22")