Skip to content

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

Merged
Tim020 merged 4 commits into
devfrom
feature/obs-http-metrics-access-log
Oct 22, 2026
Merged

Tim020 merged 4 commits into
devfrom
feature/obs-http-metrics-access-log

Conversation

@Tim020

@Tim020 Tim020 commented Oct 22, 2026

Copy link
Copy Markdown
Contributor

Summary

  • `DigiScriptServer.log_request` never called `observe_request`, so `tornado_http_requests_total` / `tornado_http_request_duration_seconds` had no samples. Now observed before the ignored-route early return, guarded so a metrics failure never breaks a request.
  • Access log levels: 1xx/2xx/3xx -> DEBUG, 4xx -> WARNING, 5xx -> ERROR (message format and extra fields unchanged).
  • Tests added to test_digi_server.py; user docs note updated.

Test plan

  • pytest: 1160 passed; ruff check/format clean
  • Full Playwright (chromium): 225 passed; tornado_http_* samples confirmed on /debug/metrics during the run

🤖 Generated with Claude Code

DigiScriptServer.log_request overrode PrometheusMixIn.log_request without
calling observe_request, so tornado_http_requests_total and
tornado_http_request_duration_seconds never had samples. Observe requests
before the ignored-route early return (guarded so metrics can't break
requests), and log 1xx-3xx at DEBUG, 4xx at WARNING, 5xx at ERROR.

Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>
@Tim020 Tim020 added the claude Issues created by Claude label Oct 22, 2026
@github-actions github-actions Bot added documentation Improvements or additions to documentation small-diff Small pull request server Pull requests changing back end code labels Oct 22, 2026
@github-actions

github-actions Bot commented Oct 22, 2026 •

Copy link
Copy Markdown

Client Test Results

102 tests   102 ✅  0s ⏱️
  9 suites    0 💤
  1 files      0 ❌

Results for commit 85b1c75.

♻️ This comment has been updated with latest results.

@github-actions

github-actions Bot commented Oct 22, 2026 •

Copy link
Copy Markdown

Client V3 Test Results

227 tests   227 ✅  0s ⏱️
 20 suites    0 💤
  1 files      0 ❌

Results for commit 85b1c75.

♻️ This comment has been updated with latest results.

@github-actions

github-actions Bot commented Oct 22, 2026 •

Copy link
Copy Markdown

Python Test Results

    1 files      1 suites   1m 17s ⏱️
1 189 tests 1 189 ✅ 0 💤 0 ❌
1 212 runs  1 212 ✅ 0 💤 0 ❌

Results for commit 85b1c75.

♻️ This comment has been updated with latest results.

@github-actions

github-actions Bot commented Oct 22, 2026 •

Copy link
Copy Markdown

Playwright E2E Results (firefox)

227 tests   227 ✅  2m 24s ⏱️
 14 suites    0 💤
  1 files      0 ❌

Results for commit 85b1c75.

♻️ This comment has been updated with latest results.

@Tim020
Tim020 added this pull request to stack #1468 October 22, 2026 17:48
@github-actions

github-actions Bot commented Oct 22, 2026 •

Copy link
Copy Markdown

Playwright E2E Results (chromium)

227 tests   227 ✅  2m 25s ⏱️
 14 suites    0 💤
  1 files      0 ❌

Results for commit 85b1c75.

♻️ This comment has been updated with latest results.

@Tim020
Tim020 marked this pull request as ready for review October 22, 2026 17:52

@Tim020 Tim020 left a comment

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Review round 1

Head SHA: 753669b03ee2c829f2829994b6eae1998344c917

Verdict: Ready to merge once the suggestion below is considered; nothing blocking.

Previous round follow-up: none (first round, no existing threads).

SonarQube: Quality Gate passed (source: Sonar bot PR comment and SonarCloud check run; the API/MCP was not queried for line-level detail). 0 new issues, 0 security hotspots, 0.0% duplication on new code, coverage condition passing.

New findings: 0 Critical, 0 Important, 1 Suggestion (inline).

Strengths:

  • Fixes the root cause: observe_request was previously never called because log_request was overridden, so tornado_http_* metrics were missing. The new test_http_request_metrics_exposed asserts this end to end.
  • Metrics are recorded before the ignored-logging early return, so /debug/metrics scrapes are counted but not logged, and this is tested.
  • Good test coverage of all three log-level bands (DEBUG/WARNING/ERROR) and of the failure-swallowing path; docs updated to match.

Note: I could not inspect tornado_prometheus.PrometheusMixIn locally (package not installed in this environment), so I relied on the tests for the observe_request contract.

🤖 Generated with Claude Code

Comment thread server/digi_server/app_server.py Outdated
… WS 101 out of 5xx

