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