feat(logging): structured JSON logs, uvicorn access log included

Hold Slayer's logs are shipped to Loki by the host's Alloy agent, which
reads container stdout. Text lines arrive there as an opaque blob:
filtering on a status code meant regex over a formatted string. This adds
LOG_FORMAT=json (default "text", so local dev stays readable) rendering
one JSON object per line.

Two parts were less obvious than a format= argument would suggest, and
both are why this is a module rather than a basicConfig tweak:

Uvicorn attaches its own handlers to `uvicorn` and `uvicorn.access` with
propagate=False, so configuring only the root logger would have left the
access log — the highest-volume, most useful stream — as colourised text
next to our JSON. configure_logging clears those handlers and re-enables
propagation, and is called both at import (for startup config checks) and
in lifespan (uvicorn configures itself after importing the app). The
__main__ path passes log_config=None so uvicorn never applies its own.

The access record's payload lives in record.args as a 5-tuple, not in the
message. Formatting it would throw the structure away and force Loki to
parse it back out, so the tuple is unpacked into real fields and
status_code is emitted as a number for range filtering.

Also drops uvicorn's `color_message` extra, an ANSI-coloured duplicate of
the message that generic extra-promotion would otherwise copy into every
startup line — the same unreadable-in-Grafana problem recently fixed for
the lab's Asterisk logs.

Verified against a real uvicorn server: 39/39 lines valid JSON, zero ANSI
escapes, no duplicates, access lines structured with correct status codes;
text mode unchanged. Thread name is included off the main thread, since
"which execution context logged this" is the first question when debugging
across the asyncio/Sippy/PJSUA2 boundary. SecretStr extras stay masked.

README Phase 4 item ticked; LOG_FORMAT and the previously-undocumented
LOG_LEVEL added to the config table and .env.example.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

.env.example

@@ -100,6 +100,9 @@ HOST=0.0.0.0
 PORT=8000
 DEBUG=false
 LOG_LEVEL=info
+# Log rendering: "text" (human-readable) or "json" (one object per line, for
+# Loki/Alloy). The Docker image sets json; text is the default for local dev.
+LOG_FORMAT=text
 
 # --- Safety ---
 # Max simultaneous calls the gateway will place (REST + MCP)

Dockerfile

@@ -45,6 +45,11 @@ RUN pip install --no-cache-dir -e . \
 
 EXPOSE 21081
 
+# Structured logs by default in the container: the host's Alloy agent reads
+# stdout and ships it to Loki, where text lines arrive as an unqueryable blob.
+# Overridable (LOG_FORMAT=text) for interactive `docker run` debugging.
+ENV LOG_FORMAT=json
+
 # Migrations run in the app's own init_db() on boot (db/database.py), so no
 # separate `alembic upgrade` here. Bind host/port from the same env vars
 # pydantic-settings reads (HOST/PORT) so configured values and the actual bind

README.md

@@ -373,6 +373,8 @@ All configuration is via environment variables (see `.env.example`):
 | `OWNER_NAME` | Casdoor username of the single operator (owner) | — (required if SSO on) |
 | `PUBLIC_BASE_URL` | Public base URL for OAuth discovery (else derived from headers) | — |
 | `MAX_CONCURRENT_CALLS` | Cap on simultaneous outbound calls | `4` |
+| `LOG_LEVEL` | Root log level (`debug`/`info`/`warning`/`error`) | `info` |
+| `LOG_FORMAT` | `text` (human-readable) or `json` (structured, for Loki) | `text` |
 | `SIP_TRUNK_HOST` | Your SIP provider hostname | — |
 | `SIP_TRUNK_USERNAME` | SIP auth username | — |
 | `SIP_TRUNK_PASSWORD` | SIP auth password | — |
@@ -449,7 +451,7 @@ Full documentation is in [`/docs`](docs/README.md):
 - [x] API authentication — Casdoor SSO (browser JWT) + owner-minted PATs, owner-only across REST/WS/MCP
 - [x] Emergency-number guard + concurrent-call cap on outbound calls
 - [ ] Rate limiting on API endpoints
