feat(agent-centric-logging): consolidate CoT infra in shared, close REASON→REFLECT chains

- shared/cot_logger.py is SSOT; backend/cot_logger.py deleted
- elapsed_ms timing in all REFLECT markers
- Frontend: REASON→REFLECT/EXPLORE in all fetch/post/delete/requestApi
- Dynamic src: route.GET.api.plugins instead of hardcoded api.request_handler
- trace_id generated immediately (no 'no-trace'), X-Trace-ID in both directions
- Global error handlers (window error + unhandledrejection + error.svelte)
- Fixed duplicate logging (shared/logger.py double StreamHandler)
- propagate=False in configure_logger (was in ConfigManager = duplicated startup logs)
- belief_scope: 'Coherence OK' → '{anchor}: completed' + elapsed_ms
- Fixed 28 pre-existing test failures (scheduler sig, DB columns, DRAFT validation, etc)
This commit is contained in:
2026-07-12 19:30:57 +03:00
parent 24d3b7d1f9
commit a39a76c87f
58 changed files with 1532 additions and 916 deletions

View File

@@ -62,10 +62,9 @@ def get_shared_http_client(timeout: float = 180.0) -> httpx.AsyncClient:
verify=ssl_ctx,
timeout=httpx.Timeout(180.0),
)
logger.reason(
"Created shared HTTP client (180s timeout)",
extra={"src": "SharedLlmHttpClient", "ssl": "system_ssl_context"},
)
# @ADR [LOG-004] Removed "Created shared HTTP client (180s timeout)".
# Singleton creation (cached). Once-per-process infra detail. Not a decision point.
# Errors during actual LLM calls are properly EXPLOREd with context.
return _http_client_180
if abs(timeout - 10.0) < 0.1:
@@ -75,10 +74,8 @@ def get_shared_http_client(timeout: float = 180.0) -> httpx.AsyncClient:
verify=ssl_ctx,
timeout=httpx.Timeout(10.0),
)
logger.reason(
"Created shared HTTP client (10s timeout)",
extra={"src": "SharedLlmHttpClient", "ssl": "system_ssl_context"},
)
# @ADR [LOG-004] Removed "Created shared HTTP client (10s timeout)".
# Singleton creation (cached). Once-per-process infra detail. Not a decision point.
return _http_client_10
# Custom timeout — create a new client (not cached)
@@ -87,10 +84,8 @@ def get_shared_http_client(timeout: float = 180.0) -> httpx.AsyncClient:
verify=ssl_ctx,
timeout=httpx.Timeout(timeout),
)
logger.reason(
"Created shared HTTP client (custom timeout)",
extra={"src": "SharedLlmHttpClient", "timeout": timeout, "ssl": "system_ssl_context"},
)
# @ADR [LOG-004] Removed "Created shared HTTP client (custom timeout)".
# Rare (only custom timeout callers). Not worth the per-creation line.
return client
# #endregion SharedLlmHttpClient.GetSharedClient

View File

