Module-level loggers via logging.getLogger(__name__). Logger names: services.parser, services.standardizer, auth.
Every line on stdout is a JSON object with a fixed field set:
{"timestamp": "2026-08-04T00:15:16.385386+00:00", "level": "INFO", "logger": "address_validator.services.parser", "message": "parse: type=Street country=US", "request_id": "01ARZ3NDEKTSV4RRFFQ69G5FAV"}timestamp/level/logger/message match structlog's defaults (so a later structlog migration doesn't churn consumers); request_id is this service's correlation field.
Single source of truth: core/logging.py::build_json_formatter(). Two consumers share it —
| Consumer | How |
|---|---|
| App loggers | core/logging.py::configure_logging(), called at main.py import |
uvicorn, uvicorn.access, uvicorn.error |
core/log_config.json (dictConfig), via the "()" factory key |
core/log_config.json is passed to uvicorn as --log-config src/address_validator/core/log_config.json in infra/address-validator.service and in every dev-server command. Drop the flag and uvicorn's own loggers keep their plain-text handlers, so journald gets plain access/error lines interleaved with JSON app records. tests/unit/core/test_logging.py pins the field set, the dictConfig validity, and the ExecStart wiring.
Every request gets a ULID generated by middleware.request_id.RequestIdMiddleware and stored in a ContextVar. logging_filter.RequestIdFilter injects request_id into every LogRecord; outside a request context it is "".
The filter is attached to the stdout handler, not to a logger — a logger-level filter only sees records emitted through that logger, so records propagating up from address_validator.* (and uvicorn's own loggers) would never get the field. Both configuration paths install it: build_stdout_handler() for the app, and the filters block in core/log_config.json for uvicorn.
The ID is also echoed to callers as the X-Request-ID response header.
Standalone CLI scripts (scripts/db/*, infra/*.py) log plain LEVEL: message lines rather than JSON, since they run outside a request context. The systemd-run infra scripts (sweep_cache.py, archive_audit.py, notify_unit_failure.py) configure logging through infra/journal_logging.py: when stderr is the journal, each record's first line carries its sd-daemon <N> priority. Without it, journald files every line at info and journalctl -p warning misses real errors. Continuation lines (tracebacks, psycopg DETAIL:) stay at info. That keeps them out of the WARNING+ journal tail that notify_unit_failure.py sends to notifier (#232).
| Event | Level | Module | Fields |
|---|---|---|---|
| Successful parse | DEBUG |
services.parser |
type=, country=, request_id |
| Ambiguous parse (RepeatedLabelError) | WARNING + DEBUG |
services.parser |
WARNING first, then DEBUG with type=Ambiguous; request_id on both |
| Standardize call | DEBUG |
services.standardizer |
count=, country=, request_id |
| Auth rejection — missing key (401) | INFO |
auth |
path=, request_id |
| Auth rejection — invalid key (403) | INFO |
auth |
path=, request_id |
| Cache lookup miss | DEBUG |
services.validation.cache_provider |
pattern_key=, request_id |
| Cache lookup hit | DEBUG |
services.validation.cache_provider |
request_id |
| Cache pipeline-version mismatch (treated as miss, #145) | INFO |
services.validation.cache_provider |
pattern_key=, row_version=, current_version=, request_id — INFO so post-bump invalidation waves are visible in prod logs; keys are hashes, no PII |
| Cache store | DEBUG |
services.validation.cache_provider |
request_id |
| Cache storage error (fail-open) | WARNING |
services.validation.cache_provider |
request_id |
| USPS API call start | DEBUG |
services.validation.usps_provider |
country=, request_id |
| USPS OAuth2 token fetch | DEBUG |
services.validation.usps_client |
request_id |
| USPS 400 Bad Request | WARNING |
services.validation.usps_client |
request_id |
| USPS 429 received | WARNING |
services.validation.usps_client |
request_id |
| Recon: novel USPS response shape (issue #122) | INFO |
services.validation.usps_client |
dpv=, extras=, request_id |
USPS unrecognised additionalInfo.DPVConfirmation, mapped to undetermined (once per distinct code per process; all longer values share one line, GH #254) |
WARNING |
services.validation.usps_provider |
the code (≤ 2 chars; longer: length only) + its length, request_id |
| Google API call start | DEBUG |
services.validation.google_provider |
country=, request_id |
| Google 400 Bad Request | WARNING |
services.validation.google_client |
request_id |
| Google 429 received | WARNING |
services.validation.google_client |
request_id |
Google unrecognised uspsData.dpvConfirmation, mapped to undetermined (once per distinct code per process; all longer values share one line, GH #254) |
WARNING |
services.validation.google_client |
the code (≤ 2 chars; longer: length only) + its length, request_id |
Google credential refresh failed transiently — token endpoint 5xx after google-auth's retries, or a metadata-server network failure (Compute Engine credentials), raised as ProviderTransientError (GH #257) |
WARNING |
services.validation.google_client |
fixed message only — the exception carries the token endpoint's error body, request_id |
Google uspsData.errorMessage present — USPS processing suspended (once per cassProcessed value per process, GH #254) |
WARNING |
services.validation.google_client |
cassProcessed= only; the message text is never logged, request_id |
Provider request failed — any httpx.RequestError (connect error, timeout, undecodable body) or google-auth TransportError, raised as ProviderTransientError (GH #257) |
WARNING |
services.validation.usps_client / services.validation.google_client |
provider name, exception class name only — never str(exc), request_id |
| Provider rate-limited / at-capacity / transient / bad request (chain fallback) | WARNING |
services.validation.chain_provider |
provider class name, exception class name, retry-after seconds (all but bad request, GH #270), request_id |
Provider answered undetermined (chain soft fallback, GH #250) |
INFO |
services.validation.chain_provider |
provider class name, request_id |
US input: fallback provider answered without a DPV code after an undetermined answer was held (answer kept, GH #258) |
INFO |
services.validation.chain_provider |
provider class name, discarded status, request_id |
| Validation outcome (every validate request) | INFO |
services.validation.cache_provider |
provider=, status=, cache_hit=, request_id |
| Audit invariant violated (NULL fields on 2xx validate) | WARNING |
middleware.audit |
endpoint=, missing field names, request_id |
| libpostal sidecar reachable at boot | INFO |
main |
libpostal_url |
| libpostal sidecar not reachable at boot (starts degraded; CA parse → 503) | WARNING |
main |
libpostal_url, reason — exception class name (RemoteProtocolError, ConnectError, ReadTimeout, RuntimeError) or HTTP <status>, never str(exc) (#244) |
libpostal sidecar unavailable (any httpx.RequestError, incl. disconnect during warmup — #239) |
WARNING |
services.libpostal_client |
httpx error message (never carries the request URL), request_id |
| libpostal sidecar non-2xx | WARNING |
services.libpostal_client |
status code only — str(HTTPStatusError) embeds the address (#185), request_id |
libpostal client closed (RuntimeError) |
WARNING |
services.libpostal_client |
httpx error message (fixed text, no URL), request_id |
| libpostal sidecar non-JSON body / unexpected JSON shape | WARNING |
services.libpostal_client |
fixed message — the body is a parse of the address, request_id |
| Loggers | Controlled by | Default |
|---|---|---|
address_validator.* and every other app/library logger (via root) |
LOG_LEVEL env var, applied by configure_logging() at main import |
INFO |
uvicorn, uvicorn.access, uvicorn.error |
uvicorn's --log-level flag; otherwise log_config.json |
INFO |
httpx, httpcore |
pinned — not configurable (see below) | WARNING |
--log-level does not affect app loggers. Uvicorn applies it to uvicorn.error, uvicorn.access, and uvicorn.asgi only — it never touches the root logger. Use LOG_LEVEL for the app tree:
# systemd: add to /etc/address-validator/.env, then restart
LOG_LEVEL=DEBUGlog_config.json's root.level only governs the handful of lines uvicorn emits before it imports the app; configure_logging() runs after dictConfig and is what decides app verbosity thereafter. An unrecognized LOG_LEVEL — or NOTSET, which on root means "emit everything from every library" and is not what an operator writing it intends — falls back to INFO and logs a WARNING naming the rejected value. A typo must not take the service down at boot, but it must not pass silently either.
DEBUG off in production.
httpx and httpcore are held at WARNING regardless of LOG_LEVEL, in core/logging.py::PINNED_LOGGER_LEVELS and mirrored in log_config.json so the uvicorn boot path applies them too.
httpx logs the full request URL at INFO, and the libpostal sidecar call is GET /parse?address=<the user's address> (services/libpostal_client.py) — so an unpinned httpx writes Canadian address content verbatim into every log line, breaking the no-PII-at-INFO+ rule. httpcore adds connection and header detail at DEBUG for the same requests.
The pin is deliberately not derived from LOG_LEVEL: raising app verbosity to debug a parse must not be able to reopen a PII leak. Real transport failures still surface — WARNING and above pass through. tests/unit/core/test_logging.py::TestPiiPinnedLoggers pins all of this, including that the JSON config mirrors the Python constant.
A side benefit: because these two are pinned, LOG_LEVEL=DEBUG is effectively app-scoped and readable rather than drowned in per-request transport chatter.
USPS and Google are unaffected — they POST, so the address is in the request body and httpx logs only method and URL.
Recon extras= carries structural labels only (key names, length buckets, type names) — never raw USPS values. PII safety is enforced by _summarise_shape in services/validation/usps_client.py.
Raw values from a validation response body reach a log line in only these places, each with a bound (GH #254):
- DPV codes, in the unrecognised-DPV warnings and as recon
dpv=. Logged verbatim only when code-sized (≤ 2 characters,_DPV_CODE_MAX_LOG_LENinservices/validation/_helpers.py). A longer value could be address text: the warning logs only its length, recon shows<long>, and all long values share one dedup signature. - Google
cassProcessed, on theerrorMessagewarning. It is logged only as a bool (or absent); any other value is shown by its type name. The text ofuspsData.errorMessageitself is never logged.
New modules: one getLogger(__name__) per module; caplog assertions in corresponding unit tests.