From 1644999bcbc2a18556db1cb968cd938d263f100d Mon Sep 17 00:00:00 2001 From: Robert Helewka Date: Thu, 30 Jul 2026 06:18:06 -0400 Subject: [PATCH] feat(logging): structured JSON logs, uvicorn access log included MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- .env.example | 3 + Dockerfile | 5 + README.md | 4 +- config.py | 5 + core/logging_config.py | 175 +++++++++++++++++++++++++++++++++ main.py | 24 +++-- tests/test_logging_config.py | 183 +++++++++++++++++++++++++++++++++++ 7 files changed, 391 insertions(+), 8 deletions(-) create mode 100644 core/logging_config.py create mode 100644 tests/test_logging_config.py diff --git a/.env.example b/.env.example index bb91307..af136b6 100644 --- a/.env.example +++ b/.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) diff --git a/Dockerfile b/Dockerfile index 6c13e1e..c5140e9 100644 --- a/Dockerfile +++ b/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 diff --git a/README.md b/README.md index 6dc2caf..a517f81 100644 --- a/README.md +++ b/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) diff --git a/config.py b/config.py index 8f40bcc..189d602 100644 --- a/config.py +++ b/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 diff --git a/core/logging_config.py b/core/logging_config.py new file mode 100644 index 0000000..b768a0b --- /dev/null +++ b/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) diff --git a/main.py b/main.py index 5dd9d52..aa49672 100644 --- a/main.py +++ b/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 -logging.basicConfig( - level=logging.INFO, - format="%(asctime)s | %(levelname)-7s | %(name)s | %(message)s", - datefmt="%H:%M:%S", - stream=sys.stdout, -) +# Configure logging at import so anything logged during module import and +# startup config checks is formatted. Uvicorn installs its own handlers *after* +# importing this module, so `lifespan` calls `configure_logging` again to take +# them over — see core/logging_config.py. +_startup_settings = get_settings() +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, ) diff --git a/tests/test_logging_config.py b/tests/test_logging_config.py new file mode 100644 index 0000000..23677d3 --- /dev/null +++ b/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"