fix(obs): hand an agent's own loggers to the logs pipeline, not just agentex's

The hand-over added in #518 had two halves, and only one of them covered an
agent's own modules. The latch in `make_logger` never looked at the logger's
name, so anything created after init was fine. The sweep matched the `agentex`
prefix, so a logger created BEFORE init under any other name kept its handler
and went on printing a second, ungoverned copy of every record.

That is not a corner case: agents call `make_logger(__name__)` from their own
modules, and `project.acp` -- the module that builds the ACP server, in every
scaffold -- logs at import, which is necessarily before `init_sgp_obs` runs.
Measured on dbt-assistant running 0.27.0b1: 123 of 3361 log lines were the
second copy, each 80 microseconds after its governed twin, carrying
`name`/`request_id` but no `trace_id`, `span_id`, `source` or `agent_id`.
Since it is emitted before the pipeline's filters, it also escapes the
allowlist and the truncation.

The SDK cannot know an agent's package name, so `make_logger` now marks each
handler it attaches and the sweep takes back exactly those, on a logger of any
name. Prefix matching stays for `agentex.*` itself, where every handler is ours
by definition. A handler this module did not attach is still left alone --
litellm's three loggers and anything else keep what their owner set up, which
is why sgp-obs warns about them rather than stripping them.

Renamed `route_agentex_loggers_to_root` to `route_loggers_to_root`, since
"agentex loggers" is what the bug was.

Co-authored-by: Claude Opus 5 <noreply@anthropic.com>

Author: stephen-wang24

src/agentex/lib/core/observability/sgp_obs_setup.py

@@ -53,7 +53,7 @@
 from agentex.lib.utils.logging import (
     make_logger,
     _reset_for_tests as _logging_reset_for_tests,
-    route_agentex_loggers_to_root,
+    route_loggers_to_root,
 )
 
 logger = make_logger(__name__)
@@ -145,7 +145,7 @@ def init_sgp_obs(app: Any = None) -> str:
         return _status
 
     if "logs" in handles:
-        _hand_agentex_logging_to_the_pipeline()
+        _hand_logging_to_the_pipeline()
 
     if "traces" in handles:
         _install_openai_agents_bridge()
@@ -156,8 +156,8 @@ def init_sgp_obs(app: Any = None) -> str:
     return _status
 
 
-def _hand_agentex_logging_to_the_pipeline() -> None:
-    """Stop agentex's own loggers printing a second, ungoverned copy of every record.
+def _hand_logging_to_the_pipeline() -> None:
+    """Stop a second, ungoverned copy of every log record being printed.
 
     ``agentex.lib.utils.logging.make_logger`` attaches a handler to each module's own
     (leaf) logger. sgp-obs' logs pipeline replaces the handlers on the ROOT logger and
@@ -169,27 +169,31 @@ def _hand_agentex_logging_to_the_pipeline() -> None:
 
     The duplicate is not merely redundant: it is emitted before the pipeline's filters,
     so it carries no ``agent_id``/``task_id``, is not governed by the allowlist, and is
