diff --git a/.env.example b/.env.example index eac872a..c88a3bf 100644 --- a/.env.example +++ b/.env.example @@ -10,10 +10,18 @@ # Application APP_ENV=local APP_READINESS_CHECK_TIMEOUT_SECONDS=2.0 +# Set by CI/CD at build/deploy time; never computed at runtime. +APP_SERVICE_VERSION=dev # Logging LOG_LEVEL=INFO LOG_JSON_FORMAT=false +# Optional second sink, always JSON regardless of LOG_JSON_FORMAT. Local dev +# only -- leave unset in production, where stdout/stderr collection is +# preferred over an in-container log file. +# LOG_FILE_PATH=logs/app.log +LOG_FILE_MAX_BYTES=10485760 +LOG_FILE_BACKUP_COUNT=5 # Postgres (application database, separate from Langfuse's Postgres) # Use 127.0.0.1 rather than localhost: some environments resolve localhost to diff --git a/CLAUDE.md b/CLAUDE.md index 04cbbbc..155c45c 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -254,7 +254,24 @@ Postgres remains system of record for tenants, API keys, audit, jobs, `graph_runs`, `llm_calls`/`llm_pricing`. Correlate the two via `request_id`, `tenant_id`, `thread_id`, `run_id`. Use `structlog` with stable event names and structured fields (`logger.info("graph.run.completed", ...)`), not -interpolated prose; JSON logs by default in production. +interpolated prose; JSON logs by default in production, plus an optional +local-only JSON file sink independent of the console renderer (`LOG_FILE_PATH`). + +**Add logging in the same change that adds the code, not as a follow-up.** +When you add a new service-level entry point (an `application/` function a +route calls directly, an ingestion phase, a mutation) or a new failure branch +inside one, add its `logger.*` event in that same diff, using ADR-0011's +level/event-naming table. Deferring it means re-deriving the failure modes and +field names later from code that no longer has them in working memory — as +happened with `src/application/files/upload.py`, where four failure branches +(`parse_failed`, `chunk_limit_exceeded`, `embedding_failed`, `index_failed`) +shipped with no log event and had to be retrofitted. + +This does not mean logging every function. Pure functions, models, schemas, +and repositories (`infrastructure/postgres/repositories/`) stay silent by +convention — the caller that turns their result into a business-meaningful +outcome (job succeeded, upload rejected, domain disabled) is where the event +belongs, not the row-level function underneath it. ## Testing (ADR-0016) diff --git a/docs/adr/0011-python-structured-logging-with-structlog.md b/docs/adr/0011-python-structured-logging-with-structlog.md index b316195..ad3316b 100644 --- a/docs/adr/0011-python-structured-logging-with-structlog.md +++ b/docs/adr/0011-python-structured-logging-with-structlog.md @@ -70,17 +70,30 @@ logger.info( Do not build log messages by interpolating operational metadata into prose. Prefer fields over long strings because fields are queryable. -### Emit JSON logs by default in production +### Emit JSON logs by default in production; console and file are independent sinks locally Production logs are JSON on stdout so process managers, container runtimes, and -log collectors can ingest them directly. Local development may use a colored -console renderer controlled by configuration. +log collectors can ingest them directly. This does not change. -File logging is optional and mainly for local development. If enabled, it must -use explicit rotation settings such as `maxBytes` and `backupCount`. Do not rely -on a default `RotatingFileHandler` with no rotation parameters. In containerized -production, stdout/stderr collection is preferred over writing `logs/app.log` -inside the application container. +Locally, stdout and an optional file are two **independent, simultaneous** +handlers on the same logger, not a single renderer chosen by a flag — the same +structlog event fans out to both: + +- **Console handler**: always on, `structlog.dev.ConsoleRenderer(colors=True)`. + This is what a developer reads while the process runs, so it stays + human-readable regardless of whether file logging is also enabled. +- **File handler**: off by default, enabled by setting `LOG_FILE_PATH`. Always + renders JSON (`structlog.processors.JSONRenderer()`), independent of the + console handler's renderer, so a saved log is machine-parseable even though + the terminal output next to it is not. Must use explicit rotation + (`RotatingFileHandler` with `maxBytes`/`backupCount` — never an unrotated + handler). + +In containerized production, stdout/stderr collection remains preferred over +writing `logs/app.log` inside the application container, so `LOG_FILE_PATH` is +expected to be unset there; the file handler exists for local development, +where reading a colored terminal *and* keeping a JSON trail to grep/parse later +are both useful at once. ### Configure stdlib and structlog together @@ -188,6 +201,36 @@ Notes: - `structlog.contextvars.merge_contextvars` ensures request-bound fields appear on both structlog and stdlib logs processed through the formatter. +### Bind process-level environment context once at startup + +Deployment identity — which build is running, in which environment, on which +instance — answers a different question than request correlation: "is this +issue specific to one deployment / one region / one instance?" rather than "is +this issue specific to one request?" It does not vary per request, so it must +not go through `structlog.contextvars`, which `RequestIdMiddleware` clears on +every request; a value bound there before the first request would be wiped the +moment that middleware runs. + +Instead, add a static structlog **processor** — a plain closure over values read +once at `configure_logging()` time — so it runs on every event regardless of +request context: + +```python +def _bind_environment(settings: AppLimitSettings): + def processor(logger, method_name, event_dict): + event_dict["env"] = settings.env + event_dict["service_version"] = settings.service_version + return event_dict + + return processor +``` + +`service_version` should be the deployed commit SHA or release tag (e.g. from a +`GIT_SHA`/`APP_VERSION` build-time env var — not computed at runtime by +shelling out to `git`). This makes "is this only happening on the new +deployment?" answerable directly from logs, without cross-referencing a +separate deployment record. + ### Bind request context with contextvars At FastAPI ingress, clear stale context, bind request identifiers, and return the diff --git a/src/bootstrap/lifespan.py b/src/bootstrap/lifespan.py index 0e21a32..7b2c7b9 100644 --- a/src/bootstrap/lifespan.py +++ b/src/bootstrap/lifespan.py @@ -59,7 +59,7 @@ def create_lifespan( @asynccontextmanager async def lifespan(app: FastAPI) -> AsyncIterator[None]: resolved_settings = settings or Settings() - configure_logging(resolved_settings.logging) + configure_logging(resolved_settings.logging, resolved_settings.app) # tiktoken fetches its vocabulary over the network on first use, so warm # it here: a missing vocabulary should fail the process at boot, not the diff --git a/src/cli/qdrant_bootstrap.py b/src/cli/qdrant_bootstrap.py index 40bfb6d..9362838 100644 --- a/src/cli/qdrant_bootstrap.py +++ b/src/cli/qdrant_bootstrap.py @@ -30,7 +30,7 @@ logger = structlog.get_logger(__name__) async def bootstrap(settings: Settings | None = None) -> int: resolved = settings or Settings() - configure_logging(resolved.logging) + configure_logging(resolved.logging, resolved.app) client = create_client(resolved.qdrant) try: created = await ensure_chunks_collection(client, collection=resolved.qdrant.collection) diff --git a/src/config.py b/src/config.py index dbcc50c..ca5edff 100644 --- a/src/config.py +++ b/src/config.py @@ -226,15 +226,34 @@ class AppLimitSettings(BaseSettings): env: str = "local" readiness_check_timeout_seconds: float = 2.0 + # The deployed commit SHA or release tag (ADR-0011, "Bind process-level + # environment context"). Set by CI/CD at build/deploy time -- never + # computed at runtime by shelling out to git, which would fail in a + # container image with no .git directory. + service_version: str = "dev" class LoggingSettings(BaseSettings): + """Logging sinks (ADR-0011). + + `json_format` controls stdout's renderer only. Production sets it `true` + so stdout is JSON for the container log collector; local development + leaves it `false` for a colored console renderer. `file_path`, when set, + is a second, independent handler that always renders JSON regardless of + `json_format` -- a developer can read a human console while still keeping + a machine-parseable file. Unset in production: stdout/stderr collection is + preferred there over a log file inside the container. + """ + model_config = SettingsConfigDict( env_prefix="LOG_", extra="ignore", env_file=".env", env_ignore_empty=True ) level: str = "INFO" json_format: bool = False + file_path: str | None = None + file_max_bytes: int = 10 * 1024 * 1024 + file_backup_count: int = 5 class Settings(BaseSettings): diff --git a/src/infrastructure/observability/logging.py b/src/infrastructure/observability/logging.py index 73e61d0..bf2200f 100644 --- a/src/infrastructure/observability/logging.py +++ b/src/infrastructure/observability/logging.py @@ -1,14 +1,50 @@ +"""Logging configuration: structlog + stdlib, dual local sinks (ADR-0011). + +Console and an optional file are independent, simultaneous handlers on the +same logger, not a single renderer chosen by a flag -- the same structlog +event fans out to both. The console handler is always human-readable +(`ConsoleRenderer`); the file handler, when enabled via `LOG_FILE_PATH`, +always renders JSON regardless of `LOG_JSON_FORMAT`, so a saved log stays +machine-parseable even when the terminal next to it is not. + +`LOG_JSON_FORMAT` controls *stdout's* renderer only: production sets it `true` +so the container log collector gets JSON; local development leaves it `false` +for the colored console. `LOG_FILE_PATH` is expected to be unset in +production -- stdout/stderr collection is preferred there over a log file +inside the container. +""" + import logging import logging.config import sys +from collections.abc import Callable import structlog -from src.config import LoggingSettings +from src.config import AppLimitSettings, LoggingSettings -def configure_logging(settings: LoggingSettings) -> None: +def _bind_environment(settings: AppLimitSettings) -> Callable[..., dict[str, object]]: + """A static processor, not a contextvar: `env`/`service_version` don't + vary per request, and a contextvar bound before the first request would + be wiped by `RequestIdMiddleware`'s `clear_contextvars()` on that request. + Closing over `settings` at configure time makes every event carry them + instead, regardless of request context (ADR-0011). + """ + + def processor( + logger: object, method_name: str, event_dict: dict[str, object] + ) -> dict[str, object]: + event_dict["env"] = settings.env + event_dict["service_version"] = settings.service_version + return event_dict + + return processor + + +def configure_logging(settings: LoggingSettings, app_settings: AppLimitSettings) -> None: shared_processors = [ + _bind_environment(app_settings), structlog.contextvars.merge_contextvars, structlog.stdlib.add_log_level, structlog.stdlib.add_logger_name, @@ -27,55 +63,84 @@ def configure_logging(settings: LoggingSettings) -> None: cache_logger_on_first_use=True, ) - renderer = ( + console_renderer = ( structlog.processors.JSONRenderer() if settings.json_format else structlog.dev.ConsoleRenderer(colors=True) ) + formatters = { + "console": { + "()": structlog.stdlib.ProcessorFormatter, + "processors": [ + structlog.stdlib.ProcessorFormatter.remove_processors_meta, + console_renderer, + ], + "foreign_pre_chain": [ + structlog.stdlib.ExtraAdder(), + *shared_processors, + ], + }, + } + handlers: dict[str, dict[str, object]] = { + "console": { + "class": "logging.StreamHandler", + "level": settings.level, + "formatter": "console", + "stream": sys.stdout, + }, + } + root_handlers = ["console"] + + if settings.file_path is not None: + # File handler always renders JSON, independent of the console + # renderer chosen above -- a saved log stays machine-parseable even + # when stdout is the colored, human-readable renderer. + formatters["file"] = { + "()": structlog.stdlib.ProcessorFormatter, + "processors": [ + structlog.stdlib.ProcessorFormatter.remove_processors_meta, + structlog.processors.JSONRenderer(), + ], + "foreign_pre_chain": [ + structlog.stdlib.ExtraAdder(), + *shared_processors, + ], + } + handlers["file"] = { + "class": "logging.handlers.RotatingFileHandler", + "level": settings.level, + "formatter": "file", + "filename": settings.file_path, + "maxBytes": settings.file_max_bytes, + "backupCount": settings.file_backup_count, + } + root_handlers.append("file") + logging.config.dictConfig( { "version": 1, "disable_existing_loggers": False, - "formatters": { - "default": { - "()": structlog.stdlib.ProcessorFormatter, - "processors": [ - structlog.stdlib.ProcessorFormatter.remove_processors_meta, - renderer, - ], - "foreign_pre_chain": [ - structlog.stdlib.ExtraAdder(), - *shared_processors, - ], - }, - }, - "handlers": { - "console": { - "class": "logging.StreamHandler", - "level": settings.level, - "formatter": "default", - "stream": sys.stdout, - }, - }, + "formatters": formatters, + "handlers": handlers, "loggers": { "": { - "handlers": ["console"], + "handlers": root_handlers, "level": settings.level, "propagate": False, }, "uvicorn": { - "handlers": ["console"], + "handlers": root_handlers, "level": settings.level, "propagate": False, }, "uvicorn.access": { - "handlers": ["console"], + "handlers": root_handlers, "level": settings.level, "propagate": False, }, "sqlalchemy.engine": { - "handlers": ["console"], + "handlers": root_handlers, "level": "WARNING", "propagate": False, }, diff --git a/tests/unit/infrastructure/observability/__init__.py b/tests/unit/infrastructure/observability/__init__.py new file mode 100644 index 0000000..e69de29 diff --git a/tests/unit/infrastructure/observability/test_logging.py b/tests/unit/infrastructure/observability/test_logging.py new file mode 100644 index 0000000..3ea878c --- /dev/null +++ b/tests/unit/infrastructure/observability/test_logging.py @@ -0,0 +1,106 @@ +"""Dual-sink logging config and the static environment processor (ADR-0011). + +`configure_logging` mutates global logging state (`logging.config.dictConfig`, +`structlog.configure`), so these tests assert on the *handler configuration it +builds*, plus one end-to-end capture per sink, rather than trying to isolate +process-global state across tests. +""" + +import json +import logging + +import pytest +import structlog + +from src.config import AppLimitSettings, LoggingSettings +from src.infrastructure.observability.logging import configure_logging + +pytestmark = pytest.mark.unit + +# Cross-test pollution from configure_logging() (cache_logger_on_first_use=True +# etc.) is reset by the autouse fixture in tests/conftest.py after every test, +# not just this module's -- these tests call the real configure_logging() +# directly and need the same cleanup any other test does. + + +def test_configure_logging_without_file_path_registers_only_console(tmp_path) -> None: + configure_logging(LoggingSettings(file_path=None), AppLimitSettings()) + + root = logging.getLogger() + handler_names = {type(h).__name__ for h in root.handlers} + assert handler_names == {"StreamHandler"} + + +def test_configure_logging_with_file_path_adds_a_rotating_file_handler(tmp_path) -> None: + log_file = tmp_path / "app.log" + + configure_logging( + LoggingSettings(file_path=str(log_file), file_max_bytes=1024, file_backup_count=2), + AppLimitSettings(), + ) + + root = logging.getLogger() + handler_names = {type(h).__name__ for h in root.handlers} + assert handler_names == {"StreamHandler", "RotatingFileHandler"} + + +def test_file_sink_is_json_even_when_console_is_not(tmp_path, capsys) -> None: + """The two sinks render independently: console stays human-readable while + the file stays JSON, regardless of LOG_JSON_FORMAT. + """ + log_file = tmp_path / "app.log" + + configure_logging( + LoggingSettings(json_format=False, file_path=str(log_file)), + AppLimitSettings(), + ) + structlog.get_logger("test").info("logging.dual_sink.test", widget_id="abc123") + + console_output = capsys.readouterr().out + file_output = log_file.read_text().strip() + + # Console: human-readable, not parseable JSON. + with pytest.raises(json.JSONDecodeError): + json.loads(console_output) + assert "logging.dual_sink.test" in console_output + + # File: valid JSON with the same event. + file_event = json.loads(file_output) + assert file_event["event"] == "logging.dual_sink.test" + assert file_event["widget_id"] == "abc123" + + +def test_every_event_carries_env_and_service_version(tmp_path, capsys) -> None: + """Static environment context, not a per-request contextvar -- it must + show up on an event with no request in flight. + """ + configure_logging( + LoggingSettings(json_format=True, file_path=None), + AppLimitSettings(env="staging", service_version="abc1234"), + ) + + structlog.get_logger("test").info("logging.env_context.test") + + event = json.loads(capsys.readouterr().out.strip()) + assert event["env"] == "staging" + assert event["service_version"] == "abc1234" + + +def test_env_context_survives_request_contextvar_clearing(tmp_path, capsys) -> None: + """The bug this design avoids: if env/service_version were bound via + contextvars before a request, RequestIdMiddleware's clear_contextvars() + would wipe them. They must still appear after a clear. + """ + configure_logging( + LoggingSettings(json_format=True, file_path=None), + AppLimitSettings(env="prod", service_version="v42"), + ) + + structlog.contextvars.clear_contextvars() + structlog.contextvars.bind_contextvars(request_id="req-1") + structlog.get_logger("test").info("logging.post_clear.test") + + event = json.loads(capsys.readouterr().out.strip()) + assert event["env"] == "prod" + assert event["service_version"] == "v42" + assert event["request_id"] == "req-1"