docs: document SIP_ENGINE and correct config tables against the models

Started as the SIP_ENGINE row flagged in the last commit. Cross-checking the
tables against config.py mechanically (rather than by eye) turned up more,
including two entries that were actively wrong.

Corrections:
- GATEWAY_RTP_PORT_MIN/MAX and GATEWAY_HOST are documented in
  configuration.md but do not exist — no code reads them and they are absent
  from .env.example. Setting them today does nothing. Replaced with the real
  GATEWAY_SIP_ fields (host/port/domain).
- GATEWAY_SIP_PORT was documented as 5080 in two places; the code and
  .env.example both say 5060.
- DATABASE_URL was documented with a SQLite default. There is none, and
  startup exits if it is unset.

Additions — every env var the models accept is now documented somewhere
(verified bidirectionally: nothing in the models undocumented, nothing
documented that the models reject):
- Server section: HOST, PORT, DEBUG, LOG_LEVEL, LOG_FORMAT
- Safety section: MAX_CONCURRENT_CALLS, USE_MOCK_SIP, SIP_ENGINE
- Receptionist section (configuration.md had none, though seven vars exist)

Structural staleness, from the PR #8 media-plane work:
- core/pjsua_engine.py was absent from the component list and file tree; so
  were dial_plan.py (the emergency guard) and sip_engine.py.
- architecture.md's banner still read "media plane in transition". The engine
  landed; it is now two selectable engines with the audio consequence stated.
- Tech Stack described "single-process async architecture" — the
  simplification CLAUDE.md explicitly calls out. Now points at the threading
  model, since there are three execution contexts.
- The Asterisk lab shipped in PR #8 with its own README but nothing linked to
  it. Linked from the test section and both doc indexes.
- CLAUDE.md's "no structured JSON logging" gap is closed; test count was 146
  across 16 files, now 189 across 19. The other listed gaps (no /metrics, no
  rate limiting, no health-probe log filter) were re-verified and still hold.

Deliberately not hardcoding a test count in the README — that is the same
staleness this commit is clearing up. All internal links and anchors verified
to resolve; 189 tests pass; lint unchanged at its 216 baseline.

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)

CLAUDE.md

@@ -68,7 +68,7 @@ REST / WS / MCP / Dashboard   (asyncio, FastAPI)
 4. **Consistent Patterns** — config via pydantic-settings sub-configs; MCP tools
    return formatted strings; REST returns Pydantic models; DB access via
    `session_scope()`. Match the neighbours.
-5. **Actually Works** — `pytest tests/ -v` (146 tests across 16 files). A change
+5. **Actually Works** — `pytest tests/ -v` (189 tests across 19 files). A change
    to call placement, routing, the classifier, or auth needs a test. The suite
    runs against SQLite (`aiosqlite`) and the mock SIP engine — no trunk, no
    Postgres required to test.
@@ -203,10 +203,12 @@ Surfaced honestly so you don't rediscover them as surprises. The README's
 Phase 4/5/6 checklists track most of these; **don't fold fixes into unrelated
 work** — raise them.
 
-- **No structured JSON logging.** Logging is plain `logging.basicConfig` in
+- ~~**No structured JSON logging.**~~ Done: `LOG_FORMAT=json` in
-  [main.py](main.py); there's no `LOG_FORMAT`/JSON path (README Phase 4 has this
+  [core/logging_config.py](core/logging_config.py), applied at import and again
-  unchecked). If Heluca observability wants JSON logs shipped to a collector,
+  in `lifespan` because uvicorn installs its own handlers (`propagate=False`)
-  that's a deliberate piece of work, not a drive-by.
+  after importing the app. The access log is included, with `status_code` as a
+  number so Loki can range-filter it. Text remains the default; the Docker image
+  sets json.
 - **No `/metrics` endpoint and no Prometheus.** Unlike the metrics-bearing
   estate services, there's no exposition endpoint here yet.
 - **No health-probe access-log filter.** Every `/health` poll hits the access

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

