From 08b90e2f9943e94b6a8b27717a6fadc30c642957 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 20 Jun 2026 20:06:30 +0000 Subject: [PATCH] fix: silence werkzeug access logger so Flask 200s don't false-red (#181) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The Server Logs panel (#178) logged every Flask request twice: the structured _access_log_finish entry, plus werkzeug's own request line, which the stdout/stderr tee captures from stderr and tags `error` (red). Healthy 200s rendered red and double-logged — and since docker-compose.prod.yml still runs the Flask dev server, this reached prod, not just dev. Silence werkzeug's built-in access logger at import in both app.py (setLevel ERROR, which keeps genuine werkzeug error/exception logging), so the structured hook is the sole, level-tagged access entry. Update the stale _access_log_finish comments and the byte-identical log_ring.py docstrings, add a per-service test asserting the logger is silenced, and record the rationale in ADR-023. Co-Authored-By: Claude Opus 4.8 (1M context) Claude-Session: https://claude.ai/code/session_01UUXqNmzoqszKVAtaam1A3U --- .../adr-023-persistent-structured-server-logs.md | 7 +++++++ duckdb-service/app.py | 13 +++++++++++-- duckdb-service/services/log_ring.py | 6 ++++-- duckdb-service/tests/test_logs.py | 10 ++++++++++ image-service/app.py | 13 +++++++++++-- image-service/services/log_ring.py | 6 ++++-- image-service/tests/test_logs.py | 16 ++++++++++++++++ 7 files changed, 63 insertions(+), 8 deletions(-) diff --git a/docs/09-architecture-decisions/adr-023-persistent-structured-server-logs.md b/docs/09-architecture-decisions/adr-023-persistent-structured-server-logs.md index fe10c05..e982afa 100644 --- a/docs/09-architecture-decisions/adr-023-persistent-structured-server-logs.md +++ b/docs/09-architecture-decisions/adr-023-persistent-structured-server-logs.md @@ -78,6 +78,13 @@ own ring's emitter and pipes the Flask services' internal `/logs/stream`; the RE - Retention is bounded on both axes, so the store can't grow without limit. - `LOG_DIR`-gating keeps unit tests and any "in-memory is fine" deployment on the old path with zero file I/O. +- **One access entry per Flask request, at the right level (#181).** Each `app.py` silences + werkzeug's built-in access logger (`logging.getLogger("werkzeug").setLevel(logging.ERROR)`) + at import. Otherwise werkzeug's own request line is tee-captured from stderr and tagged + `error`, so every healthy `200` double-logged and rendered red in the panel — this reaches + prod too, where `docker-compose.prod.yml` still runs the Flask dev server. `ERROR` keeps + werkzeug's genuine error/exception logging; the `_access_log_finish` hook remains the sole, + level-tagged access entry. ### Negative diff --git a/duckdb-service/app.py b/duckdb-service/app.py index 26f8c0b..cd58b11 100644 --- a/duckdb-service/app.py +++ b/duckdb-service/app.py @@ -1,3 +1,4 @@ +import logging import os import time @@ -30,6 +31,14 @@ # persisted too. See ADR-023. init_log_persistence() +# Silence werkzeug's built-in access logger (#181). _access_log_finish below +# already emits one structured access entry per request; werkzeug's own request +# line would otherwise be tee-captured from stderr and mis-tagged `error` (red), +# double-logging every 200. ERROR keeps werkzeug's genuine error/exception +# logging. Must run before the first request — werkzeug only forces INFO when +# the level is still NOTSET. +logging.getLogger("werkzeug").setLevel(logging.ERROR) + # Structured boot banner through the logger (#178) — the analogue to the # backend's server.ts banner. Runs at import under flask run / gunicorn and # under `python app.py`, so the structured ingestion path has a real @@ -57,8 +66,8 @@ def _access_log_finish(resp): # One structured access entry per request (#178): "method path status ms". # path ONLY — never query string, headers, or body — so the X-Admin-Key # header and any ?token=/?key= value can't reach the admin-readable / - # disk-persisted ring. werkzeug's own request line is still tee-captured; - # this is the canonical, level-tagged entry. + # disk-persisted ring. werkzeug's own access request line is silenced at the + # logger (#181), so this is the only access entry — no duplicate, no false-red. start = g.pop("_access_start", None) if start is not None: ms = (time.perf_counter() - start) * 1000.0 diff --git a/duckdb-service/services/log_ring.py b/duckdb-service/services/log_ring.py index 4f47498..d6e7aa1 100644 --- a/duckdb-service/services/log_ring.py +++ b/duckdb-service/services/log_ring.py @@ -6,8 +6,10 @@ 1. A stdout/stderr *tee* installed at startup: every write NOT produced by the structured logger is wrapped as an entry AND passed through to the real stream, so ``docker logs`` / PM2 still see everything unchanged. Captures - ``print(...)`` and werkzeug's request lines. stdout lines become - ``info``, stderr lines become ``error``. + ``print(...)`` and werkzeug's error/exception output; werkzeug's own + *access* request lines are silenced at the logger (#181) so they don't + double-log the structured access entry. stdout lines become ``info``, + stderr lines become ``error``. 2. The structured logger (``log_event``) appends an entry directly, then writes its formatted human line to the *saved real* stream (bypassing the tee, so its own output is not re-captured as a duplicate entry). diff --git a/duckdb-service/tests/test_logs.py b/duckdb-service/tests/test_logs.py index 2d50a88..2a8c778 100644 --- a/duckdb-service/tests/test_logs.py +++ b/duckdb-service/tests/test_logs.py @@ -158,6 +158,16 @@ def test_access_log_redacts_query_and_credentials(client): ) +def test_werkzeug_access_logger_silenced(client): + # #181: importing app silences werkzeug's built-in access logger so its + # request line can't be tee-captured from stderr as a duplicate (false-red) + # entry. INFO access lines are dropped; ERROR-level werkzeug logs survive. + import logging + + assert not logging.getLogger("werkzeug").isEnabledFor(logging.INFO) + assert logging.getLogger("werkzeug").isEnabledFor(logging.ERROR) + + def test_persistence_writes_jsonl(tmp_path): log_ring._reset_for_test() log_ring.init_persistence(str(tmp_path)) diff --git a/image-service/app.py b/image-service/app.py index 16e6e84..6875fcf 100644 --- a/image-service/app.py +++ b/image-service/app.py @@ -1,6 +1,7 @@ import glob import hmac import json +import logging import os import random import time @@ -38,6 +39,14 @@ # persisted too. See ADR-023. init_log_persistence() +# Silence werkzeug's built-in access logger (#181). _access_log_finish below +# already emits one structured access entry per request; werkzeug's own request +# line would otherwise be tee-captured from stderr and mis-tagged `error` (red), +# double-logging every 200. ERROR keeps werkzeug's genuine error/exception +# logging. Must run before the first request — werkzeug only forces INFO when +# the level is still NOTSET. +logging.getLogger("werkzeug").setLevel(logging.ERROR) + # Structured boot banner through the logger (#178) — the analogue to the # backend's server.ts banner. Runs at import under flask run / gunicorn and # under `python app.py`, so the structured ingestion path has a real @@ -65,8 +74,8 @@ def _access_log_finish(resp): # One structured access entry per request (#178): "method path status ms". # path ONLY — never query string, headers, or body — so the X-Admin-Key # header and any ?token=/?key= value can't reach the admin-readable / - # disk-persisted ring. werkzeug's own request line is still tee-captured; - # this is the canonical, level-tagged entry. + # disk-persisted ring. werkzeug's own access request line is silenced at the + # logger (#181), so this is the only access entry — no duplicate, no false-red. start = g.pop("_access_start", None) if start is not None: ms = (time.perf_counter() - start) * 1000.0 diff --git a/image-service/services/log_ring.py b/image-service/services/log_ring.py index 4f47498..d6e7aa1 100644 --- a/image-service/services/log_ring.py +++ b/image-service/services/log_ring.py @@ -6,8 +6,10 @@ 1. A stdout/stderr *tee* installed at startup: every write NOT produced by the structured logger is wrapped as an entry AND passed through to the real stream, so ``docker logs`` / PM2 still see everything unchanged. Captures - ``print(...)`` and werkzeug's request lines. stdout lines become - ``info``, stderr lines become ``error``. + ``print(...)`` and werkzeug's error/exception output; werkzeug's own + *access* request lines are silenced at the logger (#181) so they don't + double-log the structured access entry. stdout lines become ``info``, + stderr lines become ``error``. 2. The structured logger (``log_event``) appends an entry directly, then writes its formatted human line to the *saved real* stream (bypassing the tee, so its own output is not re-captured as a duplicate entry). diff --git a/image-service/tests/test_logs.py b/image-service/tests/test_logs.py index 60b6a7f..08b1e0c 100644 --- a/image-service/tests/test_logs.py +++ b/image-service/tests/test_logs.py @@ -155,6 +155,22 @@ def test_access_log_redacts_query_and_credentials(client): ) +# The two services' log_ring.py byte-identity is guarded by +# test_log_ring_byte_identical_across_services, which lives only in +# duckdb-service/tests/test_logs.py (it cross-reads both files, so one copy +# suffices). No mirror needed here. + + +def test_werkzeug_access_logger_silenced(client): + # #181: importing app silences werkzeug's built-in access logger so its + # request line can't be tee-captured from stderr as a duplicate (false-red) + # entry. INFO access lines are dropped; ERROR-level werkzeug logs survive. + import logging + + assert not logging.getLogger("werkzeug").isEnabledFor(logging.INFO) + assert logging.getLogger("werkzeug").isEnabledFor(logging.ERROR) + + def test_persistence_writes_jsonl(tmp_path): log_ring._reset_for_test() log_ring.init_persistence(str(tmp_path))