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.
This commit is contained in:
@@ -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)
|
||||
|
||||
@@ -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 "->".
|
||||
assert f"GET /frame/config id={frame.device_id} -> 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")
|
||||
|
||||
Reference in New Issue
Block a user