refactor(web): one logging setup and one TTL cache for the web process (#621)

* refactor(web): use src.logging_config in the web process; routine requests to DEBUG

The web interface had its own logging setup (web_interface/logging_config.py)
that replaced the root handlers with a plain stdout formatter. The web
service's journal lines therefore never carried a syslog priority, so
`journalctl -p err -u ledmatrix-web` returned nothing while errors were
logged, and the line shape differed from the display's (the log viewer's
prefix stripping only matched the display format). It also ran after the
module-level managers were built, so their INFO lines at import (including
"Re-removed N uninstalled plugin(s)") were dropped.

app.py now calls src.logging_config.setup_logging() first thing, the same as
run.py: journald priorities under systemd, LEDMATRIX_DEBUG honoured,
LEDMATRIX_JSON_LOGGING still selects JSON.

Per-request logging moves to web_interface/request_logging.py. Every request
used to be logged at INFO, so the UI's polling filled the journal
("GET /api/v3/errors/summary - 200" every minute per tab). Now a successful
GET/HEAD/OPTIONS is DEBUG, a successful write is INFO, 4xx WARNING, 5xx
ERROR. Durations use perf_counter and print to 0.1ms.

The duplicate module is deleted; nothing else imported it.

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

* refactor(web): one thread-safe TTL cache for the web process

web_interface/cache.py becomes a small TTLCache class (lock-guarded,
monotonic clock) with the existing get_cached/set_cached/delete_cached/
invalidate_cache helpers kept on top of a shared instance, so the api_v3
callers are unchanged.

Bugs fixed:
- set_cached(ttl_seconds=...) ignored its TTL; only the reader's value
  counted and get_cached defaulted to 60s. An entry now expires after the TTL
  it was stored with; a reader's ttl_seconds can only shorten that. Both
  current callers pass the same value on both sides (fonts_catalog 300s,
  system_status 10s), so their observable TTLs are unchanged.
- get_cached deleted expired keys without a lock; two threads reading the
  same expired key could raise KeyError (reproduced), which the endpoints
  turned into a 500.

app.py's two hand-rolled systemctl caches (_ap_mode_cache, 30s, and
_ledmatrix_service_cache, 15s) now share one helper over a private
TTLCache, with the same TTLs. The AP-mode check used to retry on every
request after a failure (and log an ERROR each time); a failure now keeps the
last known answer for the TTL, as the display-service check already did. With
no systemctl at all (a dev machine) it answers False without forking.

Left alone as not TTL memoisation: the gzip cache (size-bounded, keyed by URL
and version), the settings search index (keyed by installed-plugin set), the
widget bundle (keyed by file fingerprint) and CacheManager (cross-process).

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

* docs(changelog): web logging and TTL cache

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

* fix(web): only ask systemctl about known units

Codacy flagged the systemctl argv built from a variable. The unit now has
to be one of two literals, and anything else raises.

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

* fix(web): response_time_ms reads the same clock request_logging stamps

request_logging now stamps request.start_time from perf_counter, but
success_response still subtracted it from time.time(), so metadata
reported ~1.8e12 ms. Found testing on ledpi.

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

---------

Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>

CHANGELOG.md

@@ -19,6 +19,14 @@ accepts both, but the store flags the old spelling as deprecated
 
 ## Unreleased
 
