""" Application logging configuration. Emits JSON logs in the shape required by the internal OCI Logging policy (doc 1330576): top-level ``service``/``correlation``/``operation`` blocks, ``source_channel``/``conversation_start_time_ts``/``requesting_agent`` for conversation context, plus split streams (``< ERROR`` -> stdout, ``>= ERROR`` -> stderr) so the OCI Unified Monitoring Agent can ingest both. The transport itself is just stdout/stderr; the OCI Logging Agent provisioned by infra is responsible for shipping records out of the container. Uses a small local StructuredLogger compatibility helper for formatter setup. """ import json import logging import sys import time from contextvars import ContextVar from datetime import datetime, timezone from typing import Any, Dict, Optional class StructuredLogger: # minimal compatibility for text formatter helper def __init__(self, name: str = "app", use_json: bool = False): import logging as _logging self.logger = _logging.getLogger(name) from src.core.config import settings _request_id_var: ContextVar[Optional[str]] = ContextVar("request_id", default=None) _session_id_var: ContextVar[Optional[str]] = ContextVar("session_id", default=None) _user_id_var: ContextVar[Optional[str]] = ContextVar("user_id", default=None) _trace_id_var: ContextVar[Optional[str]] = ContextVar("trace_id", default=None) _span_id_var: ContextVar[Optional[str]] = ContextVar("span_id", default=None) _source_channel_var: ContextVar[Optional[str]] = ContextVar("source_channel", default=None) _conversation_start_var: ContextVar[Optional[str]] = ContextVar("conversation_start_time_ts", default=None) _requesting_agent_var: ContextVar[Optional[str]] = ContextVar("requesting_agent", default=None) _configured: bool = False _STD_LOGRECORD_ATTRS = frozenset({ "name", "msg", "args", "levelname", "levelno", "pathname", "filename", "module", "exc_info", "exc_text", "stack_info", "lineno", "funcName", "created", "msecs", "relativeCreated", "thread", "threadName", "processName", "process", "message", "asctime", "taskName", "request_id", "session_id", "user_id", "trace_id", "span_id", "source_channel", "conversation_start_time_ts", "requesting_agent", }) def _current_otel_ids() -> tuple[Optional[str], Optional[str]]: """Return (trace_id, span_id) from the active OTEL span, or (None, None). Langfuse's start_as_current_observation creates real OTEL spans; reading them here means logs emitted from inside a node/tool automatically pick up the same trace_id/span_id that appear in Langfuse — no plumbing through contextvars. """ try: from opentelemetry import trace as otel_trace span = otel_trace.get_current_span() if span is None: return None, None span_context = span.get_span_context() if not span_context or not span_context.is_valid: return None, None return format(span_context.trace_id, "032x"), format(span_context.span_id, "016x") except Exception: return None, None class _InvalidGrantFilter(logging.Filter): """Drops repeated PubSub/GCP `invalid_grant` errors that flood local dev. These come from `agent_framework.observer.api` publish callbacks when GCP credentials are absent or expired. The transport error is intentional in that environment — suppressing keeps logs readable without hiding genuine PubSub errors (other `Falha callback PubSub` messages still pass through). """ def filter(self, record: logging.LogRecord) -> bool: try: message = record.getMessage() except Exception: return True return "invalid_grant" not in message class ContextFilter(logging.Filter): """Injects correlation/conversation context from contextvars onto each record.""" def filter(self, record: logging.LogRecord) -> bool: record.request_id = _request_id_var.get() record.session_id = _session_id_var.get() record.user_id = _user_id_var.get() otel_trace_id, otel_span_id = _current_otel_ids() record.trace_id = otel_trace_id or _trace_id_var.get() record.span_id = otel_span_id or _span_id_var.get() record.source_channel = _source_channel_var.get() record.conversation_start_time_ts = _conversation_start_var.get() record.requesting_agent = _requesting_agent_var.get() return True def _iso_utc_now() -> str: return datetime.now(timezone.utc).isoformat(timespec="milliseconds").replace("+00:00", "Z") class _StructuredFormatter(logging.Formatter): """Renders records in the layout defined by the OCI Logging policy document.""" def __init__(self, use_json: bool): super().__init__() self.use_json = use_json # Helper kept only for its text-mode formatter, so framework-internal # logs and app logs match when JSON is off. self._helper = StructuredLogger(name="__formatter__", use_json=False) self._helper.logger.handlers.clear() self._helper.logger.propagate = False def format(self, record: logging.LogRecord) -> str: message = record.getMessage() request_id = getattr(record, "request_id", None) session_id = getattr(record, "session_id", None) user_id = getattr(record, "user_id", None) trace_id = getattr(record, "trace_id", None) span_id = getattr(record, "span_id", None) source_channel = getattr(record, "source_channel", None) conversation_start = getattr(record, "conversation_start_time_ts", None) requesting_agent = getattr(record, "requesting_agent", None) extras = { k: v for k, v in record.__dict__.items() if k not in _STD_LOGRECORD_ATTRS and not k.startswith("_") } operation = extras.pop("operation", None) component_override = extras.pop("component", None) payload = extras.pop("payload", None) or (extras or None) component = component_override or record.name.rsplit(".", 1)[-1] if self.use_json: obj: Dict[str, Any] = { "timestamp": _iso_utc_now(), "level": record.levelname, "logger": record.name, "message": message, "source_channel": source_channel, "conversation_start_time_ts": conversation_start, "requesting_agent": requesting_agent, "service": { "name": settings.APP_NAME, "version": settings.VERSION, "component": component, "agent_type": settings.AGENT_TYPE, }, "correlation": { "trace_id": trace_id, "request_id": request_id, "span_id": span_id, "session_id": session_id, }, "user_id": user_id, } if operation is not None: obj["operation"] = operation if payload is not None: obj["payload"] = payload if record.exc_info: obj["exception"] = self.formatException(record.exc_info) return json.dumps(obj, ensure_ascii=False, default=str) timestamp = datetime.now(timezone.utc).strftime("%Y-%m-%d %H:%M:%S") text = f"{timestamp} - {record.name} - {record.levelname} - {message}" text += ( f" | trace_id={trace_id} request_id={request_id}" f" session_id={session_id} user_id={user_id}" ) if operation is not None: status = operation.get("status") name = operation.get("name") text += f" | operation={name}/{status}" execution_time = operation.get("execution_time") if execution_time is not None: text += f" execution_time={execution_time}" if record.exc_info: text += "\n" + self.formatException(record.exc_info) return text def _resolve_level(value: Any) -> int: if isinstance(value, int): return value return getattr(logging, str(value).upper(), logging.INFO) def _build_handler(stream, level: int, use_json: bool, error_only: bool) -> logging.Handler: handler = logging.StreamHandler(stream) handler.setLevel(level) handler.setFormatter(_StructuredFormatter(use_json=use_json)) handler.addFilter(ContextFilter()) if error_only: handler.addFilter(lambda record: record.levelno >= logging.ERROR) else: handler.addFilter(lambda record: record.levelno < logging.ERROR) return handler def setup_logging( log_level: Optional[str] = None, log_format: Optional[str] = None, ) -> logging.Logger: """Configure the root logger once; subsequent calls only adjust level/format.""" global _configured level_str = (log_level or settings.LOG_LEVEL) fmt_str = (log_format or settings.LOG_FORMAT).lower() level = _resolve_level(level_str) use_json = fmt_str == "json" root = logging.getLogger() if _configured: root.setLevel(level) for h in root.handlers: # Stderr handler is pinned to ERROR; only stdout follows the configured level. if getattr(h, "_logs_below_error", False): h.setLevel(level) h.setFormatter(_StructuredFormatter(use_json=use_json)) return root for h in list(root.handlers): root.removeHandler(h) stdout_handler = _build_handler(sys.stdout, level, use_json, error_only=False) stdout_handler._logs_below_error = True # type: ignore[attr-defined] stderr_handler = _build_handler(sys.stderr, logging.ERROR, use_json, error_only=True) root.addHandler(stdout_handler) root.addHandler(stderr_handler) root.setLevel(level) # Force most third-party loggers to propagate through root so they share the # same JSON shape. Strip handlers they install on import (oci, langfuse). for name in ( "oci", "oci.circuit_breaker", "langfuse", "httpx", "httpcore", "pymongo", "urllib3", ): lg = logging.getLogger(name) for h in list(lg.handlers): lg.removeHandler(h) lg.propagate = True # Uvicorn keeps its own (colored, human-friendly) handlers so the terminal # stays readable in dev. We set propagate=False to avoid duplicating each # access/error line through our JSON pipeline. In prod the OCI Logging Agent # still ingests these lines from stdout/stderr; they just won't be in our # JSON shape — that's a deliberate trade-off for terminal readability. for name in ("uvicorn", "uvicorn.access"): logging.getLogger(name).propagate = False noisy_level = _resolve_level(settings.LOG_NOISY_LEVEL) for noisy in ( "httpx", "httpcore", "urllib3", "urllib3.connectionpool", "pymongo", "pymongo.serverSelection", "pymongo.topology", "pymongo.command", "pymongo.connection", "pymongo.heartbeat", "uvicorn.access", "agent_framework.observer.api", ): logging.getLogger(noisy).setLevel(noisy_level) # grpc._plugin_wrapping emits repeated ERROR logs when Google credentials are # absent or expired (e.g. local dev without GOOGLE_APPLICATION_CREDENTIALS). # The actual failure surfaces as SpeechClientError to the caller — suppress here. logging.getLogger("grpc._plugin_wrapping").setLevel(logging.CRITICAL) # agent_framework.observer.api retries PubSub publishes on every event; when # GCP credentials are absent/expired the future callback raises "invalid_grant" # repeatedly. Drop only those — other PubSub errors stay visible. logging.getLogger("agent_framework.observer.api").addFilter(_InvalidGrantFilter()) _configured = True return root def setup_logging_from_settings() -> logging.Logger: """Backwards-compatible alias.""" return setup_logging() def get_logger(name: str) -> logging.Logger: """Return a stdlib logger that propagates to the configured root.""" if not _configured: setup_logging() return logging.getLogger(name) # --------------------------------------------------------------------------- # Context variable accessors # --------------------------------------------------------------------------- def get_request_id() -> Optional[str]: return _request_id_var.get() def set_request_id(value: Optional[str]) -> None: _request_id_var.set(value) def set_session_id(value: Optional[str]) -> None: _session_id_var.set(value) def set_user_id(value: Optional[str]) -> None: _user_id_var.set(value) def set_trace_id(value: Optional[str]) -> None: _trace_id_var.set(value) def set_span_id(value: Optional[str]) -> None: _span_id_var.set(value) def set_source_channel(value: Optional[str]) -> None: _source_channel_var.set(value) def set_conversation_start_ts(value: Optional[str]) -> None: _conversation_start_var.set(value) def set_requesting_agent(value: Optional[str]) -> None: _requesting_agent_var.set(value) def clear_context() -> None: _request_id_var.set(None) _session_id_var.set(None) _user_id_var.set(None) _trace_id_var.set(None) _span_id_var.set(None) _source_channel_var.set(None) _conversation_start_var.set(None) _requesting_agent_var.set(None) # --------------------------------------------------------------------------- # Operation helper (start/success/failed pattern from the OCI Logging policy) # --------------------------------------------------------------------------- class log_operation: """ Context manager that emits ``started``/``success``/``failed`` logs around an operation, populating the ``operation`` block defined by the OCI Logging policy (name, status, execution_time, plus any custom fields). Works as both ``with`` and ``async with`` so it can be used uniformly in sync and async code paths. Example:: async with log_operation("process", component="llm_node") as op: op.add_field("message_count", len(state["messages"])) response = await llm.ainvoke(...) op.add_field("response_length", len(response.content)) On exception, ``failed`` is logged with ``exc_info`` and the exception is re-raised. """ def __init__( self, name: str, *, component: Optional[str] = None, logger: Optional[logging.Logger] = None, start_message: Optional[str] = None, success_message: Optional[str] = None, **fields: Any, ): self._name = name self._component = component self._logger = logger or get_logger("operation") self._fields: Dict[str, Any] = dict(fields) self._start_message = start_message or f"{name} started" self._success_message = success_message or f"{name} completed" self._start_time: Optional[float] = None def add_field(self, key: str, value: Any) -> None: """Attach a field to be emitted on subsequent operation logs.""" self._fields[key] = value def event(self, message: str, *, level: int = logging.INFO, **fields: Any) -> None: """Log a mid-operation event without closing the operation.""" op_block = {"name": self._name, "status": "in_progress", **self._fields, **fields} self._emit(level, message, op_block) def _emit(self, level: int, message: str, op_block: Dict[str, Any], **kwargs: Any) -> None: extra: Dict[str, Any] = {"operation": op_block} if self._component: extra["component"] = self._component self._logger.log(level, message, extra=extra, **kwargs) def _elapsed(self) -> float: if self._start_time is None: return 0.0 return round(time.perf_counter() - self._start_time, 3) def _enter(self) -> "log_operation": self._start_time = time.perf_counter() self._emit( logging.INFO, self._start_message, {"name": self._name, "status": "started", **self._fields}, ) return self def _exit(self, exc_type, exc, tb) -> bool: elapsed = self._elapsed() if exc is not None: op_block = { "name": self._name, "status": "failed", "execution_time": elapsed, "error_type": type(exc).__name__, **self._fields, } self._emit( logging.ERROR, f"{self._name} failed: {exc}", op_block, exc_info=(exc_type, exc, tb), ) else: op_block = { "name": self._name, "status": "success", "execution_time": elapsed, **self._fields, } self._emit(logging.INFO, self._success_message, op_block) return False # never suppress exceptions def __enter__(self) -> "log_operation": return self._enter() def __exit__(self, exc_type, exc, tb) -> bool: return self._exit(exc_type, exc, tb) async def __aenter__(self) -> "log_operation": return self._enter() async def __aexit__(self, exc_type, exc, tb) -> bool: return self._exit(exc_type, exc, tb) class MetricsLogger: """ Lightweight timer/metrics helper. Kept for backwards compatibility — new code should prefer ``log_operation`` which already captures duration and follows the OCI Logging policy structure. """ def __init__(self, operation: str, logger: Optional[logging.Logger] = None): self.operation = operation self.logger = logger or get_logger("metrics") self.start_time: Optional[float] = None self.end_time: Optional[float] = None def start(self) -> "MetricsLogger": self.start_time = time.perf_counter() self.end_time = None return self def stop(self) -> float: if self.start_time is None: return 0.0 self.end_time = time.perf_counter() return self.end_time - self.start_time @property def elapsed_time(self) -> float: if self.start_time is None: return 0.0 end = self.end_time if self.end_time is not None else time.perf_counter() return end - self.start_time def log(self, level: int = logging.INFO, **metrics: Any) -> None: if self.start_time is not None and self.end_time is None: self.stop() payload: Dict[str, Any] = { "operation": self.operation, "elapsed_seconds": round(self.elapsed_time, 6), } payload.update(metrics) self.logger.log(level, f"Metrics: {self.operation}", extra={"payload": payload}) __all__ = [ "setup_logging", "setup_logging_from_settings", "get_logger", "get_request_id", "set_request_id", "set_session_id", "set_user_id", "set_trace_id", "set_span_id", "set_source_channel", "set_conversation_start_ts", "set_requesting_agent", "clear_context", "ContextFilter", "MetricsLogger", "log_operation", ]