375 lines
11 KiB
Python
375 lines
11 KiB
Python
"""Structured logging — structlog JSON + correlation_id propagation.
|
|
|
|
The correlation_id is the spine of every log line in the event-driven system.
|
|
It is set:
|
|
- in the api by middleware (from `X-Correlation-ID` header or minted),
|
|
- in workers by the consumer base (from the RabbitMQ message header
|
|
`x-correlation-id`),
|
|
so a single upload's logs trace api → rabbit → worker-extract →
|
|
worker-analyze → DB under one id.
|
|
|
|
Additional global context (service, env, version) is bound at startup and
|
|
inherited by every logger. Per-request/job attributes can be added with
|
|
`bind_context(**extra)`.
|
|
|
|
Conventions for service authors:
|
|
- event names are snake_case.
|
|
- log at the start of every significant stage with the relevant ids
|
|
(document_id, user_id, s3_key) so a stuck job can be traced.
|
|
- log success once per handled message with decision/outcome metrics.
|
|
- log failures with exc_info=True so full traceback is captured.
|
|
- use `log_error()` for structured exception capture.
|
|
"""
|
|
|
|
from __future__ import annotations
|
|
|
|
import contextvars
|
|
import logging
|
|
import os
|
|
import sys
|
|
import time
|
|
import traceback
|
|
import uuid
|
|
|
|
import structlog
|
|
from structlog.stdlib import BoundLogger
|
|
from structlog.types import EventDict, WrappedLogger
|
|
|
|
correlation_id_var: contextvars.ContextVar[str] = contextvars.ContextVar(
|
|
"correlation_id", default=""
|
|
)
|
|
service_var: contextvars.ContextVar[str] = contextvars.ContextVar("service", default="")
|
|
env_var: contextvars.ContextVar[str] = contextvars.ContextVar("env", default="")
|
|
|
|
|
|
def set_correlation_id(value: str | None) -> None:
|
|
"""Set the correlation id for the current async context."""
|
|
correlation_id_var.set(value or "")
|
|
|
|
|
|
def get_correlation_id() -> str:
|
|
"""Return the current correlation id ("" if unset)."""
|
|
return correlation_id_var.get()
|
|
|
|
|
|
def new_correlation_id() -> str:
|
|
"""Mint a new correlation id and bind it to the current context."""
|
|
cid = str(uuid.uuid4())
|
|
set_correlation_id(cid)
|
|
return cid
|
|
|
|
|
|
def set_service(value: str | None) -> None:
|
|
"""Bind the service name to the current logging context."""
|
|
service_var.set(value or "")
|
|
|
|
|
|
def set_env(value: str | None) -> None:
|
|
"""Bind the runtime environment to the current logging context."""
|
|
env_var.set(value or "")
|
|
|
|
|
|
def bind_context(**kwargs: object) -> None:
|
|
"""Bind extra key/value pairs to the current structlog context.
|
|
|
|
These appear in every subsequent log line in this context until cleared.
|
|
"""
|
|
structlog.contextvars.bind_contextvars(**{k: v for k, v in kwargs.items() if v is not None})
|
|
|
|
|
|
def clear_context() -> None:
|
|
"""Clear all structlog contextvars (use with care, mostly for tests)."""
|
|
structlog.contextvars.clear_contextvars()
|
|
correlation_id_var.set("")
|
|
service_var.set("")
|
|
env_var.set("")
|
|
|
|
|
|
def _inject_static_context(
|
|
_logger: WrappedLogger, _method_name: str, event_dict: EventDict
|
|
) -> EventDict:
|
|
cid = correlation_id_var.get()
|
|
if cid:
|
|
event_dict["correlation_id"] = cid
|
|
service = service_var.get()
|
|
if service:
|
|
event_dict["service"] = service
|
|
env = env_var.get()
|
|
if env:
|
|
event_dict["env"] = env
|
|
return event_dict
|
|
|
|
|
|
def _add_version(_logger: WrappedLogger, _method_name: str, event_dict: EventDict) -> EventDict:
|
|
version = os.getenv("APP_VERSION", "unknown")
|
|
if version:
|
|
event_dict["version"] = version
|
|
return event_dict
|
|
|
|
|
|
def _format_exc_info(_logger: WrappedLogger, _method_name: str, event_dict: EventDict) -> EventDict:
|
|
"""Attach a full, structured exception payload when an exception is in flight.
|
|
|
|
Unlike the default structlog processor this never truncates the traceback
|
|
and always separates exception class, message, and traceback so log parsers
|
|
can group by exception_type.
|
|
"""
|
|
exc_info = event_dict.get("exc_info", False)
|
|
if not exc_info:
|
|
return event_dict
|
|
|
|
if isinstance(exc_info, bool):
|
|
exc_info = sys.exc_info()
|
|
|
|
if exc_info is None or exc_info == (None, None, None):
|
|
event_dict.pop("exc_info", None)
|
|
return event_dict
|
|
|
|
exc_type, exc_value, exc_tb = exc_info
|
|
if exc_value is None:
|
|
event_dict.pop("exc_info", None)
|
|
return event_dict
|
|
|
|
event_dict["exception_type"] = exc_type.__name__ if exc_type else "UnknownException"
|
|
event_dict["exception_message"] = str(exc_value)
|
|
event_dict["exception_module"] = (
|
|
exc_type.__module__ if exc_type and exc_type.__module__ != "builtins" else None
|
|
)
|
|
event_dict["exception_traceback"] = "".join(
|
|
traceback.format_exception(exc_type, exc_value, exc_tb)
|
|
)
|
|
event_dict["exc_info"] = False
|
|
return event_dict
|
|
|
|
|
|
def _filter_sensitive_keys(
|
|
_logger: WrappedLogger, _method_name: str, event_dict: EventDict
|
|
) -> EventDict:
|
|
"""Redact obvious secrets from log payloads when they leak into keyword args."""
|
|
sensitive = {"api_key", "token", "secret", "password", "authorization"}
|
|
for key in event_dict:
|
|
if any(s in key.lower() for s in sensitive):
|
|
value = event_dict[key]
|
|
if isinstance(value, str) and value:
|
|
event_dict[key] = value[:4] + "***"
|
|
return event_dict
|
|
|
|
|
|
def configure_logging(
|
|
level: str = "INFO",
|
|
*,
|
|
json_output: bool = True,
|
|
service: str = "contract-check",
|
|
env: str = "dev",
|
|
) -> None:
|
|
"""Configure structlog + stdlib logging.
|
|
|
|
json_output=True (staging/prod) → JSON renderer; False (dev) → colored console.
|
|
service and env are bound globally so every log line carries them.
|
|
"""
|
|
set_service(service)
|
|
set_env(env)
|
|
|
|
processors: list[structlog.types.Processor] = [
|
|
structlog.contextvars.merge_contextvars,
|
|
structlog.processors.add_log_level,
|
|
structlog.processors.TimeStamper(fmt="iso", utc=True),
|
|
_inject_static_context,
|
|
_add_version,
|
|
structlog.processors.StackInfoRenderer(),
|
|
_format_exc_info,
|
|
_filter_sensitive_keys,
|
|
]
|
|
processors.append(
|
|
structlog.processors.JSONRenderer(sort_keys=True)
|
|
if json_output
|
|
else structlog.dev.ConsoleRenderer(colors=True, pad_event=False)
|
|
)
|
|
|
|
structlog.configure(
|
|
processors=processors,
|
|
wrapper_class=structlog.make_filtering_bound_logger(_level_to_int(level)),
|
|
context_class=dict,
|
|
logger_factory=structlog.PrintLoggerFactory(file=sys.stderr),
|
|
cache_logger_on_first_use=True,
|
|
)
|
|
# Route stdlib logging through structlog so third-party libs match our format.
|
|
stdlib_handler = logging.StreamHandler(sys.stderr)
|
|
stdlib_handler.setFormatter(
|
|
structlog.stdlib.ProcessorFormatter(
|
|
processor=processors[-1],
|
|
foreign_pre_chain=processors[:-1],
|
|
)
|
|
)
|
|
root_logger = logging.getLogger()
|
|
root_logger.handlers.clear()
|
|
root_logger.addHandler(stdlib_handler)
|
|
root_logger.setLevel(_level_to_int(level))
|
|
|
|
|
|
def _level_to_int(level: str) -> int:
|
|
return getattr(logging, level.upper(), logging.INFO)
|
|
|
|
|
|
def get_logger(name: str | None = None) -> BoundLogger:
|
|
"""Return a bound structlog logger."""
|
|
logger = structlog.get_logger(name)
|
|
return logger # type: ignore[no-any-return]
|
|
|
|
|
|
def is_debug_enabled() -> bool:
|
|
"""True when DEBUG-level records are emitted under the current configuration.
|
|
|
|
structlog's filtering bound logger exposes no ``isEnabledFor``; both it and
|
|
the stdlib root logger are set to the same level in :func:`configure_logging`,
|
|
so the root logger is the authoritative level source. Call this instead of
|
|
touching stdlib ``logging`` from feature code.
|
|
"""
|
|
return logging.getLogger().isEnabledFor(logging.DEBUG)
|
|
|
|
|
|
def log_error(
|
|
logger: BoundLogger,
|
|
event: str,
|
|
exc: BaseException | None = None,
|
|
**kwargs: object,
|
|
) -> None:
|
|
"""Structured error helper: captures full traceback and exception fields."""
|
|
if exc is not None:
|
|
kwargs["exc_info"] = (type(exc), exc, exc.__traceback__)
|
|
logger.error(event, **kwargs)
|
|
|
|
|
|
class Timer:
|
|
"""Context manager that records elapsed wall time for an operation.
|
|
|
|
Logs start at entry, success at exit, and failure when an exception is raised.
|
|
"""
|
|
|
|
def __init__(self, logger: BoundLogger, operation: str, **kwargs: object) -> None:
|
|
self.logger = logger
|
|
self.operation = operation
|
|
self.kwargs = kwargs
|
|
self.start_time: float = 0.0
|
|
self.end_time: float = 0.0
|
|
|
|
def __enter__(self) -> Timer:
|
|
self.start_time = time.perf_counter()
|
|
self.logger.debug(f"{self.operation}_started", **self.kwargs)
|
|
return self
|
|
|
|
def __exit__(self, exc_type, exc_val, exc_tb) -> None: # type: ignore[no-untyped-def]
|
|
self.end_time = time.perf_counter()
|
|
duration_ms = (self.end_time - self.start_time) * 1000
|
|
if exc_type is None:
|
|
self.logger.info(
|
|
f"{self.operation}_complete",
|
|
duration_ms=round(duration_ms, 2),
|
|
**self.kwargs,
|
|
)
|
|
else:
|
|
self.logger.error(
|
|
f"{self.operation}_failed",
|
|
duration_ms=round(duration_ms, 2),
|
|
exception_type=exc_type.__name__ if exc_type else None,
|
|
**self.kwargs,
|
|
)
|
|
|
|
|
|
def log_db_operation(
|
|
logger: BoundLogger,
|
|
operation: str,
|
|
table: str,
|
|
**kwargs: object,
|
|
) -> None:
|
|
"""Structured DB operation log."""
|
|
logger.info(f"db_{operation}_{table}", **kwargs)
|
|
|
|
|
|
def log_external_call(
|
|
logger: BoundLogger,
|
|
service: str,
|
|
operation: str,
|
|
**kwargs: object,
|
|
) -> None:
|
|
"""Structured external service call log."""
|
|
logger.info(
|
|
f"external_call_{service}_{operation}",
|
|
**kwargs,
|
|
)
|
|
|
|
|
|
def log_message_processing(
|
|
logger: BoundLogger,
|
|
state: str,
|
|
queue: str,
|
|
correlation_id: str,
|
|
**kwargs: object,
|
|
) -> None:
|
|
"""Log that a worker is processing a broker message."""
|
|
logger.info(
|
|
"message_processing",
|
|
state=state,
|
|
queue=queue,
|
|
correlation_id=correlation_id,
|
|
**kwargs,
|
|
)
|
|
|
|
|
|
def log_performance_metric(
|
|
logger: BoundLogger,
|
|
metric: str,
|
|
value: float,
|
|
unit: str,
|
|
**kwargs: object,
|
|
) -> None:
|
|
"""Log a numeric performance/funnel metric."""
|
|
logger.info(
|
|
"performance_metric",
|
|
metric=metric,
|
|
value=round(value, 4),
|
|
unit=unit,
|
|
**kwargs,
|
|
)
|
|
|
|
|
|
def log_stage_complete(
|
|
logger: BoundLogger,
|
|
stage: str,
|
|
duration_ms: float,
|
|
**kwargs: object,
|
|
) -> None:
|
|
"""Log completion of a named processing stage."""
|
|
logger.info(
|
|
f"stage_{stage}_complete",
|
|
duration_ms=round(duration_ms, 2),
|
|
**kwargs,
|
|
)
|
|
|
|
|
|
def log_stage_failure(
|
|
logger: BoundLogger,
|
|
stage: str,
|
|
exc: BaseException,
|
|
**kwargs: object,
|
|
) -> None:
|
|
"""Log failure of a named processing stage."""
|
|
logger.error(
|
|
f"stage_{stage}_failure",
|
|
error=f"{type(exc).__name__}: {exc}",
|
|
**kwargs,
|
|
)
|
|
|
|
|
|
def log_stage_progress(
|
|
logger: BoundLogger,
|
|
stage: str,
|
|
label: str,
|
|
**kwargs: object,
|
|
) -> None:
|
|
"""Log progress of a long-running named processing stage."""
|
|
logger.info(
|
|
f"stage_{stage}_progress",
|
|
label=label,
|
|
**kwargs,
|
|
)
|