@@ -52,8 +52,9 @@ You give it a phone number and an intent ("dispute a charge on my December state
 ## What's Implemented
 
 ### Core Engine
-- **Sippy B2BUA Engine** (`core/sippy_engine.py`) — SIP call control, DTMF, bridging, conference, trunk registration
+- **Sippy B2BUA Engine** (`core/sippy_engine.py`) — SIP call control, DTMF, bridging, conference, trunk registration. Signalling only: no audio reaches the classifier on this path
-- **PJSUA2 Media Pipeline** (`core/media_pipeline.py`) — Audio routing, recording ports, conference bridge, WAV playback (stub mode until the `pjsua2` bindings are installed — see note below)
+- **PJSUA2 SIP Engine** (`core/pjsua_engine.py`) — Places the call itself so it owns the dialog, which is the only way PJSUA2 will surface RTP. Select with `SIP_ENGINE=pjsua2`; see [docs/architecture.md](docs/architecture.md#media-plane-why-pjsua2-places-the-call)
+- **PJSUA2 Media Pipeline** (`core/media_pipeline.py`) — Audio routing, capture ports, conference bridge, WAV playback (stub mode until the `pjsua2` bindings are installed — see note below)
 - **Call Manager** (`core/call_manager.py`) — Active call state tracking, lifecycle management
 - **Event Bus** (`core/event_bus.py`) — Async pub/sub with per-subscriber queues, type filtering, history
 
@@ -99,8 +100,12 @@ hold-slayer/
 ├── config.py                    # Pydantic settings from .env
 ├── core/
 │   ├── gateway.py               # Top-level gateway orchestrator
-│   ├── sippy_engine.py          # Sippy B2BUA SIP engine
+│   ├── dial_plan.py             # Emergency-number guard + number normalisation
+│   ├── sip_engine.py            # SIPEngine ABC + MockSIPEngine
+│   ├── sippy_engine.py          # Sippy B2BUA SIP engine (signalling only)
+│   ├── pjsua_engine.py          # PJSUA2 SIP engine (call control + media)
 │   ├── media_pipeline.py        # PJSUA2 audio routing
+│   ├── logging_config.py        # Text/JSON log formatting
 │   ├── call_manager.py          # Active call state management
 │   └── event_bus.py             # Async pub/sub event bus
 ├── services/
@@ -213,6 +218,15 @@ uvicorn main:app --host 0.0.0.0 --port 8000
 pytest tests/ -v
 ```
 
+No external services required — the suite runs against SQLite (`aiosqlite`) and
+the mock SIP engine, so it needs neither a trunk nor PostgreSQL.
+
+For the parts a unit test cannot reach — real SIP signalling, RTP, IVR
+navigation against a live switch — there is an **Asterisk lab**: a fake PSTN
+that answers calls, plays hold music, and runs scripted IVR menus, so call
+paths can be exercised without dialling a real number or incurring telephony
+charges. See [tests/lab/README.md](tests/lab/README.md).
+
 ## Docker
 
 A single image bundles the FastAPI process and the built dashboard (the node
@@ -373,11 +387,19 @@ 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` |
+| `HOST` | Bind address (off-loopback requires SSO enabled) | `0.0.0.0` |
+| `PORT` | Bind port | `8000` |
+| `DEBUG` | SQLAlchemy echo + uvicorn reload | `false` |
+| `LOG_LEVEL` | Root log level (`debug`/`info`/`warning`/`error`) | `info` |
+| `LOG_FORMAT` | `text` (human-readable) or `json` (structured, for Loki) | `text` |
+| `USE_MOCK_SIP` | Run the mock SIP engine — no real calls. Must be asked for | `false` |
+| `SIP_ENGINE` | `sippy` (signalling only) or `pjsua2` (call control + media) | `sippy` |
+| `NOTIFY_SMS_NUMBER` | SMS notification number (optional) | — |
 | `SIP_TRUNK_HOST` | Your SIP provider hostname | — |
 | `SIP_TRUNK_USERNAME` | SIP auth username | — |
 | `SIP_TRUNK_PASSWORD` | SIP auth password | — |
 | `SIP_TRUNK_DID` | Your phone number (E.164) | — |
-| `GATEWAY_SIP_PORT` | Port for device registration | `5080` |
+| `GATEWAY_SIP_PORT` | Port for device registration | `5060` |
 | `SPEACHES_URL` | Speaches/Whisper STT endpoint | `http://localhost:22070` |
 | `LLM_BASE_URL` | OpenAI-compatible LLM endpoint | `http://localhost:11434/v1` |
 | `LLM_MODEL` | Model name for IVR analysis | `llama3` |
@@ -391,11 +413,11 @@ All configuration is via environment variables (see `.env.example`):
 
 ## Tech Stack
 
-- **Python 3.12+** + **asyncio** — Single-process async architecture
+- **Python 3.12+** + **asyncio** — Single process. Not single-threaded: the SIP stacks run their own event loops on separate OS threads, crossed only through defined funnels ([docs/architecture.md](docs/architecture.md#threading-model))
 - **FastAPI** — REST API + WebSocket server
 - **SvelteKit** — Dashboard UI (built static, served by FastAPI at `/`)
-- **Sippy B2BUA** — SIP call control and DTMF
+- **Sippy B2BUA** — SIP call control and DTMF (`SIP_ENGINE=sippy`, signalling only)
-- **PJSUA2** — Media pipeline, conference bridge, recording, WAV playback
+- **PJSUA2** — Call control + media: conference bridge, capture ports, recording, WAV playback (`SIP_ENGINE=pjsua2`)
 - **Speaches** (Whisper) — Speech-to-text
 - **Rhema** (Kokoro) — Text-to-speech (OpenAI-compatible `/v1/audio/speech`)
 - **Ollama / vLLM / OpenAI** — LLM for IVR menu analysis and receptionist intent capture
@@ -408,6 +430,9 @@ Full documentation is in [`/docs`](docs/README.md):
 
 - [Architecture](docs/architecture.md) — System design, data flow, threading model
 - [Core Engine](docs/core-engine.md) — SIP engine, media pipeline, call manager, event bus
+- [Dial Plan](docs/dial-plan.md) — Number normalisation and the emergency-number guard
+- [PJSUA2 Build](docs/pjsua2-build.md) — Building the bindings (not pip-installable)
+- [Asterisk Lab](tests/lab/README.md) — The fake PSTN used for media validation
 - [Hold Slayer Service](docs/hold-slayer-service.md) — IVR navigation, hold detection, human detection
 - [Audio Classifier](docs/audio-classifier.md) — Waveform analysis, feature extraction, classification
 - [Services](docs/services.md) — LLM client, transcription, recording, analytics, notifications
@@ -449,7 +474,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)

docs/README.md

@@ -8,6 +8,9 @@ Comprehensive documentation for the Hold Slayer AI telephony gateway.
 |----------|-------------|
 | [Architecture](architecture.md) | System architecture, component diagram, data flow |
 | [Core Engine](core-engine.md) | SIP engine, media pipeline, call manager, event bus |
+| [Dial Plan](dial-plan.md) | Number normalisation and the emergency-number guard |
+| [PJSUA2 Build](pjsua2-build.md) | Building the `pjsua2` bindings (not pip-installable) |
+| [Asterisk Lab](../tests/lab/README.md) | The fake PSTN used for media validation |
 | [Hold Slayer Service](hold-slayer-service.md) | IVR navigation, hold detection, human detection, transfer |
 | [Audio Classifier](audio-classifier.md) | Waveform analysis, feature extraction, classification logic |
 | [Services](services.md) | LLM client, transcription, recording, analytics, notifications |

docs/architecture.md

@@ -4,11 +4,12 @@ Hold Slayer is a single-process async Python application built on FastAPI. It
 acts as an intelligent B2BUA (Back-to-Back User Agent) sitting between your SIP
 trunk (PSTN access) and your desk phone/softphone.
 
-> **Media plane in transition.** The gateway currently signals with Sippy and
+> **Two SIP engines, selected by `SIP_ENGINE`.** `sippy` (the default) signals
-> intends PJSUA2 to carry media, but PJSUA2 will not surface an RTP stream for
+> only — PJSUA2 will not surface an RTP stream for a dialog it does not own, so
-> a dialog it does not own — so no audio ever reaches the classifier. The fix
+> **no audio reaches the classifier** on that path. `pjsua2`
-> moves *call placement* into PJSUA2 while Sippy keeps the SBC roles. See
+> (`core/pjsua_engine.py`) places the call itself and is the only mode where
-> [Media plane: why PJSUA2 places the call](#media-plane-why-pjsua2-places-the-call)
+> audio reaches the classifier; it is opt-in while being proven against the lab.
+> Read [Media plane: why PJSUA2 places the call](#media-plane-why-pjsua2-places-the-call)
 > before changing anything in `core/`.
 
 ## System Diagram

docs/configuration.md

@@ -34,14 +34,36 @@ SSO-disabled-off-loopback.
 | `SIP_TRUNK_DID` | Your phone number (E.164) | — | Yes |
 | `SIP_TRUNK_TRANSPORT` | Transport protocol (`udp`, `tcp`, `tls`) | `udp` | No |
 
+### Server
+
+| Variable | Description | Default | Required |
+|----------|-------------|---------|----------|
+| `HOST` | Bind address. Off-loopback requires `CASDOOR_ENABLED=true` | `0.0.0.0` | No |
+| `PORT` | Bind port | `8000` | No |
+| `DEBUG` | SQLAlchemy echo + uvicorn reload | `false` | No |
+| `LOG_LEVEL` | Root log level (`debug`/`info`/`warning`/`error`) | `info` | No |
+| `LOG_FORMAT` | `text` (human-readable) or `json` (structured, for Loki) | `text` | No |
+
+`LOG_FORMAT=json` renders one JSON object per line, including uvicorn's access
+log — `method`, `path`, `status_code` (numeric, so it can be range-filtered) and
+`client_addr` arrive as queryable fields rather than a formatted string. The
+Docker image sets it; `text` is the default so local development stays readable.
+
+### Safety
+
+| Variable | Description | Default | Required |
+|----------|-------------|---------|----------|
+| `MAX_CONCURRENT_CALLS` | Cap on simultaneous outbound calls | `4` | No |
+| `USE_MOCK_SIP` | Run the mock SIP engine — no real calls. Must be asked for explicitly; an unconfigured trunk without it fails startup | `false` | No |
+| `SIP_ENGINE` | `sippy` (signalling only — no audio reaches the classifier) or `pjsua2` (call control + media) | `sippy` | No |
+
 ### Gateway
 
 | Variable | Description | Default | Required |
 |----------|-------------|---------|----------|
-| `GATEWAY_SIP_PORT` | Port for device SIP registration | `5080` | No |
+| `GATEWAY_SIP_HOST` | Bind address for the device-registration listener | `0.0.0.0` | No |
-| `GATEWAY_RTP_PORT_MIN` | Minimum RTP port | `10000` | No |
+| `GATEWAY_SIP_PORT` | Port for device SIP registration | `5060` | No |
-| `GATEWAY_RTP_PORT_MAX` | Maximum RTP port | `20000` | No |
+| `GATEWAY_SIP_DOMAIN` | SIP domain devices register against | `gateway.local` | No |
-| `GATEWAY_HOST` | Bind address | `0.0.0.0` | No |
 
 ### LLM
 
@@ -65,7 +87,7 @@ SSO-disabled-off-loopback.
 
 | Variable | Description | Default | Required |
 |----------|-------------|---------|----------|
-| `DATABASE_URL` | PostgreSQL or SQLite connection string | `sqlite+aiosqlite:///./hold_slayer.db` | No |
+| `DATABASE_URL` | PostgreSQL connection string. Startup exits with a readable error if unset | — | Yes |
 
 ### Notifications
 
@@ -73,6 +95,18 @@ SSO-disabled-off-loopback.
 |----------|-------------|---------|----------|
 | `NOTIFY_SMS_NUMBER` | Phone number for SMS alerts (E.164) | — | No |
 
+### Receptionist
+
+| Variable | Description | Default | Required |
+|----------|-------------|---------|----------|
+| `RECEPTIONIST_ENABLED` | Answer inbound calls with the AI receptionist | `true` | No |
+| `RECEPTIONIST_GREETING_TEMPLATE` | Spoken greeting | `"Hi, you've reached Robert's line. Who's calling, and what's this about?"` | No |
+| `RECEPTIONIST_MESSAGE_PROMPT` | Spoken prompt before recording a message | `"Please leave your message after the tone."` | No |
+| `RECEPTIONIST_LLM_PERSONA` | System prompt shaping the receptionist's decisions | See `config.py` | No |
+| `RECEPTIONIST_LISTEN_TIMEOUT_S` | Seconds to wait for the caller to speak | `15.0` | No |
+| `RECEPTIONIST_END_OF_UTTERANCE_SILENCE_S` | Silence marking the end of a turn | `1.2` | No |
+| `RECEPTIONIST_MESSAGE_MAX_SECONDS` | Voicemail cap | `90` | No |
+
 ### Audio Classifier
 
 | Variable | Description | Default | Required |

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"