From 6b55d98465c9b49e7796f61d79549249baee1dc4 Mon Sep 17 00:00:00 2001 From: Blake Bertuccelli-Booth <46652+bbertucc@users.noreply.github.com> Date: Mon, 18 May 2026 14:34:23 -0500 Subject: [PATCH] feat(logging): JSON formatter so structured log fields survive MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit LoggingMiddleware attaches per-request structured fields to every log record via extra={} — path, status code, latency, and the authenticated identity (user_sub / user_email / user_provider). None of it reached the logs: src/main.py configured logging with basicConfig and a fixed format string ("%(asctime)s - %(name)s - %(levelname)s - %(message)s"), and the stdlib formatter renders only the fields named in that string. Every extra was silently dropped, so CloudWatch / any log sink saw nothing but "Response: 200 (0.041s)" — no path, no status, no user. This adds src/utils/logging_config.py with: - JsonFormatter: emits each record as single-line JSON including any extra={} fields, exc_info, and stack_info. Uses default=str so a non-serialisable extra (UUID, datetime) degrades instead of raising inside the log call. - configure_logging(level, json_format): installs one root handler with the chosen formatter. src/main.py now calls configure_logging with json_format gated on environment == "production". Production emits JSON (queryable in CloudWatch Logs Insights, Loki, etc.); local dev keeps the human-readable text format. The noisy-third-party-logger silencing is unchanged. No new dependency — JsonFormatter is ~40 lines of stdlib. The middleware was already doing the work; this stops the formatter from throwing it away. Co-Authored-By: Claude Opus 4.7 (1M context) --- src/main.py | 10 ++- src/utils/logging_config.py | 79 +++++++++++++++++++++ tests/unit/utils/test_logging_config.py | 93 +++++++++++++++++++++++++ 3 files changed, 180 insertions(+), 2 deletions(-) create mode 100644 src/utils/logging_config.py create mode 100644 tests/unit/utils/test_logging_config.py diff --git a/src/main.py b/src/main.py index db8e145..55f6291 100644 --- a/src/main.py +++ b/src/main.py @@ -27,11 +27,17 @@ from .middleware.metrics import setup_metrics from .services.rate_limit_service import RateLimitService from .telemetry import init_telemetry, shutdown_telemetry +from .utils.logging_config import configure_logging from .workers.pii_worker import start_pii_worker from .workers.timeout_worker import start_timeout_worker -# Configure logging -logging.basicConfig(level=settings.log_level, format="%(asctime)s - %(name)s - %(levelname)s - %(message)s") +# Configure logging. JSON in production so the structured fields the +# middleware attaches via extra={} (path, status, latency, identity) are +# queryable downstream; human-readable text in local dev. +configure_logging( + level=settings.log_level, + json_format=(settings.environment == "production"), +) # Silence noisy third-party loggers (they flood DEBUG with base64 payloads, auth signatures, etc.) for _noisy_logger in ("botocore", "boto3", "urllib3", "httpcore", "httpx", "s3transfer", "python_multipart"): diff --git a/src/utils/logging_config.py b/src/utils/logging_config.py new file mode 100644 index 0000000..5151585 --- /dev/null +++ b/src/utils/logging_config.py @@ -0,0 +1,79 @@ +"""Application logging configuration. + +The request/response middleware attaches structured fields to log records +via ``logging``'s ``extra={}`` mechanism (path, status code, latency, +authenticated identity). The stdlib's default formatter renders only the +fields named in its format string, so every one of those extras is +silently dropped. + +This module provides a JSON formatter that emits the extras, plus a +``configure_logging`` helper. JSON is used in production (so CloudWatch +Logs Insights, Loki, etc. can query the fields); plain text is kept for +local development where logs are read by eye. +""" + +from __future__ import annotations + +import datetime +import json +import logging + +# LogRecord attributes that the stdlib sets itself. Anything on a record +# that is *not* in this set was supplied by the caller via extra={} and is +# what we want to surface. +_STANDARD_ATTRS = frozenset({ + "name", "msg", "args", "levelname", "levelno", "pathname", "filename", + "module", "exc_info", "exc_text", "stack_info", "lineno", "funcName", + "created", "msecs", "relativeCreated", "thread", "threadName", + "processName", "process", "taskName", "message", "asctime", +}) + + +class JsonFormatter(logging.Formatter): + """Format log records as single-line JSON, including ``extra`` fields.""" + + def format(self, record: logging.LogRecord) -> str: + payload: dict[str, object] = { + "timestamp": datetime.datetime.fromtimestamp( + record.created, tz=datetime.UTC + ).isoformat(), + "level": record.levelname, + "logger": record.name, + "message": record.getMessage(), + } + + # Caller-supplied extras (the whole point of this formatter). + for key, value in record.__dict__.items(): + if key not in _STANDARD_ATTRS and not key.startswith("_"): + payload[key] = value + + if record.exc_info: + payload["exc_info"] = self.formatException(record.exc_info) + if record.stack_info: + payload["stack_info"] = self.formatStack(record.stack_info) + + # default=str so non-serialisable values (UUIDs, datetimes) degrade + # gracefully instead of crashing the log call. + return json.dumps(payload, default=str) + + +def configure_logging(level: str, *, json_format: bool) -> None: + """Install a single root handler with the chosen formatter. + + Args: + level: Root log level (``DEBUG``, ``INFO``, ...). + json_format: ``True`` for JSON output (production), ``False`` for + the human-readable text format (local development). + """ + handler = logging.StreamHandler() + if json_format: + handler.setFormatter(JsonFormatter()) + else: + handler.setFormatter( + logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s") + ) + + root = logging.getLogger() + root.handlers.clear() + root.addHandler(handler) + root.setLevel(level) diff --git a/tests/unit/utils/test_logging_config.py b/tests/unit/utils/test_logging_config.py new file mode 100644 index 0000000..d66cb49 --- /dev/null +++ b/tests/unit/utils/test_logging_config.py @@ -0,0 +1,93 @@ +"""Tests for JSON logging configuration.""" + +import json +import logging +import uuid + +import pytest +from src.utils.logging_config import JsonFormatter, configure_logging + +pytestmark = pytest.mark.unit + + +def _record(**extra) -> logging.LogRecord: + """Build a LogRecord with optional extra fields, the way logging does.""" + record = logging.LogRecord( + name="src.test", + level=logging.INFO, + pathname=__file__, + lineno=1, + msg="hello %s", + args=("world",), + exc_info=None, + ) + for key, value in extra.items(): + setattr(record, key, value) + return record + + +def test_formats_valid_json_with_core_fields(): + out = json.loads(JsonFormatter().format(_record())) + assert out["level"] == "INFO" + assert out["logger"] == "src.test" + assert out["message"] == "hello world" # %-args rendered + assert "timestamp" in out + + +def test_includes_extra_fields(): + out = json.loads(JsonFormatter().format(_record( + path="/api/v1/documents", + status_code=200, + user_sub="zach", + ))) + assert out["path"] == "/api/v1/documents" + assert out["status_code"] == 200 + assert out["user_sub"] == "zach" + + +def test_does_not_emit_standard_record_internals(): + out = json.loads(JsonFormatter().format(_record())) + # Internal LogRecord attributes must not leak into the payload. + for noise in ("args", "msg", "levelno", "pathname", "thread"): + assert noise not in out + + +def test_non_serialisable_extra_degrades_gracefully(): + job_id = uuid.uuid4() + out = json.loads(JsonFormatter().format(_record(job_id=job_id))) + # default=str keeps the log call from crashing on a UUID. + assert out["job_id"] == str(job_id) + + +def test_includes_exception_info(): + try: + raise ValueError("boom") + except ValueError: + import sys + record = _record() + record.exc_info = sys.exc_info() + out = json.loads(JsonFormatter().format(record)) + assert "exc_info" in out + assert "ValueError: boom" in out["exc_info"] + + +def test_configure_logging_json_installs_json_formatter(): + try: + configure_logging(level="INFO", json_format=True) + root = logging.getLogger() + assert len(root.handlers) == 1 + assert isinstance(root.handlers[0].formatter, JsonFormatter) + assert root.level == logging.INFO + finally: + logging.getLogger().handlers.clear() + + +def test_configure_logging_text_installs_plain_formatter(): + try: + configure_logging(level="DEBUG", json_format=False) + root = logging.getLogger() + assert len(root.handlers) == 1 + assert not isinstance(root.handlers[0].formatter, JsonFormatter) + assert root.level == logging.DEBUG + finally: + logging.getLogger().handlers.clear()