diff --git a/CHANGELOG.md b/CHANGELOG.md index 995f3e88..1eb67063 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/src/web_interface/api_helpers.py b/src/web_interface/api_helpers.py index be2b0771..fe6471e2 100644 --- a/src/web_interface/api_helpers.py +++ b/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 diff --git a/test/web_interface/test_cache.py b/test/web_interface/test_cache.py index 46f6b0ee..90d260bb 100644 --- a/test/web_interface/test_cache.py +++ b/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 == [] diff --git a/test/web_interface/test_web_logging.py b/test/web_interface/test_web_logging.py new file mode 100644 index 00000000..de980898 --- /dev/null +++ b/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 diff --git a/web_interface/app.py b/web_interface/app.py index 8453bc13..9c75a62c 100644 --- a/web_interface/app.py +++ b/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 `, 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(), diff --git a/web_interface/cache.py b/web_interface/cache.py index f7aad3ea..977600a2 100644 --- a/web_interface/cache.py +++ b/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) diff --git a/web_interface/logging_config.py b/web_interface/logging_config.py deleted file mode 100644 index 07c2f267..00000000 --- a/web_interface/logging_config.py +++ /dev/null @@ -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) diff --git a/web_interface/request_logging.py b/web_interface/request_logging.py new file mode 100644 index 00000000..7f9d9294 --- /dev/null +++ b/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