-- [ ] Structured JSON logging
+- [x] Structured JSON logging (`LOG_FORMAT=json`, uvicorn access log included)
 - [x] Honest /health — engine mode, DB ping, trunk registration, STT/TTS availability
 - [ ] Graceful degradation (classifier works without STT, etc.)
 - [x] Docker Compose (Hold Slayer + PostgreSQL)

config.py

@@ -145,6 +145,11 @@ class Settings(BaseSettings):
     debug: bool = False
     log_level: str = "info"
 
+    # Log rendering: "text" (human-readable, for a terminal) or "json" (one
+    # object per line, for Loki). Text is the default so local dev is readable;
+    # the container sets LOG_FORMAT=json. See core/logging_config.py.
+    log_format: str = "text"
+
     # Auth — Casdoor SSO for the browser + owner-minted PATs for MCP/CLI,
     # gated to a single owner. `owner_name` is the Casdoor username that owns
     # this gateway (everyone else gets 403). `public_base_url` seeds the OAuth

core/logging_config.py

@@ -0,0 +1,175 @@
+"""
+Logging configuration — human-readable text or structured JSON.
+
+Hold Slayer's logs are shipped to Loki by the host's Alloy agent, which reads
+the container's stdout. Text logs arrive there as an opaque blob: filtering on
+a status code or a call ID means regex over a formatted string. JSON lines
+arrive as queryable fields.
+
+Two things about this are less obvious than they look, and both are the reason
+this module exists instead of a `format=` argument on `basicConfig`:
+
+1. **Uvicorn brings its own handlers.** `uvicorn.config.LOGGING_CONFIG` attaches
+   a `StreamHandler` to `uvicorn` and `uvicorn.access` with `propagate: False`,
+   so those records never reach the root logger's formatter. Configuring only
+   the root would leave the access log — the highest-volume, most useful stream
+   — as plain colourised text next to our JSON. `configure_logging` reaches into
+   those two loggers explicitly.
+
+2. **The access record's payload is in `record.args`, not the message.** Uvicorn
+   logs access lines as a 5-tuple `(client_addr, method, full_path, http_version,
+   status_code)` and lets its `AccessFormatter` interpolate them. Formatting the
+   message would throw that structure away and force Loki to parse it back out,
+   so `JSONFormatter` unpacks the tuple into real fields.
+
+Text mode stays the default: it is what a developer wants on a terminal, and a
+JSON-only logger makes local debugging worse. Production opts in via
+`LOG_FORMAT=json`.
+"""
+
+import datetime as _dt
+import json
+import logging
+import sys
+from typing import Any
+
+# LogRecord attributes that are either already represented in our output or are
+# formatting machinery. Anything on a record that is *not* here is treated as a
+# caller-supplied `extra=` field and promoted into the JSON object.
+_RESERVED = frozenset(
+    {
+        "args",
+        "asctime",
+        # Uvicorn passes an ANSI-colourised duplicate of the message as
+        # `extra={"color_message": ...}` for its own formatter to prefer. Left
+        # unfiltered, generic extra-promotion copies escape codes into every
+        # startup line — the same unreadable-in-Grafana problem as the lab's
+        # Asterisk logs.
+        "color_message",
+        "created",
+        "exc_info",
+        "exc_text",
+        "filename",
+        "funcName",
+        "levelname",
+        "levelno",
+        "lineno",
+        "module",
+        "msecs",
+        "message",
+        "msg",
+        "name",
+        "pathname",
+        "process",
+        "processName",
+        "relativeCreated",
+        "stack_info",
+        "taskName",
+        "thread",
+        "threadName",
+    }
+)
+
+# Uvicorn's own access-log tuple, in order.
+_ACCESS_FIELDS = ("client_addr", "method", "path", "http_version", "status_code")
+
+TEXT_FORMAT = "%(asctime)s | %(levelname)-7s | %(name)s | %(message)s"
+
+
+class JSONFormatter(logging.Formatter):
+    """Render a LogRecord as a single-line JSON object."""
+
+    def format(self, record: logging.LogRecord) -> str:
+        payload: dict[str, Any] = {
+            # RFC 3339 in UTC. `logging`'s default asctime is local-time and
+            # date-less, which makes correlating with Loki's own timestamps
+            # unnecessarily hard.
+            "ts": _dt.datetime.fromtimestamp(record.created, tz=_dt.UTC).isoformat(
+                timespec="milliseconds"
+            ),
+            "level": record.levelname,
+            "logger": record.name,
+        }
+
+        if record.name == "uvicorn.access" and isinstance(record.args, tuple):
+            payload.update(_access_fields(record))
+        else:
+            payload["msg"] = record.getMessage()
+
+        # Thread name matters here in a way it doesn't in a single-context app:
+        # this process runs the asyncio loop, the Sippy ED thread, and PJSUA2
+        # worker threads, and "which context logged this" is usually the first
+        # question when debugging a call.
+        if record.threadName and record.threadName != "MainThread":
+            payload["thread"] = record.threadName
+
+        if record.exc_info:
+            payload["exc"] = self.formatException(record.exc_info)
+        if record.stack_info:
+            payload["stack"] = self.formatStack(record.stack_info)
+
+        for key, value in record.__dict__.items():
+            if key not in _RESERVED and not key.startswith("_"):
+                payload[key] = _safe(value)
+
+        return json.dumps(payload, default=str, separators=(",", ":"))
+
+
+def _access_fields(record: logging.LogRecord) -> dict[str, Any]:
+    """Unpack uvicorn's access-log arg tuple into named fields.
+
+    Falls back to the interpolated message if uvicorn ever changes the tuple's
+    shape — a log line with a slightly wrong shape beats an exception inside the
+    logging path taking out the request.
+    """
+    args = record.args
+    if not isinstance(args, tuple) or len(args) != len(_ACCESS_FIELDS):
+        return {"msg": record.getMessage()}
+
+    fields: dict[str, Any] = dict(zip(_ACCESS_FIELDS, args))
+    try:
+        fields["status_code"] = int(fields["status_code"])
+    except (TypeError, ValueError):
+        pass
+    return fields
+
+
+def _safe(value: Any) -> Any:
+    """Keep JSON-native types; stringify everything else."""
+    if isinstance(value, (str, int, float, bool, type(None))):
+        return value
+    return str(value)
+
+
+def configure_logging(log_format: str, log_level: str) -> None:
+    """Install the root and uvicorn log handlers.
+
+    Idempotent: existing root handlers are removed first, so calling this after
+    uvicorn has configured itself replaces its formatting rather than adding a
+    second stream (which is how you get every line twice).
+    """
+    level = getattr(logging, log_level.upper(), logging.INFO)
+    use_json = log_format.lower() == "json"
+
+    formatter: logging.Formatter = (
+        JSONFormatter() if use_json else logging.Formatter(TEXT_FORMAT, datefmt="%H:%M:%S")
+    )
+
+    handler = logging.StreamHandler(stream=sys.stdout)
+    handler.setFormatter(formatter)
+
+    root = logging.getLogger()
+    for existing in root.handlers[:]:
+        root.removeHandler(existing)
+    root.addHandler(handler)
+    root.setLevel(level)
+
+    # Uvicorn sets `propagate = False` on these and attaches its own colourised
+    # handlers, so they must be redirected explicitly or they bypass everything
+    # above. Clearing the handlers and re-enabling propagation routes them
+    # through the root handler like any other logger.
+    for name in ("uvicorn", "uvicorn.error", "uvicorn.access"):
+        uv = logging.getLogger(name)
+        uv.handlers.clear()
+        uv.propagate = True
+        uv.setLevel(level)