-    not truncated.
-
-    Only agentex's loggers are handed over — see
-    :func:`~agentex.lib.utils.logging.route_agentex_loggers_to_root` for why by prefix,
-    why ``capture_loggers=`` is not the mechanism, and why a third party's handler is
-    left where it is.
+    not truncated. Measured on dbt-assistant running 0.27.0b1: 123 of 3361 log lines
+    were the second copy, each one 80 microseconds after its governed twin.
+
+    An agent's OWN modules are covered, not just the SDK's. They call
+    ``make_logger(__name__)`` too, under the agent's package name, and that is where
+    the dbt-assistant duplicate came from. See
+    :func:`~agentex.lib.utils.logging.route_loggers_to_root` for how a handler is
+    recognised as the SDK's on a logger whose name the SDK cannot predict, why
+    ``capture_loggers=`` is not the mechanism, and why a third party's handler is left
+    where it is.
     """
     try:
-        cleared = route_agentex_loggers_to_root()
+        cleared = route_loggers_to_root()
     except Exception:  # pragma: no cover - telemetry must never break startup
-        logger.debug("could not hand agentex logging to the sgp-obs pipeline", exc_info=True)
+        logger.debug("could not hand agentex logging to the sgp-obs logs pipeline", exc_info=True)
         return
 
     if cleared:
         # sgp-obs has already logged its "bypass log governance" warning by this point,
         # naming loggers this call has just fixed. Say so, or the two lines read as a
         # contradiction to whoever is looking at the pod's first second of output.
         logger.info(
-            "routed %d agentex logger(s) through the sgp-obs logs pipeline; any "
-            "'bypass log governance' warning above that names agentex.* loggers was "
-            "emitted before this ran and no longer applies to them",
+            "routed %d logger(s) through the sgp-obs logs pipeline; any 'bypass log "
+            "governance' warning above that names an agentex.* logger, or one of this "
+            "agent's own, was emitted before this ran and no longer applies to it",
             cleared,
         )
 

src/agentex/lib/core/observability/tests/test_sgp_obs_setup.py

@@ -403,18 +403,18 @@ def boom():
 
 
 class TestLoggingHandover:
-    """agentex's make_logger attaches a handler to each module's own logger; sgp-obs'
-    logs pipeline owns the ROOT logger and deliberately leaves named loggers alone. Both
-    then print, so every record appears twice — and the agentex copy is emitted before
-    the pipeline's filters, so it carries no agent_id/task_id, is not governed by the
-    allowlist, and is not truncated.
+    """agentex's make_logger attaches a handler to each module's own logger — the
+    agent's modules as well as the SDK's; sgp-obs' logs pipeline owns the ROOT logger and
+    deliberately leaves named loggers alone. Both then print, so every record appears
+    twice — and the leaf copy is emitted before the pipeline's filters, so it carries no
+    agent_id/task_id, is not governed by the allowlist, and is not truncated.
     """
 
     @staticmethod
     def _spy(monkeypatch):
         calls = []
         monkeypatch.setattr(
-            sgp_obs_setup, "route_agentex_loggers_to_root", lambda: calls.append(True) or 1
+            sgp_obs_setup, "route_loggers_to_root", lambda: calls.append(True) or 1
         )
         return calls
 
@@ -442,6 +442,6 @@ def test_a_failing_handover_does_not_stop_startup(self, monkeypatch):
         def boom():
             raise RuntimeError("logging registry is in a strange state")
 
-        monkeypatch.setattr(sgp_obs_setup, "route_agentex_loggers_to_root", boom)
+        monkeypatch.setattr(sgp_obs_setup, "route_loggers_to_root", boom)
         _fake_sgp_obs(monkeypatch, lambda **_kwargs: {"logs": object()})
         assert init_sgp_obs() == "wired:logs"

src/agentex/lib/utils/logging.py

@@ -24,14 +24,29 @@
 #
 # While this is True, ``make_logger`` attaches nothing and the record reaches the root
 # pipeline by propagation alone. ``sgp_obs_setup`` sets it via
-# :func:`route_agentex_loggers_to_root` -- nothing else may.
+# :func:`route_loggers_to_root` -- nothing else may.
 _ROOT_PIPELINE_OWNS_LOGGING = False
 
 # Handlers are cleared by prefix rather than by an enumerated list: the names are
 # module paths, several agentex modules are imported LAZILY, and any list would be a
 # snapshot that goes stale the moment one of them loads.
 _PACKAGE_ROOT = "agentex"
 
+# ``make_logger`` stamps every handler it attaches, so the hand-over can find its own
+# handlers again on a logger of ANY name.
+#
+# The prefix above cannot reach them all, and that gap was a measured duplicate rather
+# than a theoretical one: agents call ``make_logger(__name__)`` from their own modules,
+# whose names come from the agent's package (``project.acp`` in every scaffold), so the
+# prefix does not match and the leaf handler stayed attached. On dbt-assistant, 123 of
+# 3361 log lines were a second, ungoverned copy carrying ``name``/``request_id`` but no
+# ``trace_id``, ``span_id``, ``source`` or ``agent_id``. The SDK cannot know an agent's
+# package name, so ownership is recorded on the handler at the moment it is attached.
+#
+# Marking the handler rather than keeping a registry of logger names means there is no
+# bookkeeping to go stale, and a handler moved to another logger is still recognised.
+_OWNED_BY_MAKE_LOGGER = "_agentex_make_logger_owned"
+
 
 def resolve_log_level() -> int:
     """Read the log level from ``LOG_LEVEL``, falling back to INFO.
@@ -81,6 +96,17 @@ def json_record(self, message: str, extra: dict, record: logging.LogRecord) -> d
 
         return extra
 
+
+def _attach(logger: logging.Logger, handler: logging.Handler) -> None:
+    """Attach ``handler`` and record that this module owns it.
+
+    The mark is what lets :func:`route_loggers_to_root` take this handler back off a
+    logger whose name it could not have predicted.
+    """
+    setattr(handler, _OWNED_BY_MAKE_LOGGER, True)
+    logger.addHandler(handler)
+
+
 def make_logger(name: str) -> logging.Logger:
     """
     Creates a logger object with a RichHandler to print colored text.