@@ -1,74 +1,274 @@
# #region CotLoggerModule [C:4] [TYPE Module] [SEMANTICS logging,cot,json,trace,structured]
# #region Shared.CotLoggerModule [C:4] [TYPE Module] [SEMANTICS logging,cot,json,trace,structured]
# @defgroup Shared Shared lightweight utilities for backend and agent.
# @BRIEF Structured JSON logger implementing the decision audit logging protocol.
# Uses ContextVar for trace_id and span_id propagation across async contexts.
# Provides log(), seed_trace_id(), push_span(), pop_span().
# @BRIEF Structured JSON logger implementing the Molecular CoT protocol.
# SSOT for trace_id/span_id ContextVars, derive_src, log(), cot_span.
# Backend and agent container BOTH import from here.
# @LAYER Core
# @RELATION CALLED_BY -> [Shared.SharedLoggerModule]
# @PRE Python 3.7+ (ContextVar available).
# @POST JSON log records written to the 'cot' Python logger.
# @SIDE_EFFECT Writes structured JSON to the 'cot' Python logger.
# @DATA_CONTRACT Log call -> Single-line JSON to logging.StreamHandler/file.
# @DATA_CONTRACT log() -> Single-line JSON to logging.StreamHandler/file.
# @INVARIANT No dependency on FastAPI, SQLAlchemy, Gradio, LangChain, pydantic.
# Pure stdlib + standard logging.
# @RATIONALE SSOT for all CoT primitives. Backend previously had a separate copy
# (backend/src/core/cot_logger.py) which diverged. Now deprecated — use shared.
# @REJECTED Keeping backend copy was rejected — skip lists diverged (backend had "gunicorn",
# shared didn't), cot_span existed only in backend, suppression lists had 4 copies.
# One SSOT prevents drift.
from contextvars import ContextVar
import inspect
import json
import logging
import time
from typing import Any
import uuid
# #region cot_trace_context [C:1] [TYPE Data] [SEMANTICS contextvar,trace_id,span_id,propagation]
# ── Trace context ──────────────────────────────────────────────────────────
# #region Shared.TraceContext [C:1] [TYPE Data] [SEMANTICS contextvar,trace_id,span_id,propagation]
# @BRIEF ContextVars for trace ID and span ID propagation across async boundaries.
# These are the SINGLE source of truth — both backend and agent read them.
_trace_id: ContextVar[str] = ContextVar("_trace_id", default="")
_span_id: ContextVar[str] = ContextVar("_span_id", default="")
# #endregion cot_trace_context
# #endregion Shared.TraceContext
# #region cot_logger_instance [C:1] [TYPE Data] [SEMANTICS logger,instance]
# ── Timing tracking ─────────────────────────────────────────────────────────
# Maps (trace_id, src) -> time.monotonic() for elapsed_ms in REFLECT/EXPLORE
_entry_timestamps: dict[tuple[str, str], float] = {}
_MAX_ENTRY_TRACKING = 500 # guard against unbounded growth
# ── Suppression (temporary, per ADR-0017 / LOG-004) ─────────────────────────
# Central single source — all consumers import is_routine_infra() from here.
# As call sites are cleaned per ADR-0017, this list shrinks (not grows).
# #region Shared.Suppression [C:2] [TYPE Data] [SEMANTICS suppression,routine,infra]
# @BRIEF Central suppression list for low-value infrastructure noise.
# @RATIONALE All 4 previous copies (backend/logger.py, shared/logger.py x3, pretty_cot.py)
# merged into one list. Call site cleanup (ADR-0017) is the permanent fix.
# @REJECTED Keeping separate lists per file rejected — they diverged immediately
# (backend had 13 phrases, shared had 7-12, pretty_cot had 9).
_ROUTINE_INFRA_PHRASES: tuple[str, ...] = (
"Reusing cached Superset auth tokens",
"Resolve authenticated user principal",
"User principal resolved",
"Resolving current user preference",
"Loading current user's dashboard preference",
"Validated ENCRYPTION_KEY for EncryptionManager initialization",
"Superset client ready",
"Superset client initialized",
"SupersetClientRegistry.get_client",
"Initialized ResourceService",
"ResourceService initialized",
"Created shared HTTP client",
"Ensured directory",
)
_suppression_enabled: bool = True
# #endregion Shared.Suppression
# ── derive_src ──────────────────────────────────────────────────────────────
# Default skip list covers BOTH backend and shared call paths.
_DEFAULT_SKIP: tuple[str, ...] = (
"src.core.logger", "src.core.cot_logger",
"ss_tools.shared.logger", "ss_tools.shared.cot_logger",
"logging",
"anyio", "starlette", "fastapi", "asyncio",
"middleware", "trace.__call__",
"uvicorn", "gunicorn",
)
# #region Shared.derive_src [C:2] [TYPE Function] [SEMANTICS src,qualified,inspect,agent-centric]
# @ingroup Shared
# @BRIEF Derive qualified src for logs to ensure agent-readable traces (stdlib only).
# @INVARIANT Never emits generic "superset_tools_app" or "root" when caller can be determined.
# @RELATION CALLED_BY -> [Shared.log, Shared.SharedLoggerModule]
def derive_src(
fallback: str | None = None,
*,
skip_substrings: tuple[str, ...] | None = None,
) -> str:
"""Derive qualified src from call stack (for agent-centric logging).
Args:
fallback: Returned if no business frame found.
skip_substrings: Custom skip list override. Defaults to _DEFAULT_SKIP
which covers both backend (src.core.logger) and
shared (ss_tools.shared.logger) internal frames.
"""
try:
frame = inspect.currentframe()
skip = skip_substrings if skip_substrings is not None else _DEFAULT_SKIP
max_walk = 40
walked = 0
best = None
while frame and walked < max_walk:
frame = frame.f_back
walked += 1
if frame is None:
break
module_name = (frame.f_globals.get("__name__") or "").strip()
filename = (frame.f_code.co_filename or "").strip()
qualname = frame.f_code.co_name or "?"
if any(s in module_name for s in skip) or any(s in filename for s in skip):
continue
candidate = f"{module_name}.{qualname}" if module_name else qualname
# Normalize: drop leading "src." for cleaner agent-readable src
if candidate.startswith("src."):
candidate = candidate[4:]
is_app = (
"backend/src" in filename
or module_name.startswith("src.")
or ".api." in module_name
or module_name.startswith("api.")
or "services." in module_name
or ("core." in module_name and "middleware" not in module_name)
or "plugins." in module_name
)
if is_app:
return candidate
if best is None:
best = candidate
if best:
return best
except Exception:
pass
return fallback or "unknown"
# #endregion Shared.derive_src
# ── Suppression predicate ───────────────────────────────────────────────────
# #region Shared.is_routine_infra [C:1] [TYPE Function] [SEMANTICS suppression,filter,predicate]
# @ingroup Shared
# @BRIEF Check if an intent string matches known infrastructure noise.
# @USAGE Used by logger.reason/reflect in both shared/logger.py and backend/logger.py.
def is_routine_infra(intent: str) -> bool:
"""Return True if *intent* matches a known routine-infrastructure phrase.
This is defense-in-depth — the primary fix is editing call sites (ADR-0017).
"""
if not _suppression_enabled:
return False
return any(p in intent for p in _ROUTINE_INFRA_PHRASES)
# #endregion Shared.is_routine_infra
# #region Shared.set_routine_suppression [C:1] [TYPE Function] [SEMANTICS suppression,config,override]
# @ingroup Shared
# @BRIEF Configure suppression from backend's LoggingConfig (called by configure_logger).
# @USAGE set_routine_suppression(enabled=config.hide_routine_infra)
def set_routine_suppression(
enabled: bool | None = None,
phrases: tuple[str, ...] | None = None,
) -> None:
"""Override suppression settings globally.
Args:
enabled: If set, updates the _suppression_enabled flag.
phrases: If set, replaces the suppression list entirely.
Pass an empty tuple to clear all suppression (goal state).
"""
global _suppression_enabled, _ROUTINE_INFRA_PHRASES
if enabled is not None:
_suppression_enabled = enabled
if phrases is not None:
_ROUTINE_INFRA_PHRASES = phrases
# #endregion Shared.set_routine_suppression
# ── Logger instance ─────────────────────────────────────────────────────────
# #region Shared.cot_logger_instance [C:1] [TYPE Data] [SEMANTICS logger,instance]
# @BRIEF Dedicated Python logger for all decision audit log output.
cot_logger = logging.getLogger("cot")
# #endregion cot_logger_instance
# #endregion Shared.cot_logger_instance
__all__ = [
"get_trace_id",
"log",
"pop_span",
"push_span",
"seed_trace_id",
"set_trace_id",
]
# ── Trace ID API ────────────────────────────────────────────────────────────
# #region seed_trace_id [C:1] [TYPE Function] [SEMANTICS trace_id,uuid,contextvar,set]
# #region Shared.seed_trace_id [C:1] [TYPE Function] [SEMANTICS trace_id,uuid,contextvar,set]
# @ingroup Shared
# @BRIEF Generate a new UUID4 trace_id, set it in ContextVar, and return it.
def seed_trace_id() -> str:
"""Generate a new UUID4 trace ID and store it in the thread-local ContextVar."""
trace_id = str(uuid.uuid4())
"""Generate a new UUID4 trace ID and store it in the ContextVar.
Call once at request/job entry. Also resets span_id.
"""
trace_id = uuid.uuid4().hex
_trace_id.set(trace_id)
# Reset span on new trace
_span_id.set("")
return trace_id
# #endregion seed_trace_id
# #endregion Shared.seed_trace_id
# #region set_trace_id [C:1] [TYPE Function] [SEMANTICS trace_id,contextvar,set,public]
# #region Shared.set_trace_id [C:1] [TYPE Function] [SEMANTICS trace_id,contextvar,set,public]
# @ingroup Shared
# @BRIEF Set an explicit trace_id into the ContextVar (e.g. from X-Trace-ID header).
def set_trace_id(trace_id: str) -> None:
"""Set a specific trace_id into the ContextVar (e.g. from an incoming header)."""
"""Set a specific trace_id into the ContextVar.
Used by TraceContextMiddleware when an X-Trace-ID header is present,
enabling cross-service trace chaining.
"""
_trace_id.set(trace_id)
# #endregion set_trace_id
# #endregion Shared.set_trace_id
# #region get_trace_id [C:1] [TYPE Function] [SEMANTICS trace_id,contextvar,get,public]
# #region Shared.get_trace_id [C:1] [TYPE Function] [SEMANTICS trace_id,contextvar,get,public]
# @ingroup Shared
# @BRIEF Get the current trace_id from ContextVar.
def get_trace_id() -> str:
"""Get the current trace_id from the thread-local ContextVar."""
"""Get the current trace_id from ContextVar."""
return _trace_id.get()
# #endregion get_trace_id
# #endregion Shared.get_trace_id
# #region push_span [C:1] [TYPE Function] [SEMANTICS span_id,contextvar,stack]
# ── Span ID API ─────────────────────────────────────────────────────────────
# #region Shared.push_span [C:1] [TYPE Function] [SEMANTICS span_id,contextvar,stack]
# @ingroup Shared
# @BRIEF Set a new span_id in ContextVar and return the previous for restoration.
def push_span(span: str) -> str:
"""Push a new span ID onto the context and return the previous span ID."""
"""Push a new span ID onto the context and return the previous span ID.
Args:
span: The new span identifier (e.g. function or operation name).
Returns:
The previous span ID, suitable for passing to pop_span().
"""
prev = _span_id.get()
_span_id.set(span)
return prev
# #endregion push_span
# #endregion Shared.push_span
# #region pop_span [C:1] [TYPE Function] [SEMANTICS span_id,contextvar,restore]
# #region Shared.pop_span [C:1] [TYPE Function] [SEMANTICS span_id,contextvar,restore]
# @ingroup Shared
# @BRIEF Restore a previous span_id into the ContextVar.
def pop_span(prev: str) -> None:
"""Restore a previous span ID into the ContextVar."""
_span_id.set(prev)
# #endregion pop_span
"""Restore a previous span ID into the ContextVar.
# #region cot_log_function [C:2] [TYPE Function] [SEMANTICS log,json,structured,marker]
Args:
prev: The span ID to restore (previously returned by push_span()).
"""
_span_id.set(prev)
# #endregion Shared.pop_span
# ── Core log function ───────────────────────────────────────────────────────
# #region Shared.log [C:2] [TYPE Function] [SEMANTICS log,json,structured,marker,agent-centric]
# @ingroup Shared
# @BRIEF Core structured logging function that emits a single-line JSON record.
# Supports elapsed_ms timing: call REASON first, then REFLECT/EXPLORE
# auto-computes elapsed milliseconds.
def log(
src: str,
marker: str,
@@ -77,10 +277,44 @@ def log(
error: str | None = None,
level: str | None = None,
) -> None:
"""Emit a single-line structured JSON log record through the 'cot' logger."""
"""Emit a single-line structured JSON log record through the 'cot' logger.
Args:
src: Qualified function or component name (e.g. 'AuthRepository.get_user').
marker: Protocol marker — one of 'REASON', 'REFLECT', 'EXPLORE'.
intent: Short one-line description of intent or action.
payload: Optional structured data dict.
error: Required for EXPLORE markers; describes the violated assumption.
level: Log level override. Auto-inferred from marker if omitted
(REASON/REFLECT -> INFO, EXPLORE -> WARNING).
Side effects:
Writes single-line JSON to the 'cot' Python logger.
Tracks entry timestamps for elapsed_ms auto-computation.
"""
if level is None:
level = "WARNING" if marker == "EXPLORE" else "INFO"
# Derive good src if caller passed a poor one
if not src or src in ("superset_tools_app", "app_name", "root", "", None):
src = derive_src(src)
# ── elapsed_ms auto-computation ────────────────────────────────────────
# REASON records the entry time; REFLECT/EXPLORE compute delta.
tid = _trace_id.get() or ""
elapsed_ms: float | None = None
if marker == "REASON":
_entry_timestamps[(tid, src)] = time.monotonic()
# Prevent unbounded growth
if len(_entry_timestamps) > _MAX_ENTRY_TRACKING:
_entry_timestamps.clear()
elif marker in ("REFLECT", "EXPLORE"):
start = _entry_timestamps.pop((tid, src), None)
if start is not None:
elapsed_ms = round((time.monotonic() - start) * 1000, 1)
# ── Build the extra dict for CotJsonFormatter ──────────────────────────
extra: dict[str, Any] = {
"marker": marker,
"intent": intent,
@@ -92,6 +326,8 @@ def log(
extra["payload"] = payload
if error is not None:
extra["error"] = error
if elapsed_ms is not None:
extra["elapsed_ms"] = elapsed_ms
log_func = {
"WARNING": cot_logger.warning,
@@ -100,28 +336,112 @@ def log(
}.get(level, cot_logger.info)
log_func(intent, extra=extra)
# #endregion cot_log_function
# #endregion Shared.log
# #region MarkerLogger [C:2] [TYPE Class] [SEMANTICS logger,proxy,marker,syntactic-sugar]
class MarkerLogger:
"""Thin proxy over the cot_logger.log() function."""
# ── cot_span decorator ─────────────────────────────────────────────────────
def __init__(self, module_name: str) -> None:
self._module_name = module_name
# #region Shared.cot_span [C:3] [TYPE Decorator] [SEMANTICS cot,span,marker,agent-centric]
# @ingroup Shared
# @BRIEF Decorator for C4/C5 functions that auto-emits REASON on entry and
# REFLECT/EXPLORE on exit with elapsed_ms timing.
# @INVARIANT Always emits exactly one entry marker and one exit/explore marker.
# @RELATION DEPENDS_ON -> [push_span, pop_span, log]
# @USAGE
# @cot_span("REASON", "High level description")
# async def my_important_operation(...):
# ...
def cot_span(marker: str = "REASON", intent: str | None = None):
"""Wrap a function so it automatically participates in the CoT trace.
def reason(self, intent: str, *, payload: dict[str, Any] | None = None) -> None:
log(self._module_name, "REASON", intent, payload=payload)
On entry: REASON (with args summary, elapsed_ms enabled)
On success: REFLECT (with elapsed_ms)
On exception: EXPLORE (with elapsed_ms and error)
"""
import asyncio
from functools import wraps
def reflect(self, intent: str, *, payload: dict[str, Any] | None = None) -> None:
log(self._module_name, "REFLECT", intent, payload=payload)
def decorator(func):
@wraps(func)
async def async_wrapper(*args, **kwargs):
src = f"{func.__module__}.{func.__qualname__}"
prev_span = push_span(func.__qualname__)
default_intent = intent or f"Execute {func.__qualname__}"
try:
log(src, marker, default_intent, payload=_summarise_args(args, kwargs))
result = await func(*args, **kwargs)
log(src, "REFLECT", f"{func.__qualname__} completed",
payload={"result": _summarise_value(result)})
return result
except Exception as e:
log(src, "EXPLORE", f"{func.__qualname__} failed",
error=str(e), payload={"args": _summarise_args(args, kwargs)})
raise
finally:
pop_span(prev_span)
def explore(
self,
intent: str,
*,
payload: dict[str, Any] | None = None,
error: str | None = None,
) -> None:
log(self._module_name, "EXPLORE", intent, payload=payload, error=error)
# #endregion MarkerLogger
# #endregion CotLoggerModule
@wraps(func)
def sync_wrapper(*args, **kwargs):
src = f"{func.__module__}.{func.__qualname__}"
prev_span = push_span(func.__qualname__)
default_intent = intent or f"Execute {func.__qualname__}"
try:
log(src, marker, default_intent, payload=_summarise_args(args, kwargs))
result = func(*args, **kwargs)
log(src, "REFLECT", f"{func.__qualname__} completed",
payload={"result": _summarise_value(result)})
return result
except Exception as e:
log(src, "EXPLORE", f"{func.__qualname__} failed",
error=str(e), payload={"args": _summarise_args(args, kwargs)})
raise
finally:
pop_span(prev_span)
return async_wrapper if asyncio.iscoroutinefunction(func) else sync_wrapper
return decorator
# #endregion Shared.cot_span
# ── Internal summarizers (used by cot_span) ─────────────────────────────────
# #region Shared.Summarizers [C:1] [TYPE Functions] [SEMANTICS helpers,summarise,args]
# @ingroup Shared
# @BRIEF Helpers to produce compact, agent-safe payload summaries.
def _summarise_value(val, max_len: int = 200) -> str:
"""Convert a value to string, truncating if longer than max_len."""
s = str(val)
return s[:max_len] + "..." if len(s) > max_len else s
def _summarise_args(args, kwargs) -> dict:
"""Build a compact payload dict from function args/kwargs.
Skips noisy infrastructure arguments (self, cls, db, request, session, token)
to keep agent-visible traces clean.
"""
skip = {"self", "cls", "db", "request", "session", "token"}
result = {}
for k, v in kwargs.items():
if k not in skip:
result[k] = _summarise_value(v)
return result
# #endregion Shared.Summarizers
# ── Public API ──────────────────────────────────────────────────────────────
# NOTE: MarkerLogger removed. It was @DEPRECATED with zero usages.
# Use shared/logger.py's logger.reason/reflect/explore or cot_logger.log() directly.
__all__ = [
"cot_logger",
"cot_span",
"derive_src",
"get_trace_id",
"log",
"pop_span",
"push_span",
"seed_trace_id",
"set_trace_id",
"is_routine_infra",
"set_routine_suppression",
]
# #endregion Shared.CotLoggerModule

View File

@@ -1,12 +1,14 @@
# #region SharedLoggerModule [C:3] [TYPE Module] [SEMANTICS logging,json,formatter,structured]
# @BRIEF Lightweight JSON logger for agent container.
# Provides the same .reason()/.reflect()/.explore() API as backend's
# src.core.logger, but without pydantic, WebSocketLogHandler, or
# RotatingFileHandler dependencies.
# #region Shared.SharedLoggerModule [C:3] [TYPE Module] [SEMANTICS logging,json,formatter,structured]
# @BRIEF Lightweight JSON logger for agent container and backend.
# Provides the same .reason()/.reflect()/.explore() API everywhere,
# backed by shared/cot_logger.py primitives and central suppression.
# @INVARIANT No dependency on FastAPI, SQLAlchemy, Gradio, LangChain, pydantic.
# @INVARIANT Every log.info/error/warning call produces single-line JSON.
# @DATA_CONTRACT Log record format:
# {ts, level, trace_id, src, marker, intent, span_id?, payload?, error?}
# {ts, level, trace_id, src, marker, intent, span_id?, payload?, error?, elapsed_ms?}
# @RELATION DEPENDS_ON -> [Shared.CotLoggerModule]
# @RATIONALE Cleaned from 3 suppression lists to 1 (in cot_logger.py).
# CotJsonFormatter no longer filters — formatters format, they don't suppress.
import json
import logging
@@ -14,20 +16,58 @@ import sys
import types
from datetime import UTC, datetime
from .cot_logger import _span_id, _trace_id
from .cot_logger import (
_span_id,
_trace_id,
derive_src,
is_routine_infra,
)
# #region CotJsonFormatter [C:2] [TYPE Class] [SEMANTICS logging,formatter,json,cot]
# #region Shared.CotJsonFormatter [C:2] [TYPE Class] [SEMANTICS logging,formatter,json,cot]
# @ingroup Shared
# @BRIEF JSON formatter matching the Molecular CoT protocol.
# Reads structured data from LogRecord's extra attributes.
# Does NOT filter — formatters format, they don't suppress.
# Suppression happens upstream in reason()/reflect().
class CotJsonFormatter(logging.Formatter):
"""JSON formatter matching the backend decision audit protocol.
Reads structured data from the LogRecord's extra attributes.
"""JSON formatter matching the Molecular CoT protocol.
Reads structured data from the LogRecord's extra attributes (marker, intent,
payload, error, src, elapsed_ms) set via the ``extra`` kwarg. Falls back to
plain message wrapping when no structured extra is present.
Output format (single-line JSON)::
{
"ts": "2026-05-12T10:30:00.123",
"level": "INFO",
"trace_id": "uuid-or-no-trace",
"src": "module.name",
"marker": "REASON|REFLECT|EXPLORE",
"intent": "human-readable intent",
"span_id": "optional-span",
"payload": { ... },
"elapsed_ms": 12.5,
"error": "..."
}
"""
# #region format [C:2] [TYPE Function] [SEMANTICS format,json,record]
# @INVARIANT Output is always valid single-line JSON.
def format(self, record):
marker = getattr(record, 'marker', None)
intent = getattr(record, 'intent', None)
payload = getattr(record, 'payload', None)
error = getattr(record, 'error', None)
src = getattr(record, 'src', None) or record.name
src = getattr(record, 'src', None)
elapsed_ms = getattr(record, 'elapsed_ms', None)
# Agent-centric: never emit useless generic src names
bad_srcs = {"superset_tools_app", "app_name", "root", "", None}
if not src or src in bad_srcs:
src = derive_src(record.name)
if src in bad_srcs:
src = record.name or "unknown"
if not marker:
marker = "REASON"
@@ -50,46 +90,61 @@ class CotJsonFormatter(logging.Formatter):
log_obj["payload"] = payload
if error is not None:
log_obj["error"] = error
if elapsed_ms is not None:
log_obj["elapsed_ms"] = elapsed_ms
return json.dumps(log_obj, ensure_ascii=False, default=str)
# #endregion CotJsonFormatter
# #endregion format
# #endregion Shared.CotJsonFormatter
# #region shared_logger_setup [C:2] [TYPE Function] [SEMANTICS logging,setup,instance]
def _setup_logger() -> logging.Logger:
"""Create and configure the shared JSON logger.
Guards against duplicate handlers: if the logger already has handlers
(e.g., configured by backend's src.core.logger), skip setup.
"""
# #region Shared._setup_logger [C:2] [TYPE Function] [SEMANTICS logging,setup,instance]
# @ingroup Shared
# @BRIEF Create and configure the shared JSON logger.
# Defers handler setup: backend/logger.py adds the console handler.
# For standalone use (agent container), call setup_handler().
# @INVARIANT Only ONE StreamHandler on superset_tools_app at any time.
_LOG_CONFIGURED = False
def setup_handler() -> None:
"""Add console handler to superset_tools_app. Safe to call multiple times."""
global _LOG_CONFIGURED
log = logging.getLogger("superset_tools_app")
# If already configured (e.g. by backend src.core.logger), skip
if log.handlers:
return log
log.setLevel(logging.INFO)
if _LOG_CONFIGURED:
return
if not log.handlers:
formatter = CotJsonFormatter()
console_handler = logging.StreamHandler(sys.stdout)
console_handler.setFormatter(formatter)
log.addHandler(console_handler)
log.propagate = False
_LOG_CONFIGURED = True
formatter = CotJsonFormatter()
console_handler = logging.StreamHandler(sys.stdout)
console_handler.setFormatter(formatter)
log.addHandler(console_handler)
def _setup_logger() -> logging.Logger:
log = logging.getLogger("superset_tools_app")
return log
logger = _setup_logger()
# #endregion shared_logger_setup
setup_handler()
# #endregion Shared._setup_logger
# #region explore [C:2] [TYPE Function] [SEMANTICS log,explore,marker,warning]
# #region Shared.explore [C:2] [TYPE Function] [SEMANTICS log,explore,marker,warning]
# @ingroup Shared
# @BRIEF Log an EXPLORE marker (WARNING level) with structured extra data.
def explore(self, msg, *args, **kwargs):
"""Log an EXPLORE marker (WARNING level) with structured extra data."""
user_extra = kwargs.pop('extra', {})
error_val = kwargs.pop('error', None)
payload = kwargs.pop('payload', None)
extra: dict = {'marker': 'EXPLORE', 'intent': msg}
explicit_src = kwargs.pop('src', None)
src = explicit_src or user_extra.pop('src', None)
if not src or src in {"superset_tools_app", "app_name", "root", ""}:
src = derive_src()
extra: dict = {'marker': 'EXPLORE', 'intent': msg, 'src': src}
if error_val is not None:
extra['error'] = error_val
if not payload and len(args) == 1 and isinstance(args[0], dict):
@@ -99,16 +154,28 @@ def explore(self, msg, *args, **kwargs):
extra['payload'] = payload
extra.update(user_extra)
self.warning(msg, extra=extra, **kwargs)
# #endregion explore
# #endregion Shared.explore
# #region reason [C:2] [TYPE Function] [SEMANTICS log,reason,marker,info]
# #region Shared.reason [C:2] [TYPE Function] [SEMANTICS log,reason,marker,info]
# @ingroup Shared
# @BRIEF Log a REASON marker (INFO level) with structured extra data.
# Uses central is_routine_infra() for suppression (defense-in-depth).
def reason(self, msg, *args, **kwargs):
"""Log a REASON marker (INFO level) with structured extra data."""
user_extra = kwargs.pop('extra', {})
error_val = kwargs.pop('error', None)
payload = kwargs.pop('payload', None)
extra: dict = {'marker': 'REASON', 'intent': msg}
explicit_src = kwargs.pop('src', None)
src = explicit_src or user_extra.pop('src', None)
if not src or src in {"superset_tools_app", "app_name", "root", ""}:
src = derive_src()
# Central suppression — single source of truth
if is_routine_infra(msg):
return # keep agent traces clean (defense-in-depth, per ADR-0017)
extra: dict = {'marker': 'REASON', 'intent': msg, 'src': src}
if error_val is not None:
extra['error'] = error_val
if not payload and len(args) == 1 and isinstance(args[0], dict):
@@ -118,16 +185,28 @@ def reason(self, msg, *args, **kwargs):
extra['payload'] = payload
extra.update(user_extra)
self.info(msg, extra=extra, **kwargs)
# #endregion reason
# #endregion Shared.reason
# #region reflect [C:2] [TYPE Function] [SEMANTICS log,reflect,marker,info]
# #region Shared.reflect [C:2] [TYPE Function] [SEMANTICS log,reflect,marker,info]
# @ingroup Shared
# @BRIEF Log a REFLECT marker (INFO level) with structured extra data.
# Uses central is_routine_infra() for suppression (defense-in-depth).
def reflect(self, msg, *args, **kwargs):
"""Log a REFLECT marker (INFO level) with structured extra data."""
user_extra = kwargs.pop('extra', {})
error_val = kwargs.pop('error', None)
payload = kwargs.pop('payload', None)
extra: dict = {'marker': 'REFLECT', 'intent': msg}
explicit_src = kwargs.pop('src', None)
src = explicit_src or user_extra.pop('src', None)
if not src or src in {"superset_tools_app", "app_name", "root", ""}:
src = derive_src()
# Central suppression — single source of truth
if is_routine_infra(msg):
return # keep agent traces clean (defense-in-depth, per ADR-0017)
extra: dict = {'marker': 'REFLECT', 'intent': msg, 'src': src}
if error_val is not None:
extra['error'] = error_val
if not payload and len(args) == 1 and isinstance(args[0], dict):
@@ -137,11 +216,11 @@ def reflect(self, msg, *args, **kwargs):
extra['payload'] = payload
extra.update(user_extra)
self.info(msg, extra=extra, **kwargs)
# #endregion reflect
# #endregion Shared.reflect
# Monkey-patch the convenience methods onto the logger instance
logger.explore = types.MethodType(explore, logger)
logger.reason = types.MethodType(reason, logger)
logger.reflect = types.MethodType(reflect, logger)
# #endregion SharedLoggerModule
# #endregion Shared.SharedLoggerModule