main.py

@@ -26,6 +26,7 @@ from api import call_flows, call_history, calls, devices, routing, tokens, webso
 from auth import get_current_owner, init_jwks_client, is_owner, resolve_from_header_or_query
 from config import Settings, get_settings
 from core.gateway import AIPSTNGateway, build_sip_engine
+from core.logging_config import configure_logging
 from db.database import close_db, init_db, session_scope
 from mcp_server.server import create_mcp_server
 from models.call import CallMode
@@ -39,13 +40,12 @@ from services.routing import RoutingService
 from services.transcription import TranscriptionService
 from services.tts import TTSService
 
-# Configure logging
+# Configure logging at import so anything logged during module import and
-logging.basicConfig(
+# startup config checks is formatted. Uvicorn installs its own handlers *after*
-    level=logging.INFO,
+# importing this module, so `lifespan` calls `configure_logging` again to take
-    format="%(asctime)s | %(levelname)-7s | %(name)s | %(message)s",
+# them over — see core/logging_config.py.
-    datefmt="%H:%M:%S",
+_startup_settings = get_settings()
-    stream=sys.stdout,
+configure_logging(_startup_settings.log_format, _startup_settings.log_level)
-)
 logger = logging.getLogger(__name__)
 
 
@@ -150,6 +150,12 @@ def _check_startup_config(settings: Settings) -> None:
 async def lifespan(app: FastAPI):
     """Startup: Initialize database, SIP engine, and services."""
     settings = get_settings()
