AnoobFeng e3e5c73b03
feat(observability): add trace-id correlation and enhanced logging (#3902)
* feat(observability): add trace-id correlation and enhanced logging

- add opt-in gateway request trace correlation via X-Trace-Id
- enhance logging with configurable trace_id-aware formatting
- propagate deerflow_trace_id into runtime context and Langfuse metadata
- keep enhanced logging disabled by default to preserve existing behavior

* fix: harden trace correlation wiring

- Make logging enhancement a restart-required startup snapshot and remove per-request config reads from TraceMiddleware
- Restrict trace ids to printable ASCII before writing them to response headers, logs, and Langfuse metadata
- Gate implicit DeerFlowClient trace-id creation behind logging.enhance.enabled while preserving explicit caller opt-in
- Bind embedded client trace context per stream step to avoid generator ContextVar leaks and cross-context reset errors
- Rebind memory update trace ids in Timer/executor worker paths so enhanced logs keep the captured correlation id
- Remove unrelated __run_journal context overwrite from the trace-correlation change set

* fix(gateway): avoid eager app construction on package import

* fix(gateway): avoid config load during app import

Keep Gateway app construction import-safe when config.yaml is absent by
disabling TraceMiddleware only for that construction-time fallback path.
Startup lifespan still performs strict config loading before serving.
2026-07-03 08:01:46 +08:00

110 lines
3.9 KiB
Python

"""Logging setup helpers for DeerFlow."""
from __future__ import annotations
import json
import logging
from datetime import UTC, datetime
from typing import Any
from deerflow.config.app_config import apply_logging_level
from deerflow.trace_context import get_current_trace_id
DEFAULT_LOG_DATE_FORMAT = "%Y-%m-%d %H:%M:%S"
DEFAULT_LOG_FORMAT = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
TRACE_TEXT_LOG_FORMAT = "%(asctime)s - %(name)s - %(levelname)s - [trace_id=%(trace_id)s] - %(message)s"
_TRACE_FILTER_NAME = "deerflow_trace_context_filter"
class TraceContextFilter(logging.Filter):
"""Inject the current request trace id into every log record."""
name = _TRACE_FILTER_NAME
def filter(self, record: logging.LogRecord) -> bool:
record.trace_id = get_current_trace_id() or "-"
return True
class JsonTraceFormatter(logging.Formatter):
"""Small JSON formatter used when ``logging.enhance.format=json``."""
_deerflow_trace_formatter = True
def format(self, record: logging.LogRecord) -> str:
if not hasattr(record, "trace_id"):
record.trace_id = get_current_trace_id() or "-"
payload: dict[str, Any] = {
"timestamp": datetime.fromtimestamp(record.created, UTC).isoformat(),
"logger": record.name,
"level": record.levelname,
"trace_id": record.trace_id,
"message": record.getMessage(),
}
if record.exc_info:
payload["exc_info"] = self.formatException(record.exc_info)
if record.stack_info:
payload["stack_info"] = self.formatStack(record.stack_info)
return json.dumps(payload, ensure_ascii=False)
class TraceTextFormatter(logging.Formatter):
"""Marker subclass so trace formatting can be reverted cleanly in tests."""
_deerflow_trace_formatter = True
def _ensure_root_handler() -> None:
if logging.root.handlers:
return
logging.basicConfig(level=logging.INFO, format=DEFAULT_LOG_FORMAT, datefmt=DEFAULT_LOG_DATE_FORMAT)
def _has_trace_filter(handler: logging.Handler) -> bool:
return any(getattr(f, "name", None) == _TRACE_FILTER_NAME or isinstance(f, TraceContextFilter) for f in handler.filters)
def _install_trace_filter(handler: logging.Handler) -> None:
if not _has_trace_filter(handler):
handler.addFilter(TraceContextFilter())
def _remove_trace_filter(handler: logging.Handler) -> None:
handler.filters = [f for f in handler.filters if not (getattr(f, "name", None) == _TRACE_FILTER_NAME or isinstance(f, TraceContextFilter))]
def _default_formatter() -> logging.Formatter:
return logging.Formatter(DEFAULT_LOG_FORMAT, datefmt=DEFAULT_LOG_DATE_FORMAT)
def _trace_formatter(format_name: str | None) -> logging.Formatter:
if (format_name or "text").strip().lower() == "json":
return JsonTraceFormatter()
return TraceTextFormatter(TRACE_TEXT_LOG_FORMAT, datefmt=DEFAULT_LOG_DATE_FORMAT)
def configure_logging(config: object) -> None:
"""Configure DeerFlow logging from an AppConfig-like object.
With logging enhancement disabled this preserves the previous
``basicConfig + apply_logging_level`` behavior. With enhancement enabled,
root handlers gain a trace-context filter and a formatter that includes
only the additional ``trace_id`` field.
"""
_ensure_root_handler()
logging_config = getattr(config, "logging", None)
enhance = getattr(logging_config, "enhance", None)
enhanced = bool(getattr(enhance, "enabled", False))
for handler in logging.root.handlers:
if enhanced:
_install_trace_filter(handler)
handler.setFormatter(_trace_formatter(getattr(enhance, "format", "text")))
else:
_remove_trace_filter(handler)
if getattr(handler.formatter, "_deerflow_trace_formatter", False):
handler.setFormatter(_default_formatter())
apply_logging_level(getattr(config, "log_level", None))