Skip to content

feat: request timing middleware and /debug/timing page#204

Merged
axisrow merged 3 commits intomainfrom
feat/request-timing-debug
Mar 22, 2026
Merged

feat: request timing middleware and /debug/timing page#204
axisrow merged 3 commits intomainfrom
feat/request-timing-debug

Conversation

@axisrow
Copy link
Owner

@axisrow axisrow commented Mar 22, 2026

Summary

  • Add TimingMiddleware that wraps every request and records duration via time.monotonic()
  • Add TimingBuffer (circular buffer, 200 entries) to store per-request timing records
  • Add /debug/timing page showing last 200 requests sorted by duration descending; rows >1000ms highlighted red, 500–999ms yellow
  • Log WARNING: SLOW ... for requests exceeding 500ms

Test plan

  • Start server: python -m src.main serve
  • Navigate to several pages (/channels, /dashboard, /analytics)
  • Open /debug/timing — verify table populates with correct method/path/status/ms
  • Verify /static/ and /health requests are excluded from the buffer
  • Trigger a slow route and confirm WARNING: SLOW ... appears in /debug/ logs

Closes #203

🤖 Generated with Claude Code

Add TimingMiddleware that measures per-request duration and stores
results in a TimingBuffer. Slow requests (>500ms) are logged as
WARNING. A new /debug/timing page displays the last 200 requests
sorted by duration, with color-coded rows for slow/very-slow requests.

Closes #203

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
@axisrow
Copy link
Owner Author

axisrow commented Mar 22, 2026

@claude review. Focus on critical issues: bugs, security vulnerabilities, logical errors, data loss risks, performance problems. Do NOT nitpick style, naming conventions, minor formatting, or subjective preferences — only flag issues that could break functionality or cause real harm in production.

@claude
Copy link

claude bot commented Mar 22, 2026

Claude finished @axisrow's task in 2m 5s —— View job


Code Review: feat/request-timing-debug

  • Gather context
  • Read changed files
  • Analyze for critical issues
  • Post review

Overall the implementation is clean and correct. No security vulnerabilities, data loss risks, or logic errors found. Two issues worth addressing and one minor observation:


Issue 1: Unhandled exception leaves timing gap (src/web/app.py:83–100)

async def dispatch(self, request: Request, call_next):
    t0 = time.monotonic()
    response = await call_next(request)   # ← no try/except
    ...

If call_next raises an exception that isn't caught by FastAPI's unhandled_exception_handler before reaching the middleware (e.g., the exception handler itself raises, or a Starlette-level transport error occurs), response is never set, the timing record is never added, and the WARNING: SLOW log is never emitted. In normal operation this is unlikely, but wrapping in try/except would make the middleware robust:

try:
    response = await call_next(request)
finally:
    ms = int((time.monotonic() - t0) * 1000)
    # record + warn here

Fix this →


Issue 2: Redundant (and slightly incorrect) static path exclusion (src/web/app.py:88)

if not is_public_path(path) and not path.startswith("/static"):

is_public_path (panel_auth.py:52) already returns True for path.startswith("/static/") (with trailing slash). The extra check not path.startswith("/static") is therefore redundant AND subtly different — it also silently excludes any hypothetical /staticfiles or /static (no slash) routes from timing. It should either be removed (relying on is_public_path's existing /static/ coverage) or use the same trailing-slash form for consistency. This won't cause a production bug today, but it's a latent inconsistency.

Fix this →


Observation: /debug/timing records itself

The timing page is not excluded from the buffer, so visiting it adds a new row on every load. With the current 200-entry circular buffer this is harmless noise, but if you add auto-refresh (like /debug/logs has) it would fill the buffer quickly with self-referential entries. Worth excluding /debug/timing from recording in the middleware if auto-refresh is ever added.


Not an issue: thread/concurrency safety

TimingBuffer uses collections.deque from asyncio context (single event loop thread). No locking needed. ✓

Not an issue: XSS in template

Jinja2's {{ r.path }} auto-escapes HTML. ✓

Not an issue: auth protection

/debug/timing is behind BasicAuthMiddleware since it's not in is_public_path. ✓

…tatic check

- Use try/finally so timing is always recorded even when call_next raises
  (e.g. connection resets, streaming errors); status defaults to 500 in
  error case
- Remove redundant `path.startswith("/static")` — is_public_path already
  covers /static/ paths, keeping public-path logic in one place

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
@axisrow
Copy link
Owner Author

axisrow commented Mar 22, 2026

Observation: /debug/timing records itself — acknowledged. Under current usage (manually opened page) this is harmless noise in the circular buffer. If auto-refresh is ever added to this page, the self-recording entries should be excluded at that point. No change made now.

@axisrow
Copy link
Owner Author

axisrow commented Mar 22, 2026

@claude review. Focus on critical issues: bugs, security vulnerabilities, logical errors, data loss risks, performance problems. Do NOT nitpick style, naming conventions, minor formatting, or subjective preferences — only flag issues that could break functionality or cause real harm in production.

@claude
Copy link

claude bot commented Mar 22, 2026

Claude finished @axisrow's task in 1m 33s —— View job


Code Review: feat/request-timing-debug

  • Gather context and read changed files
  • Analyze for critical issues
  • Post review

Both issues from the previous review have been addressed in commit 314c9b1. The current code is clean — no bugs, security vulnerabilities, logic errors, or data loss risks found.

Issue 1 (try/finally) — Fixed. response = None is initialized before the try block, and status = response.status_code if response is not None else 500 correctly handles exception paths. ✓

Issue 2 (redundant static check) — Fixed. The not path.startswith("/static") guard has been removed; the middleware now relies solely on is_public_path(path). ✓


One dead-code note (src/web/timing.py:26–28)

TimingBuffer.now() is defined as a static method but never called anywhere — the middleware uses time.strftime("%H:%M:%S") directly. Not a bug, but it's unreachable code. Safe to remove if you want to keep the file tidy.


Not an issue: timing_buffer identity across middleware and routes

The middleware reads request.app.state.timing_buffer (set synchronously in create_app()); the route handler reads through container.timing_buffer. lifespan passes the pre-existing buffer instance into build_container_with_templates, and configure_app re-assigns the same reference back to app.state. Both paths point to the same TimingBuffer object. ✓

Not an issue: middleware ordering

TimingMiddleware runs outermost (before BasicAuthMiddleware), so 401 responses to non-public paths are recorded. The timing page itself is still auth-protected, so there's no information disclosure concern. ✓


No blocking issues. Ready to merge.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
@axisrow axisrow merged commit c0c47f9 into main Mar 22, 2026
2 checks passed
@axisrow axisrow deleted the feat/request-timing-debug branch March 22, 2026 23:43
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

perf: add request timing middleware to identify slow routes

1 participant