+
+    # Re-apply: under `uvicorn main:app` the server installs its own handlers on
+    # `uvicorn`/`uvicorn.access` after importing this module, which would emit
+    # colourised text alongside our JSON. This takes them back over.
+    configure_logging(settings.log_format, settings.log_level)
+
     _check_startup_config(settings)
 
     # Prefetch Casdoor's JWKS so the first authenticated request doesn't pay
@@ -622,4 +628,8 @@ if __name__ == "__main__":
         port=settings.port,
         reload=settings.debug,
         log_level=settings.log_level,
+        # Suppress uvicorn's own dictConfig: ours is installed at import and in
+        # lifespan, and letting uvicorn apply its default would attach a second,
+        # colourised handler — every line twice, one of them not JSON.
+        log_config=None,
     )

tests/test_logging_config.py

@@ -0,0 +1,183 @@
+"""
+Structured-logging tests.
+
+The two things worth guarding are the ones that are easy to break silently:
+uvicorn's access logger must actually route through our formatter (it sets
+`propagate = False` and brings its own handler), and its arg tuple must land as
+real JSON fields rather than a pre-formatted string.
+"""
+
+import json
+import logging
+import logging.config
+
+import pytest
+
+from config import Settings
+from core.logging_config import JSONFormatter, configure_logging
+
+
+def _record(name="test.logger", level=logging.INFO, msg="hello", args=None, **extra):
+    record = logging.LogRecord(
+        name=name, level=level, pathname=__file__, lineno=1, msg=msg, args=args, exc_info=None
+    )
+    for key, value in extra.items():
+        setattr(record, key, value)
+    return record
+
+
+def _emit(record):
+    return json.loads(JSONFormatter().format(record))
+
+
+class TestJSONFormatter:
+    def test_emits_single_line_json_with_core_fields(self):
+        out = JSONFormatter().format(_record())
+        assert "\n" not in out
+        payload = json.loads(out)
+        assert payload["msg"] == "hello"
+        assert payload["level"] == "INFO"
+        assert payload["logger"] == "test.logger"
+
+    def test_timestamp_is_utc_rfc3339_with_date(self):
+        # logging's default asctime is local-time and date-less, which is
+        # exactly what makes text logs hard to correlate in Loki.
+        ts = _emit(_record())["ts"]
+        assert ts.endswith("+00:00")
+        assert "T" in ts
+
+    def test_interpolates_message_args(self):
+        assert _emit(_record(msg="call %s ended", args=("abc123",)))["msg"] == "call abc123 ended"
+
+    def test_extra_fields_are_promoted(self):
+        payload = _emit(_record(call_id="c-1", duration=12.5))
+        assert payload["call_id"] == "c-1"
+        assert payload["duration"] == 12.5
+
+    def test_uvicorn_color_message_is_dropped(self):
+        # Uvicorn ships an ANSI-coloured copy of the message via extra=; letting
+        # it through puts escape codes in Loki.
+        payload = _emit(
+            _record(name="uvicorn.error", msg="Started", color_message="\x1b[36mStarted\x1b[0m")
+        )
+        assert "color_message" not in payload
+        assert "\x1b" not in json.dumps(payload)
+
+    def test_non_json_native_extra_is_stringified(self):
+        payload = _emit(_record(obj=object()))
+        assert isinstance(payload["obj"], str)
+
+    def test_secretstr_extra_stays_masked(self):
+        # Config secrets are SecretStr precisely so an accidental log can't leak
+        # them; stringification must preserve that.
+        from pydantic import SecretStr
+
+        payload = _emit(_record(secret=SecretStr("hs_pat_supersecret")))
+        assert "supersecret" not in json.dumps(payload)
+
+    def test_exception_is_captured(self):
+        try:
+            raise ValueError("boom")
+        except ValueError:
+            import sys
+
+            record = _record(level=logging.ERROR, msg="failed")
+            record.exc_info = sys.exc_info()
+        payload = _emit(record)
+        assert "ValueError: boom" in payload["exc"]
+
+    def test_thread_name_included_only_off_main_thread(self):
+        # Which execution context logged a line is the first question when
+        # debugging a call across the asyncio/Sippy/PJSUA2 boundary.
+        on_main = _record()
+        on_main.threadName = "MainThread"
+        assert "thread" not in _emit(on_main)
+
+        off_main = _record()
+        off_main.threadName = "sippy-ed"
+        assert _emit(off_main)["thread"] == "sippy-ed"
+
+
+class TestAccessLogFields:
+    def _access(self, status=200):
+        return _emit(
+            _record(
+                name="uvicorn.access",
+                msg='%s - "%s %s HTTP/%s" %d',
+                args=("127.0.0.1:5050", "GET", "/api/v1/calls", "1.1", status),
+            )
+        )
+
+    def test_arg_tuple_becomes_structured_fields(self):
+        payload = self._access()
+        assert payload["method"] == "GET"
+        assert payload["path"] == "/api/v1/calls"
+        assert payload["client_addr"] == "127.0.0.1:5050"
+        assert payload["http_version"] == "1.1"
+
+    def test_status_code_is_a_number_not_a_string(self):
+        # So Loki can range-filter on it (status_code >= 500).
+        assert self._access(503)["status_code"] == 503
+
+    def test_access_line_is_not_pre_formatted(self):
+        # The whole point: no interpolated request line to regex back apart.
+        assert "msg" not in self._access()
+
+    def test_unexpected_arg_shape_falls_back_to_message(self):
+        # A logging path that raises would take out the request; degrade instead.
+        payload = _emit(_record(name="uvicorn.access", msg="just a string", args=None))
+        assert payload["msg"] == "just a string"
+
+
+class TestConfigureLogging:
+    @pytest.fixture(autouse=True)
+    def _restore(self):
+        root = logging.getLogger()
+        saved = root.handlers[:], root.level
+        yield
+        root.handlers[:] = saved[0]
+        root.setLevel(saved[1])
+
+    def _uvicorn_defaults(self):
+        """Reproduce what uvicorn does to its loggers at startup."""
+        from uvicorn.config import LOGGING_CONFIG
+
+        logging.config.dictConfig(LOGGING_CONFIG)
+
+    def test_takes_over_uvicorn_handlers(self):
+        self._uvicorn_defaults()
+        access = logging.getLogger("uvicorn.access")
+        assert access.propagate is False  # uvicorn's default, the problem
+
+        configure_logging("json", "info")
+        assert access.propagate is True
+        assert access.handlers == []
+
+    def test_json_mode_installs_json_formatter(self):
+        configure_logging("json", "info")
+        assert isinstance(logging.getLogger().handlers[0].formatter, JSONFormatter)
+
+    def test_text_mode_does_not(self):
+        configure_logging("text", "info")
+        assert not isinstance(logging.getLogger().handlers[0].formatter, JSONFormatter)
+
+    def test_is_idempotent(self):
+        # Called at import and again in lifespan; a second call must replace the
+        # handler, not add one, or every line is emitted twice.
+        configure_logging("json", "info")
+        configure_logging("json", "info")
+        assert len(logging.getLogger().handlers) == 1
+
+    def test_respects_log_level(self):
+        configure_logging("json", "warning")
+        assert logging.getLogger().level == logging.WARNING
+
+
+class TestSettings:
+    def test_defaults_to_text(self):
+        # A JSON-only default would make local development worse.
+        assert Settings(database_url="sqlite+aiosqlite:///:memory:").log_format == "text"
+
+    def test_reads_log_format_env(self, monkeypatch):
+        monkeypatch.setenv("LOG_FORMAT", "json")
+        assert Settings(database_url="sqlite+aiosqlite:///:memory:").log_format == "json"