fix: silence werkzeug access logger so Flask 200s don't false-red (#181)

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
 

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

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).

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))

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

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).

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))