+- The web service (`ledmatrix-web`) logs through `src.logging_config` like the
+  display service, so `journalctl -p err -u ledmatrix-web` works. Successful
+  GET/HEAD/OPTIONS requests (the UI's polling) are logged at DEBUG instead of
+  INFO; 4xx at WARNING, 5xx at ERROR. `LEDMATRIX_DEBUG=true` shows them again.
+  `web_interface/logging_config.py` is removed. The web cache
+  (`web_interface/cache.py`) now honours the TTL a value was stored with and is
+  thread-safe.
+
 - `FontManager.get_font()` returns a BDF font at its native size when asked for
   a size the file doesn't contain (5x7.bdf at 8 or 10px, say). It used to
   return PIL's default font, a different typeface, so a plugin that relied on

src/web_interface/api_helpers.py

@@ -34,7 +34,8 @@ def success_response(
     # metadata block for responses that have neither.
     enriched = dict(metadata) if metadata is not None else {}
     if hasattr(request, 'start_time'):
-        enriched['response_time_ms'] = int((time.time() - request.start_time) * 1000)
+        # request_logging stamps start_time from perf_counter, not the wall clock.
+        enriched['response_time_ms'] = int((time.perf_counter() - request.start_time) * 1000)
 
     if metadata is not None or enriched:
         response_data['metadata'] = enriched

test/web_interface/test_cache.py

@@ -1,9 +1,14 @@
 """Tests for the web interface's in-memory cache helpers."""
+import sys
+import threading
 from typing import Iterator
 
 import pytest
 
-from web_interface.cache import delete_cached, get_cached, invalidate_cache, set_cached
+from web_interface import cache as cache_module
+from web_interface.cache import (
+    TTLCache, delete_cached, get_cached, invalidate_cache, set_cached,
+)
 
 
 @pytest.fixture(autouse=True)
@@ -44,3 +49,142 @@ def test_invalidate_cache_pattern() -> None:
     invalidate_cache('fonts')
     assert get_cached('fonts_catalog') is None
     assert get_cached('plugins_list') == 2
+
+
+# ---------------------------------------------------------------------------
+# Expiry. set_cached used to accept ttl_seconds and ignore it; only the TTL a
+# reader passed to get_cached counted, and get_cached defaulted to 60s.
+# ---------------------------------------------------------------------------
+
+class _Clock:
+    def __init__(self) -> None:
+        self.now = 1000.0
+
+    def __call__(self) -> float:
+        return self.now
+
+
+@pytest.fixture
+def clock() -> _Clock:
+    return _Clock()
+
+
+def test_entry_expires_after_its_ttl(clock: _Clock) -> None:
+    c = TTLCache(clock=clock)
+    c.set('k', 'v', ttl=10)
+    clock.now += 9.9
+    assert c.get('k') == 'v'
+    clock.now += 0.1
+    assert c.get('k') is None
+
+
+def test_default_ttl_applies_when_none_given(clock: _Clock) -> None:
+    c = TTLCache(default_ttl=5, clock=clock)
+    c.set('k', 'v')
+    clock.now += 4.9
+    assert c.get('k') == 'v'
+    clock.now += 0.1
+    assert c.get('k') is None
+
+
+def test_reader_max_age_can_only_shorten(clock: _Clock) -> None:
+    c = TTLCache(clock=clock)
+    c.set('k', 'v', ttl=10)
+    clock.now += 5
+    assert c.get('k', max_age=6) == 'v'
+    assert c.get('k', max_age=5) is None
+    clock.now += 5
+    assert c.get('k', max_age=60) is None, "a reader extended a 10s entry"
+
+
+def test_set_cached_ttl_is_honoured(monkeypatch: pytest.MonkeyPatch, clock: _Clock) -> None:
+    monkeypatch.setattr(cache_module, '_default_cache', TTLCache(clock=clock))
+    set_cached('short', 1, ttl_seconds=2)
+    set_cached('long', 2, ttl_seconds=300)
+    clock.now += 2
+    assert get_cached('short') is None, "set_cached ignored its ttl_seconds"
+    clock.now += 100  # past the old implicit 60s read default
+    assert get_cached('long') == 2
+
+
+def test_get_cached_ttl_still_bounds_the_read(monkeypatch: pytest.MonkeyPatch, clock: _Clock) -> None:
+    """The existing callers pass the TTL on both sides; that keeps working."""
+    monkeypatch.setattr(cache_module, '_default_cache', TTLCache(clock=clock))
+    set_cached('system_status', {'cpu': 1}, ttl_seconds=10)
+    clock.now += 9
+    assert get_cached('system_status', ttl_seconds=10) == {'cpu': 1}
+    clock.now += 1
+    assert get_cached('system_status', ttl_seconds=10) is None
+
+
+def test_peek_returns_the_last_value_after_expiry(clock: _Clock) -> None:
+    c = TTLCache(clock=clock)
+    assert c.peek('k', 'fallback') == 'fallback'
+    c.set('k', True, ttl=1)
+    clock.now += 5
+    assert c.get('k') is None
+    assert c.peek('k', False) is True
+
+
+def test_falsy_values_are_cached(clock: _Clock) -> None:
+    c = TTLCache(clock=clock)
+    c.set('k', False, ttl=10)
+    assert c.get('k', default='miss') is False
+
+
+def test_clear_pattern_on_instance() -> None:
+    c = TTLCache()
+    c.set('fonts_catalog', 1)
+    c.set('system_status', 2)
+    c.clear('fonts')
+    assert c.peek('fonts_catalog') is None
+    assert c.get('system_status') == 2
+    c.clear()
+    assert c.peek('system_status') is None
+
+
+def test_concurrent_expiry_reads_and_writes_do_not_raise() -> None:
+    """The old dicts deleted expired keys inside get; two threads reading the
+    same expired key (or one reading while another invalidated) could raise
+    KeyError, which the endpoints turned into a 500."""
+    c = TTLCache()
+    keys = [f'k{n}' for n in range(8)]
+    errors = []
+    stop = threading.Event()
+
+    def reader() -> None:
+        try:
+            while not stop.is_set():
+                for key in keys:
+                    c.get(key, max_age=0)  # always expired for this reader
+                    c.get(key)
+                    c.peek(key)
+                c.clear('k1')
+        except Exception as exc:  # pragma: no cover - the failure being tested
+            errors.append(exc)
+
+    def writer() -> None:
+        try:
+            for i in range(20000):
+                key = keys[i % len(keys)]
+                c.set(key, i, ttl=0 if i % 2 else 60)
+                if i % 7 == 0:
+                    c.delete(key)
+        except Exception as exc:  # pragma: no cover
+            errors.append(exc)
+
+    # Switch threads as often as possible so an unlocked check-then-act
+    # actually gets interleaved within the test's run time.
+    old_interval = sys.getswitchinterval()
+    sys.setswitchinterval(1e-6)
+    try:
+        readers = [threading.Thread(target=reader) for _ in range(4)]
+        for t in readers:
+            t.start()
+        writer()
+        stop.set()
+        for t in readers:
+            t.join()
+    finally:
+        sys.setswitchinterval(old_interval)
+    assert errors == []

test/web_interface/test_web_logging.py

@@ -0,0 +1,179 @@
+"""The web process logs the way the display process does.
+
+web_interface/app.py used to call its own setup (web_interface/logging_config.py)
+which replaced the root handlers with a plain stdout formatter. Under systemd
+every line then reached the journal as PRIORITY=6, so
+
+    journalctl -p err -u ledmatrix-web
+
+showed nothing while the web interface was logging errors. It also logged
+every request at INFO, including what the UI polls: the journal on a Pi showed
+``GET /api/v3/errors/summary - 200`` every minute per open tab.
+"""
+import logging
+import os
+import subprocess
+import sys
+import textwrap
+from pathlib import Path
+
+import pytest
+from flask import Flask
+
+from web_interface import request_logging
+
+PROJECT_ROOT = Path(__file__).resolve().parents[2]
+
+
+# ---------------------------------------------------------------------------
+# The real app, imported the way systemd runs it
+# ---------------------------------------------------------------------------
+
+_CHILD = textwrap.dedent("""
+    import logging
+    import web_interface.app as web_app
+
+    # Startup reconciliation may try to reinstall plugins; not this test's job.
+    web_app._reconciliation_started = True
+    client = web_app.app.test_client()
+    client.get('/api/v3/errors/summary')
+    client.get('/favicon.ico')
+    client.get('/api/v3/no-such-endpoint')
+    logging.getLogger('web_interface.probe').error('probe error line')
+    logging.getLogger('web_interface.probe').info('probe info line')
+""")
+
+
+@pytest.fixture(scope="module")
+def journal_output(tmp_path_factory):
+    """Run the child with stdout as a file systemd would call the journal.
+
+    systemd sets JOURNAL_STREAM to the dev:ino of the stream it captures;
+    src.logging_config only adds priorities when stdout really is that stream,
+    so hand the child a file and name that file's dev:ino.
+    """
+    out_path = tmp_path_factory.mktemp("journal") / "stdout.txt"
+    with open(out_path, "wb") as out:
+        st = os.fstat(out.fileno())
+        env = dict(os.environ)
+        env.update({
+            "JOURNAL_STREAM": f"{st.st_dev}:{st.st_ino}",
+            "PYTHONUTF8": "1",
+            "EMULATOR": "true",
+            "PYTHONPATH": str(PROJECT_ROOT),
+        })
+        env.pop("LEDMATRIX_DEBUG", None)
+        env.pop("LEDMATRIX_JSON_LOGGING", None)
+        proc = subprocess.run(
+            [sys.executable, "-c", _CHILD], cwd=str(PROJECT_ROOT), env=env,
+            stdout=out, stderr=subprocess.PIPE, timeout=180,
+        )
+    text = out_path.read_text(encoding="utf-8", errors="replace")
+    assert proc.returncode == 0, proc.stderr.decode(errors="replace")[-4000:]
+    return text.splitlines()
+
+
+def test_error_reaches_the_journal_as_err(journal_output):
+    lines = [l for l in journal_output if "probe error line" in l]
+    assert lines, "\n".join(journal_output[-40:])
+    assert lines[0].startswith("<3>"), lines[0]
+    # Same readable shape as the display service (and what the log viewer strips).
+    assert " - ERROR - web_interface.probe - probe error line" in lines[0]
+
+
+def test_info_reaches_the_journal_as_info(journal_output):
+    lines = [l for l in journal_output if "probe info line" in l]
+    assert lines and lines[0].startswith("<6>"), journal_output[-40:]
+
+
+def test_polling_gets_are_not_logged_at_info(journal_output):
+    for path in ("/api/v3/errors/summary", "/favicon.ico"):
+        assert not [l for l in journal_output if f"GET {path} " in l], (
+            f"a successful GET {path} was logged by default")
+
+
+def test_failed_request_is_still_logged(journal_output):
+    lines = [l for l in journal_output if "GET /api/v3/no-such-endpoint - 404" in l]
+    assert lines and lines[0].startswith("<4>"), journal_output[-40:]
+
+
+# ---------------------------------------------------------------------------
+# The level policy
+# ---------------------------------------------------------------------------
+
+@pytest.mark.parametrize("method,status,level", [
+    ("GET", 200, logging.DEBUG),
+    ("GET", 304, logging.DEBUG),
+    ("HEAD", 200, logging.DEBUG),
+    ("OPTIONS", 204, logging.DEBUG),
+    ("get", 200, logging.DEBUG),
+    ("POST", 200, logging.INFO),
+    ("PUT", 204, logging.INFO),
+    ("DELETE", 200, logging.INFO),
+    ("PATCH", 302, logging.INFO),
+    ("GET", 404, logging.WARNING),
+    ("POST", 400, logging.WARNING),
+    ("GET", 500, logging.ERROR),
+    ("POST", 503, logging.ERROR),
+])
+def test_request_log_level(method, status, level):
+    assert request_logging.request_log_level(method, status) == level
+
+
+@pytest.fixture
+def tiny_app():
+    app = Flask(__name__)
+    request_logging.init_app(app)
+
+    @app.route("/poll")
+    def poll():
+        return "ok"
+
+    @app.route("/save", methods=["POST"])
+    def save():
+        return "saved"
+
+    @app.route("/boom")
+    def boom():
+        return "no", 500
+
+    return app.test_client()
+
+
+def test_hooks_log_each_request_once_at_its_level(tiny_app, caplog):
+    caplog.set_level(logging.DEBUG, logger="web_interface.api")
+    tiny_app.get("/poll")
+    tiny_app.post("/save")
+    tiny_app.get("/boom")
+    tiny_app.get("/missing")
+    got = [(r.levelno, r.getMessage().split(" (")[0]) for r in caplog.records
+           if r.name == "web_interface.api"]
+    assert got == [
+        (logging.DEBUG, "GET /poll - 200"),
+        (logging.INFO, "POST /save - 200"),
+        (logging.ERROR, "GET /boom - 500"),
+        (logging.WARNING, "GET /missing - 404"),
+    ]
+
+
+def test_duration_is_rounded(tiny_app, caplog):
+    caplog.set_level(logging.DEBUG, logger="web_interface.api")
+    tiny_app.post("/save")
+    msg = caplog.records[-1].getMessage()
+    duration = msg.rsplit("(", 1)[1]
+    assert duration.endswith("ms)") and len(duration.split(".")[1]) == len("0ms)"), msg
+
+
+def test_success_response_timing_uses_the_same_clock():
+    # request_logging stamps request.start_time from perf_counter; a reader
+    # subtracting it from time.time() reported ~1.8e12 ms (found on a Pi).
+    from src.web_interface.api_helpers import success_response
+    app = Flask(__name__)
+    request_logging.init_app(app)
+
+    @app.route('/timed')
+    def timed():
+        return success_response(data={}, metadata={})
+
+    body = app.test_client().get('/timed').get_json()
+    assert 0 <= body['metadata']['response_time_ms'] < 10_000

web_interface/app.py

@@ -16,6 +16,17 @@ from datetime import datetime, timedelta
 # Add parent directory to path for imports
 sys.path.insert(0, str(Path(__file__).parent.parent))
 
+# Configure logging before anything below logs: the same setup as the display
+# service (run.py), so this process's journal lines carry their real syslog
+# priority too (`journalctl -p err -u ledmatrix-web`). LEDMATRIX_DEBUG=true
+# turns on DEBUG, which includes the routine per-request lines.
+from src.logging_config import setup_logging
+setup_logging(format_type=(
+    'json' if os.environ.get('LEDMATRIX_JSON_LOGGING', 'false').lower() == 'true'
+    else 'readable'))
+logging.getLogger('werkzeug').setLevel(logging.WARNING)  # request_logging covers requests
+logging.getLogger('urllib3').setLevel(logging.WARNING)
+
 from src.config_manager import ConfigManager
 from src.web_interface.error_handler import describe_exception
 from src.common.path_safety import (
@@ -284,34 +295,47 @@ try:
 except ImportError:
     pass
 
-# Cached AP mode check — avoids creating a WiFiManager per request
-_ap_mode_cache = {'value': False, 'timestamp': 0}
+# systemctl answers, memoised so they are not a subprocess fork per request
+# (AP mode) or per SSE tick (display service). A failed check keeps the last
+# known answer for the same TTL rather than retrying on every request.
+from web_interface.cache import TTLCache
+_service_status_cache = TTLCache()
 _AP_MODE_CACHE_TTL = 30  # seconds — AP mode is user-initiated; 30s is fine
-
-# Cached ledmatrix service status for SSE stats stream
-_ledmatrix_service_cache = {'active': False, 'timestamp': 0}
 _LEDMATRIX_SERVICE_CACHE_TTL = 15  # seconds
 
+# The only units _unit_is_active() may ask systemctl about: its argv is built
+# from these literals, never from request data.
+_CHECKABLE_UNITS = frozenset({'hostapd', 'ledmatrix'})
+
+def _unit_is_active(unit, ttl):
+    """`systemctl is-active <unit>`, cached for ``ttl`` seconds.
+
+    False where there is no systemctl (a dev machine); on a failed check, the
+    last known answer.
+    """
+    if unit not in _CHECKABLE_UNITS:
+        raise ValueError(f"not a checkable unit: {unit!r}")
+    active = _service_status_cache.get(unit)
+    if active is not None:
+        return active
+    active = _service_status_cache.peek(unit, False)
+    if _SYSTEMCTL:
+        try:
+            result = subprocess.run([_SYSTEMCTL, 'is-active', unit],  # nosec B603 - list argv, unit is from _CHECKABLE_UNITS  # nosemgrep
+                                    capture_output=True, text=True, timeout=2)
+            active = result.stdout.strip() == 'active'
+        except (subprocess.SubprocessError, OSError) as e:
+            logging.getLogger('web_interface').warning(
+                "systemctl is-active %s failed: %s", unit, e)
+    _service_status_cache.set(unit, active, ttl=ttl)
+    return active
+
 def is_ap_mode_active():
     """
     Check if access point mode is currently active (cached, 30s TTL).
     Uses a direct systemctl check instead of instantiating WiFiManager.
     """
-    now = time.time()
-    if (now - _ap_mode_cache['timestamp']) < _AP_MODE_CACHE_TTL:
-        return _ap_mode_cache['value']
-    try:
-        result = subprocess.run(
-            ['systemctl', 'is-active', 'hostapd'],
-            capture_output=True, text=True, timeout=2
-        )
-        active = result.stdout.strip() == 'active'
-        _ap_mode_cache['value'] = active
-        _ap_mode_cache['timestamp'] = now
-        return active
-    except (subprocess.SubprocessError, OSError) as e:
-        logging.getLogger('web_interface').error(f"AP mode check failed: {e}")
-        return _ap_mode_cache['value']
+    return _unit_is_active('hostapd', _AP_MODE_CACHE_TTL)
 
 # Captive portal detection endpoints
 # When AP mode is active, return responses that TRIGGER the captive portal popup.
@@ -346,41 +370,9 @@ def success_txt():
         return redirect(url_for('pages_v3.captive_setup'), code=302)
     return 'success', 200
 
-# Initialize logging
-try:
-    from web_interface.logging_config import setup_web_interface_logging, log_api_request
-    # Use JSON logging in production, readable logs in development
-    use_json_logging = os.environ.get('LEDMATRIX_JSON_LOGGING', 'false').lower() == 'true'
-    setup_web_interface_logging(level='INFO', use_json=use_json_logging)
-except ImportError:
-    # Logging config not available, use default
-    log_api_request = None
-
-# Request timing and logging middleware
-@app.before_request
-def before_request():
-    """Track request start time for logging."""
-    from flask import request
-    request.start_time = time.time()
-
-@app.after_request
-def after_request_logging(response):
-    """Log API requests after response."""
-    if log_api_request:
-        try:
-            from flask import request
-            duration_ms = (time.time() - getattr(request, 'start_time', time.time())) * 1000
-            ip_address = request.remote_addr if hasattr(request, 'remote_addr') else None
-            log_api_request(
-                method=request.method,
-                path=request.path,
-                status_code=response.status_code,
-                duration_ms=duration_ms,
-                ip_address=ip_address
-            )
-        except Exception:  # nosec B110 - request logging must never interrupt a live HTTP response
-            pass  # Don't break response if logging fails
-    return response
+# Request timing and logging (routine reads at DEBUG; see request_logging)
+from web_interface import request_logging
+request_logging.init_app(app)
 
 # Global error handlers
 @app.errorhandler(404)
@@ -693,17 +685,7 @@ def system_status_generator():
             cpu_temp = metrics['cpu_temp']
 
             # Check if display service is running (cached to avoid per-client subprocess forks)
-            now = time.time()
-            if (now - _ledmatrix_service_cache['timestamp']) >= _LEDMATRIX_SERVICE_CACHE_TTL:
-                if _SYSTEMCTL:
-                    try:
-                        result = subprocess.run([_SYSTEMCTL, 'is-active', 'ledmatrix'],
-                                                capture_output=True, text=True, timeout=2)
-                        _ledmatrix_service_cache['active'] = result.stdout.strip() == 'active'
-                    except (subprocess.SubprocessError, OSError) as e:
-                        app.logger.warning("systemctl status check failed: %s", e)
-                _ledmatrix_service_cache['timestamp'] = now
-            service_active = _ledmatrix_service_cache['active']
+            service_active = _unit_is_active('ledmatrix', _LEDMATRIX_SERVICE_CACHE_TTL)
             
             status = {
                 'timestamp': time.time(),

web_interface/cache.py

@@ -1,48 +1,107 @@
 """
-Simple in-memory cache for expensive operations.
-Separated from app.py to avoid circular import issues.
+In-process TTL cache for the web interface.
+
+The one place the web process memoises cheap-to-recompute values for a few
+seconds or minutes (the font catalog, the system-status snapshot, systemctl
+checks). It is per-process and in-memory only; data shared with the display
+service goes through ``src.cache_manager.CacheManager`` instead.
+
+Separated from app.py to avoid circular imports: blueprints import the
+module-level helpers below lazily, inside their request handlers.
 """
+import threading
 import time
-from typing import Any, Optional
+from typing import Any, Callable, Dict, Optional, Tuple
 
 
-# Simple in-memory cache for expensive operations
-_cache = {}
-_cache_timestamps = {}
+class TTLCache:
+    """A small thread-safe key/value store whose entries expire.
+
+    Each entry keeps the TTL it was stored with. A reader may additionally
+    pass ``max_age`` to ask for something fresher than that; an entry is only
+    returned while it is younger than both.
+
+    Expired entries are not dropped on read: :meth:`peek` still returns them,
+    which is what a "keep the last known answer if the refresh fails" caller
+    needs. They are replaced by the next :meth:`set` of the same key, so this
+    is meant for a small, fixed set of keys, not an unbounded key space.
+
+    Ages are measured with ``time.monotonic`` so a wall-clock jump (NTP sync
+    on a Pi that booted without an RTC) neither expires nor immortalises
+    everything at once.
+    """
+
+    def __init__(self, default_ttl: float = 60,
+                 clock: Callable[[], float] = time.monotonic):
+        self._default_ttl = default_ttl
+        self._clock = clock
+        self._lock = threading.Lock()
+        # key -> (value, stored_at, ttl)
+        self._entries: Dict[str, Tuple[Any, float, float]] = {}
+
+    def get(self, key: str, default: Any = None,
+            max_age: Optional[float] = None) -> Any:
+        """The value for ``key`` if it is still fresh, else ``default``."""
+        with self._lock:
+            entry = self._entries.get(key)
+        if entry is None:
+            return default
+        value, stored_at, ttl = entry
+        age = self._clock() - stored_at
+        if age >= ttl or (max_age is not None and age >= max_age):
+            return default
+        return value
+
+    def peek(self, key: str, default: Any = None) -> Any:
+        """The last value stored for ``key``, fresh or not."""
+        with self._lock:
+            entry = self._entries.get(key)
+        return default if entry is None else entry[0]
+
+    def set(self, key: str, value: Any, ttl: Optional[float] = None) -> None:
+        """Store ``value`` for ``ttl`` seconds (the cache default if None)."""
+        ttl = self._default_ttl if ttl is None else ttl
+        with self._lock:
+            self._entries[key] = (value, self._clock(), ttl)
+
+    def delete(self, key: str) -> None:
+        """Remove ``key`` if present."""
+        with self._lock:
+            self._entries.pop(key, None)
+
+    def clear(self, pattern: Optional[str] = None) -> None:
+        """Remove every entry, or only those whose key contains ``pattern``."""
+        with self._lock:
+            if pattern is None:
+                self._entries.clear()
+            else:
+                for key in [k for k in self._entries if pattern in k]:
+                    del self._entries[key]
 
 
-def get_cached(key: str, ttl_seconds: int = 60) -> Optional[Any]:
-    """Get value from cache if not expired."""
-    if key in _cache:
-        if time.time() - _cache_timestamps[key] < ttl_seconds:
-            return _cache[key]
-        else:
-            # Expired, remove
-            del _cache[key]
-            del _cache_timestamps[key]
-    return None
+# The shared cache behind the functional helpers the blueprints use.
+_default_cache = TTLCache(default_ttl=60)
 
 
-def set_cached(key: str, value: Any, ttl_seconds: int = 60) -> None:
-    """Set value in cache with TTL."""
-    _cache[key] = value
-    _cache_timestamps[key] = time.time()
+def get_cached(key: str, ttl_seconds: Optional[float] = None) -> Optional[Any]:
+    """Get a value from the cache if it has not expired.
+
+    The entry expires after the TTL it was stored with; ``ttl_seconds``, when
+    given, is an extra upper bound on its age for this read.
+    """
+    return _default_cache.get(key, max_age=ttl_seconds)
+
+
+def set_cached(key: str, value: Any, ttl_seconds: float = 60) -> None:
+    """Store a value in the cache for ``ttl_seconds``."""
+    _default_cache.set(key, value, ttl=ttl_seconds)
 
 
 def delete_cached(key: str) -> None:
     """Remove a single key from the cache if present."""
-    _cache.pop(key, None)
-    _cache_timestamps.pop(key, None)
+    _default_cache.delete(key)
 
 
 def invalidate_cache(pattern: Optional[str] = None) -> None:
     """Invalidate cache entries matching pattern, or all if pattern is None."""
-    if pattern is None:
-        _cache.clear()
-        _cache_timestamps.clear()
-    else:
-        keys_to_remove = [k for k in _cache.keys() if pattern in k]
-        for key in keys_to_remove:
-            del _cache[key]
-            del _cache_timestamps[key]
-
+    _default_cache.clear(pattern)

web_interface/logging_config.py

@@ -1,110 +0,0 @@
-"""
-Structured logging configuration for the web interface.
-Provides JSON-formatted logs for production and readable logs for development.
-"""
-import logging
-import json
-import sys
-from datetime import datetime
-from typing import Optional
-
-
-class JSONFormatter(logging.Formatter):
-    """Formatter that outputs logs as JSON for structured logging."""
-    
-    def format(self, record: logging.LogRecord) -> str:
-        """Format log record as JSON."""
-        log_data = {
-            'timestamp': datetime.utcnow().isoformat(),
-            'level': record.levelname,
-            'logger': record.name,
-            'message': record.getMessage(),
-            'module': record.module,
-            'function': record.funcName,
-            'line': record.lineno,
-        }
-        
-        # Add exception info if present
-        if record.exc_info:
-            log_data['exception'] = self.formatException(record.exc_info)
-        
-        # Add extra fields if present
-        if hasattr(record, 'request_id'):
-            log_data['request_id'] = record.request_id
-        if hasattr(record, 'user_id'):
-            log_data['user_id'] = record.user_id
-        if hasattr(record, 'ip_address'):
-            log_data['ip_address'] = record.ip_address
-        if hasattr(record, 'duration_ms'):
-            log_data['duration_ms'] = record.duration_ms
-        
-        return json.dumps(log_data)
-
-
-def setup_web_interface_logging(level: str = 'INFO', use_json: bool = False):
-    """
-    Set up logging for the web interface.
-    
-    Args:
-        level: Log level (DEBUG, INFO, WARNING, ERROR)
-        use_json: If True, use JSON formatting (for production)
-    """
-    # Get root logger
-    logger = logging.getLogger()
-    logger.setLevel(getattr(logging, level.upper()))
-    
-    # Remove existing handlers
-    logger.handlers.clear()
-    
-    # Create console handler
-    console_handler = logging.StreamHandler(sys.stdout)
-    console_handler.setLevel(getattr(logging, level.upper()))
-    
-    # Set formatter
-    if use_json:
-        formatter = JSONFormatter()
-    else:
-        formatter = logging.Formatter(
-            '%(asctime)s - %(name)s - %(levelname)s - %(message)s',
-            datefmt='%Y-%m-%d %H:%M:%S'
-        )
-    
-    console_handler.setFormatter(formatter)
-    logger.addHandler(console_handler)
-    
-    # Set levels for specific loggers
-    logging.getLogger('werkzeug').setLevel(logging.WARNING)  # Reduce Flask noise
-    logging.getLogger('urllib3').setLevel(logging.WARNING)  # Reduce HTTP noise
-
-
-def log_api_request(method: str, path: str, status_code: int, duration_ms: float,
-                   ip_address: Optional[str] = None, **kwargs):
-    """
-    Log an API request with structured data.
-    
-    Args:
-        method: HTTP method
-        path: Request path
-        status_code: HTTP status code
-        duration_ms: Request duration in milliseconds
-        ip_address: Client IP address
-        **kwargs: Additional context
-    """
-    logger = logging.getLogger('web_interface.api')
-    
-    extra = {
-        'method': method,
-        'path': path,
-        'status_code': status_code,
-        'duration_ms': round(duration_ms, 2),
-        'ip_address': ip_address,
-        **kwargs
-    }
-    
-    # Log at appropriate level based on status code
-    if status_code >= 500:
-        logger.error(f"{method} {path} - {status_code} ({duration_ms}ms)", extra=extra)
-    elif status_code >= 400:
-        logger.warning(f"{method} {path} - {status_code} ({duration_ms}ms)", extra=extra)
-    else:
-        logger.info(f"{method} {path} - {status_code} ({duration_ms}ms)", extra=extra)

web_interface/request_logging.py

@@ -0,0 +1,62 @@
+"""
+Per-request logging for the web interface.
+
+Logging itself is configured by ``src.logging_config.setup_logging`` (the same
+formatter and journald priorities as the display service); this module only
+decides what one HTTP request is worth logging, and at which level.
+
+The UI polls: the error summary, system status, display preview and log
+streams are fetched every few seconds by every open tab. Logging each of those
+at INFO buried everything else in the journal (``GET /api/v3/errors/summary -
+200`` once a minute per tab, forever). So a request that only read something
+and succeeded is DEBUG; one that changed something, or failed, is logged at a
+level that shows up by default.
+"""
+import logging
+import time
+
+from flask import Flask, request
+
+logger = logging.getLogger('web_interface.api')
+
+#: Methods that do not change server state. A successful one is routine.
+_READ_ONLY_METHODS = frozenset({'GET', 'HEAD', 'OPTIONS'})
+
+
+def request_log_level(method: str, status_code: int) -> int:
+    """The level a finished request is logged at."""
+    if status_code >= 500:
+        return logging.ERROR
+    if status_code >= 400:
+        return logging.WARNING
+    if method.upper() in _READ_ONLY_METHODS:
+        return logging.DEBUG
+    return logging.INFO
+
+
+def log_request(method: str, path: str, status_code: int,
+                duration_ms: float) -> None:
+    """Log one finished request."""
+    level = request_log_level(method, status_code)
+    if logger.isEnabledFor(level):
+        logger.log(level, "%s %s - %d (%.1fms)",
+                   method, path, status_code, duration_ms)
+
+
+def init_app(app: Flask) -> None:
+    """Time every request and log it when its response is ready."""
+
+    @app.before_request
+    def _start_request_timer():
+        request.start_time = time.perf_counter()
+
+    @app.after_request
+    def _log_finished_request(response):
+        try:
+            started = getattr(request, 'start_time', None)
+            duration_ms = 0.0 if started is None else (time.perf_counter() - started) * 1000
+            log_request(request.method, request.path, response.status_code,
+                        duration_ms)
+        except Exception:  # nosec B110 - request logging must never interrupt a live HTTP response
+            pass
+        return response