feat(observability): add dual local logging sinks and static environment context

Why:
- Wanted human-readable console output while developing locally, without
  losing a machine-parseable log for later grepping/parsing. A single
  renderer chosen by a flag can't do both at once.
- ADR-0011 had no way to correlate an issue with a specific deployment
  (build/region/instance) independent of any one request.

Changes:
- configure_logging() now builds two independent handlers: console (always
  on, colored unless LOG_JSON_FORMAT=true) and an optional rotating JSON file
  (LOG_FILE_PATH, unset by default) -- the same structlog event fans out to
  both, so call sites are unaffected.
- A static structlog processor binds env/service_version onto every event.
  Deliberately not a contextvar: RequestIdMiddleware's clear_contextvars()
  would wipe a value bound there before the first request.
- New settings: APP_SERVICE_VERSION, LOG_FILE_PATH/LOG_FILE_MAX_BYTES/
  LOG_FILE_BACKUP_COUNT.
- ADR-0011 amended with both decisions ("console and file are independent
  sinks locally"; "bind process-level environment context once at startup").

Impact:
- configure_logging() signature changed to (logging_settings, app_settings);
  both call sites (lifespan, qdrant_bootstrap CLI) updated.
This commit is contained in:
Ali Zarinkolah
2026-08-20 19:20:27 +03:30
parent e9e83b3a26
commit 9e8987968c
9 changed files with 297 additions and 39 deletions

View File

@@ -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

View File

@@ -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)

View File

@@ -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

View File

@@ -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

View File

@@ -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)

View File

@@ -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):

View File

@@ -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)
)
logging.config.dictConfig(
{
"version": 1,
"disable_existing_loggers": False,
"formatters": {
"default": {
formatters = {
"console": {
"()": structlog.stdlib.ProcessorFormatter,
"processors": [
structlog.stdlib.ProcessorFormatter.remove_processors_meta,
renderer,
console_renderer,
],
"foreign_pre_chain": [
structlog.stdlib.ExtraAdder(),
*shared_processors,
],
},
},
"handlers": {
}
handlers: dict[str, dict[str, object]] = {
"console": {
"class": "logging.StreamHandler",
"level": settings.level,
"formatter": "default",
"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": 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,
},

View File

@@ -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"