@@ -102,13 +128,15 @@ def make_logger(name: str) -> logging.Logger:
     if environment == "local":
         console = Console()
         # Add the RichHandler to the logger to print colored text
-        handler = RichHandler(
-            console=console,
-            show_level=False,
-            show_path=False,
-            show_time=False,
+        _attach(
+            logger,
+            RichHandler(
+                console=console,
+                show_level=False,
+                show_path=False,
+                show_time=False,
+            ),
         )
-        logger.addHandler(handler)
         return logger
 
     stream_handler = logging.StreamHandler()
@@ -119,21 +147,22 @@ def make_logger(name: str) -> logging.Logger:
             logging.Formatter("%(asctime)s %(levelname)s [%(name)s] [%(filename)s:%(lineno)d] - %(message)s")
         )
 
-    logger.addHandler(stream_handler)
+    _attach(logger, stream_handler)
     # Create a logger object with the name of the current module
     return logger
 
 
-def route_agentex_loggers_to_root() -> int:
-    """Hand agentex's logging over to whatever owns the root logger. Returns the
-    number of loggers cleared.
+def route_loggers_to_root() -> int:
+    """Hand logging over to whatever owns the root logger. Returns the number of
+    loggers a handler was taken off.
 
     Two halves, and BOTH are needed -- measured, one line per ``logger.info()`` only
     when they run together:
 
-    * the sweep below fixes the loggers that ALREADY exist, i.e. every agentex module
-      imported before this ran;
-    * the flag fixes every logger created AFTER it, which a sweep cannot reach.
+    * the sweep below fixes the loggers that ALREADY exist, i.e. every module whose
+      ``make_logger`` call ran before this did -- the whole of an agent's own code,
+      since the ACP server is constructed from a module that logs;
+    * the latch fixes every logger created AFTER it, which a sweep cannot reach.
       agentex imports several modules lazily (the adk ``_claude_code_sync`` /
       ``_codex_sync`` / ``_pydantic_ai_sync`` harnesses among them), so their
       ``make_logger`` call happens later and would attach a fresh duplicate handler.
@@ -144,9 +173,17 @@ def route_agentex_loggers_to_root() -> int:
     paths; and passing anything at all replaces its uvicorn default, which would put
     uvicorn's access log back to printing twice.
 
-    Only agentex's own loggers are touched. A third party's handler may be there on
-    purpose -- which is exactly why sgp-obs warns about them rather than stripping them
-    -- so litellm's three loggers and anything else keep whatever they have.
+    A handler is taken off only when it is ours, on one of two grounds:
+
+    * anything under the ``agentex`` prefix is this package's own logger, so every
+      handler on it is ours to move;
+    * on a logger of any other name -- an agent's ``project.acp``, or any third
+      party's -- only a handler carrying :data:`_OWNED_BY_MAKE_LOGGER` is touched.
+
+    That second rule is the fix for the duplicate measured on dbt-assistant, and it is
+    narrow on purpose. A third party's handler may be there deliberately -- which is
+    exactly why sgp-obs warns about them rather than stripping them -- so litellm's
+    three loggers and anything else keep whatever they set up themselves.
     """
     global _ROOT_PIPELINE_OWNS_LOGGING
     _ROOT_PIPELINE_OWNS_LOGGING = True
@@ -157,22 +194,26 @@ def route_agentex_loggers_to_root() -> int:
     for name, existing in list(logging.Logger.manager.loggerDict.items()):
         if not isinstance(existing, logging.Logger):
             continue  # a PlaceHolder for a name whose children exist but itself does not
-        if name != _PACKAGE_ROOT and not name.startswith(_PACKAGE_ROOT + "."):
-            continue
         if not existing.handlers:
             continue
         if not existing.propagate:
             # Deliberately cut off from root, so nothing of its reaches the pipeline.
             # Clearing its handlers would send its records NOWHERE -- worse than a
             # duplicate. Leave it exactly as its owner set it up.
             continue
+        ours = name == _PACKAGE_ROOT or name.startswith(_PACKAGE_ROOT + ".")
+        removed = 0
         for handler in list(existing.handlers):
+            if not ours and not getattr(handler, _OWNED_BY_MAKE_LOGGER, False):
+                continue
             try:
                 handler.flush()  # a buffering handler must not lose records on removal
             except Exception:
                 pass
             existing.removeHandler(handler)
-        cleared += 1
+            removed += 1
+        if removed:
+            cleared += 1
     return cleared