fix(tools): log boot-time UnscopedSecretError probes at debug, not warning

With multiplexing on, check_fns evaluated before any profile secret scope
exists fail closed by design: get_secret raises UnscopedSecretError and the
tool re-probes on the first scoped turn. _run_check_fn_uncached logged that
expected signal like a crashed check_fn (WARNING + exc_info), so every
multiplexed gateway start printed three full tracebacks that drowned real
check_fn failures.

Split the handler: an unscoped read reported while the profile cache scope
was unresolved logs one debug line without a traceback; the same error with
the scope resolved is a genuinely lost scope and keeps the loud
warning + traceback.

Fixes #100697
This commit is contained in:
liuhao1024
2026-09-02 05:42:51 +08:00
committed by Teknium
parent 79732c6452
commit 39fca697ae
2 changed files with 56 additions and 0 deletions
@@ -360,3 +360,34 @@ class TestCheckFnTransientFailureSuppression:
assert "terminal" not in names
assert "execute_code" not in names
class TestUnscopedSecretReadLogging:
"""#100697: with multiplexing on, boot-time check_fns run before any
profile secret scope exists, so get_secret fails closed with
UnscopedSecretError. That expected signal must not be logged like a
crashed check_fn (WARNING + traceback); an unscoped read reported while
the scope was *resolved* is a genuinely lost scope and stays loud."""
def test_expected_fail_closed_probe_is_quiet_but_lost_scope_stays_loud(self, caplog):
import logging
import tools.registry as reg
from agent.secret_scope import get_secret, set_multiplex_active
def probe():
return bool(get_secret("REGISTRY_LOG_PROBE_TOKEN", ""))
set_multiplex_active(True)
try:
with caplog.at_level(logging.DEBUG, logger="tools.registry"):
assert reg._run_check_fn_uncached(probe, unresolved_scope=True) is False
boot = [r for r in caplog.records if r.name == "tools.registry"]
caplog.clear()
assert reg._run_check_fn_uncached(probe, unresolved_scope=False) is False
lost = [r for r in caplog.records if r.name == "tools.registry"]
finally:
set_multiplex_active(False)
assert boot and all(r.levelno == logging.DEBUG and r.exc_info is None for r in boot)
assert any(r.levelno >= logging.WARNING and r.exc_info for r in lost)
+25
View File
@@ -348,8 +348,33 @@ def check_fn_cache_scope() -> Optional[str]:
def _run_check_fn_uncached(fn: Callable, *, unresolved_scope: bool = False) -> bool:
"""Run an availability check without cache/grace handling."""
from agent.secret_scope import UnscopedSecretError
try:
return bool(fn())
except UnscopedSecretError:
if unresolved_scope:
# Expected fail-closed probe: with multiplexing on, boot-time
# check_fns run before any profile secret scope exists, so
# get_secret raises by design. The tool re-probes on the first
# scoped turn — log without a traceback so this cannot be
# mistaken for a crashed check_fn (#100697).
logger.debug(
"check_fn %s hit the multiplex fail-closed path with no "
"profile secret scope active; dependent tools re-probe on "
"the first scoped turn",
getattr(fn, "__qualname__", fn),
)
return False
# The scope resolved but the read still failed closed: a genuinely
# lost scope. Keep the loud crash-style report.
logger.warning(
"check_fn %s raised UnscopedSecretError while the profile cache "
"scope was resolved; dependent tools will be unavailable this turn",
getattr(fn, "__qualname__", fn),
exc_info=True,
)
return False
except Exception:
detail = " while profile cache scope was unresolved" if unresolved_scope else ""
logger.warning(