tornado_prometheus.classify_status_code buckets anything outside 200-499
as 5xx, so every WebSocket upgrade (101) was counted as a server error.
Skip observe_request for 1xx. Run each observer independently and warn
(with traceback) at most once per minute on failure, DEBUG otherwise.

Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>
@Tim020

Tim020 commented Oct 22, 2026

Copy link
Copy Markdown
Contributor Author

Review round 1 addressed in d76f3dc.

  • Inline suggestion (independent observers, failures visible at INFO): fixed. Each observer runs in its own try; failure logs a WARNING with traceback at most once per 60s, DEBUG otherwise (avoids per-request spam; deliberately not warning every request). Tests cover independence and warn-once.
  • Cross-cutting (Add Prometheus/Grafana monitoring overlay and docs #1462): confirmed. tornado_prometheus.classify_status_code returns "5xx" for anything outside 200-499, so the 101 WS upgrade was counted as 5xx. Fixed at source: observe_request is skipped for 1xx; other statuses (2xx/3xx/4xx/5xx) still counted. Regression test test_websocket_upgrade_not_counted_as_5xx fails without the fix. 3xx classification is correct.
  • Docs: user_config.md updated to describe the metrics and the 101 exclusion.

pytest 1162 passed, ruff clean.

@github-actions github-actions Bot added medium-diff and removed small-diff Small pull request labels Oct 22, 2026

@Tim020 Tim020 left a comment

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Review round 2

Head SHA: 08c4cf1947d3d2e16ec81d274ce3fdb31e28fd08 (incremental diff since 753669b; it is an ancestor, so no force-push)

Verdict: Ready to merge.

Previous round follow-up: 1 verified fixed, 0 still open, 0 incomplete, 0 needing a human decision. The round 1 suggestion (independent observers, failures visible above DEBUG) is fixed in _observe_metrics and the thread is resolved.

SonarQube: Quality Gate passed (source: Sonar bot PR comment and check run; API not queried). 0 new issues, 0.0% duplication on new code; the coverage condition passes. Other CI checks pass; Build Server (linux/windows) was still pending when I looked.

New findings: none.

Strengths:

  • The author found and fixed a real related bug: tornado_prometheus classifies any status outside 200-499 as 5xx, so every WebSocket 101 upgrade was counted as a server error. Skipping 1xx for observe_request is a sound, minimal fix, with a regression test and docs.
  • The warn-once rate limit is simple and tested.
  • Minor nit, non-blocking: test_websocket_upgrade_not_counted_as_5xx relies on a fixed 0.2s sleep, which could be slightly flaky on slow CI, though the author reports it fails without the fix.

🤖 Generated with Claude Code

Co-Authored-By: Claude Sonnet 5.5 <noreply@anthropic.com>
@Tim020

Tim020 commented Oct 22, 2026

Copy link
Copy Markdown
Contributor Author

Round 2 nit addressed in 85b1c75.

Finding: test_websocket_upgrade_not_counted_as_5xx relies on a fixed 0.2s sleep, which could be flaky on slow CI.
Fixed: the test now wraps the app's log_request, sets an asyncio.Event once the 101 request has been fully handled (metrics observed), and waits on it with a bounded asyncio.wait_for(..., timeout=10) before asserting the 5xx total is unchanged. Re-verified: the test still fails when the 1xx skip is removed, passes with it. Full pytest 1189 passed, ruff check/format clean.

@sonarqubecloud

Copy link
Copy Markdown

@Tim020 Tim020 left a comment

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Review round 3

Head SHA: 85b1c758b19dd8c39dc8ad9c67f50113cbf6b3a4 (incremental diff since 08c4cf1; ancestor, no force-push)

Verdict: Ready to merge.

Previous round follow-up: no open threads (the round 1 thread was resolved earlier). The round 2 non-inline nit (fixed 0.2s sleep in test_websocket_upgrade_not_counted_as_5xx) is verified fixed: the test now wraps log_request, sets an asyncio.Event once the 101 request is handled, and waits on it with a 10s bound. Patching the instance attribute works because Tornado calls application.log_request(handler), and the original bound method is captured before the patch, so there is no recursion.

SonarQube: Quality Gate passed (source: Sonar bot PR comment; API not queried). 0 new issues.

New findings: none. The only change since round 2 is this test-only commit.

Strengths: the flaky-test fix replaces a time-based wait with an event-based one and keeps the regression property (the author reports the test still fails without the 1xx skip).

🤖 Generated with Claude Code

@Tim020
Tim020 enabled stacked auto-merge (squash) October 22, 2026 23:10
@Tim020
Tim020 merged commit 5c504cb into dev Oct 22, 2026
28 checks passed
@Tim020
Tim020 deleted the feature/obs-http-metrics-access-log branch October 22, 2026 23:13
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

claude Issues created by Claude documentation Improvements or additions to documentation medium-diff server Pull requests changing back end code

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant