diff --git a/modules/hooks-session-naming/amplifier_module_hooks_session_naming/__init__.py b/modules/hooks-session-naming/amplifier_module_hooks_session_naming/__init__.py index deb02d82..fb7a2707 100644 --- a/modules/hooks-session-naming/amplifier_module_hooks_session_naming/__init__.py +++ b/modules/hooks-session-naming/amplifier_module_hooks_session_naming/__init__.py @@ -103,6 +103,12 @@ def __init__(self, coordinator: Any, config: SessionNamingConfig): self.config = config self._defer_counts: dict[str, int] = {} self._pending_tasks: set[asyncio.Task] = set() + # Tracks which sessions have already received the "model_role + # resolved to no candidates, falling back" WARNING (see + # _call_provider). Naming retries every few turns for the life of a + # session, so without this a stable config gap would re-emit the + # identical warning on every retry. + self._role_fallback_warned: set[str] = set() async def on_orchestrator_complete( self, event: str, data: dict[str, Any] @@ -248,7 +254,7 @@ async def _generate_name( # Call the provider — hard timeout caps stalled providers try: response = await asyncio.wait_for( - self._call_provider(prompt), timeout=10.0 + self._call_provider(prompt, session_id), timeout=10.0 ) except asyncio.TimeoutError: logger.warning( @@ -454,7 +460,9 @@ def _truncate_content(self, content: str, max_len: int) -> str: truncated = truncated[:last_space] return truncated + "..." - async def _call_provider(self, prompt: str) -> str | None: + async def _call_provider( + self, prompt: str, session_id: str | None = None + ) -> str | None: """Call the LLM provider to generate name/description. Resolution order (highest to lowest priority): @@ -466,14 +474,26 @@ async def _call_provider(self, prompt: str) -> str | None: at all), logs a debug message and falls back to #2 — that fallback is legitimate and intended. - But when a model_role_resolver IS registered and the resolution itself - fails (resolves to no candidates, or raises), that is a failure of an - explicitly-configured routing preference, not an absent one. Silently - substituting the fallback provider in that case would mean a transient - resolver error (e.g. a provider API hiccup while listing models) quietly - routes a cheap background chore onto the session's primary/expensive - model. Instead, abort this naming attempt (return None) and let the - self-retrying trigger try again on a later turn. + When a model_role_resolver IS registered and resolution itself raises + (e.g. a transient provider API hiccup while listing models), the + failure mode is unknown and possibly transient. Silently substituting + the fallback provider in that case could quietly route a cheap + background chore onto the session's primary/expensive model on every + retry until the transient error clears. So this case still aborts + (returns None) and lets the self-retrying trigger try again on a + later turn. + + But when the resolver runs cleanly and simply resolves to *no + candidates* for the configured role (e.g. no "fast" model configured + for the active provider), that is a stable configuration gap, not a + transient error — retrying later changes nothing. Skipping silently + in that case means session naming is a feature that quietly never + runs, with only a log line nobody reads to explain why. So this case + falls back to #2 (the session's own default/priority provider) + instead of skipping, and logs a WARNING naming the unresolved role + and the provider substituted for it — once per session (via + ``session_id``), since naming retries every few turns and repeating + the identical warning on every retry would just be noise. """ try: providers = self.coordinator.get("providers") @@ -484,6 +504,7 @@ async def _call_provider(self, prompt: str) -> str | None: # Resolution order: model_role > priority provider provider = None model_override: str | None = None + role_had_no_candidates = False if self.config.model_role: # Look up the model_role_resolver capability registered by @@ -524,19 +545,42 @@ async def _call_provider(self, prompt: str) -> str | None: provider = p break else: + role_had_no_candidates = True + + # Fallback: use first/priority provider. Reached when model_role + # is unset, no resolver capability is registered, OR the role + # resolved to no candidates (role_had_no_candidates, handled + # below with a loud warning instead of a silent substitution). + if provider is None: + fallback_key = next(iter(providers), None) + provider = providers.get(fallback_key) if fallback_key else None + + if role_had_no_candidates and provider is not None: + warn_key = session_id or "" + if warn_key not in self._role_fallback_warned: + self._role_fallback_warned.add(warn_key) logger.warning( - "model_role %r resolved to no candidates; skipping" - " session naming for this turn rather than silently" - " falling back to the priority (expensive) provider" - " — will retry on a later turn", + "model_role %r resolved to no candidates; session" + " naming is falling back to provider %r (the" + " session's own default) instead of skipping." + " This uses whatever model that provider is" + " already configured with, which may be more" + " expensive than intended — configure a %r" + " candidate in the routing matrix to route naming" + " to a cheap model instead. (Further occurrences" + " this session are logged at DEBUG.)", + self.config.model_role, + fallback_key, self.config.model_role, ) - return None - - # Fallback: use first/priority provider (only reached when - # model_role is unset, or no resolver capability is registered) - if provider is None: - provider = next(iter(providers.values()), None) + else: + logger.debug( + "model_role %r again resolved to no candidates;" + " reusing fallback provider %r (already warned" + " once this session)", + self.config.model_role, + fallback_key, + ) if not provider: logger.warning("No provider available for session naming") diff --git a/modules/hooks-session-naming/tests/test_session_naming.py b/modules/hooks-session-naming/tests/test_session_naming.py index 0130c4eb..626cff16 100644 --- a/modules/hooks-session-naming/tests/test_session_naming.py +++ b/modules/hooks-session-naming/tests/test_session_naming.py @@ -377,14 +377,21 @@ async def test_no_model_role_uses_priority_provider(self) -> None: assert request.model is None, "No model override without model_role" @pytest.mark.asyncio - async def test_resolver_empty_result_aborts_without_calling_provider(self) -> None: - """Resolver present but resolves to [] must abort, NOT fall back to the - priority provider. + async def test_resolver_empty_result_falls_back_to_priority_provider( + self, caplog + ) -> None: + """Resolver present but resolves to [] must fall back to the session's + priority provider AND log a WARNING identifying the unresolved role + and the provider substituted for it -- naming must still run. This is the load-bearing regression test for the bug: a resolver that - legitimately exists but fails to resolve any candidates (e.g. a transient - provider error inside list_models()) must never silently substitute the - session's primary/expensive model for a background naming chore. + resolves to no candidates for a configured model_role (e.g. no "fast" + model configured for the active provider) is a *stable configuration + gap*, not a transient error -- retrying later changes nothing. Skipping + silently in that case means session naming is a feature that quietly + never runs. Naming must still happen, using the session's own default + provider, with a loud warning explaining why a role-based routing + preference was not honored. """ priority_provider = _make_mock_provider() providers = {"provider-priority": priority_provider} @@ -396,17 +403,72 @@ async def test_resolver_empty_result_aborts_without_calling_provider(self) -> No model_role="fast", ) - result = await hook._call_provider("name this session") + with caplog.at_level("WARNING"): + result = await hook._call_provider("name this session", "session-abc") - assert result is None, ( - "Must abort (return None) when model_role resolves to no candidates" + assert result is not None, ( + "Naming must still run against the fallback provider when " + "model_role resolves to no candidates, not abort" ) - assert not priority_provider.complete.called, ( - "Must NOT silently fall back to the priority provider when an " - "explicitly-configured model_role fails to resolve" + assert priority_provider.complete.called, ( + "Must fall back to the priority provider when an explicitly-" + "configured model_role resolves to no candidates, rather than " + "silently skipping naming for the turn" + ) + call_kwargs = priority_provider.complete.call_args + request = call_kwargs[0][0] + assert request.model is None, ( + "Fallback must not invent a model override -- it uses whatever " + "model the fallback provider is already configured with" ) resolver.resolve.assert_called_once() + warnings = [r for r in caplog.records if r.levelno >= 30] + assert warnings, ( + "Expected a WARNING log identifying the unresolved role and the " + "fallback provider substituted for it" + ) + assert any("fast" in r.getMessage() for r in warnings), ( + "Warning should name the model_role that failed to resolve" + ) + assert any("provider-priority" in r.getMessage() for r in warnings), ( + "Warning should name the provider actually used" + ) + + @pytest.mark.asyncio + async def test_resolver_empty_result_warns_once_per_session(self, caplog) -> None: + """The no-candidates fallback warning fires once per session, then + drops to DEBUG on subsequent occurrences within the same session. + + Naming retries every few turns for the life of a session, so without + this, a stable config gap (role never resolves) would re-emit the + identical WARNING on every retry -- noise that drowns out the one + occurrence a reader actually needs to see. + """ + providers = {"provider-priority": _make_mock_provider()} + resolver = _make_resolver(return_value=[]) + hook = _make_hook( + providers=providers, + model_role_resolver=resolver, + model_role="fast", + ) + + with caplog.at_level("DEBUG"): + await hook._call_provider("name this session", "session-xyz") + first_pass_warnings = [r for r in caplog.records if r.levelno >= 30] + caplog.clear() + await hook._call_provider("name this session", "session-xyz") + second_pass_warnings = [r for r in caplog.records if r.levelno >= 30] + second_pass_debugs = [r for r in caplog.records if r.levelno == 10] + + assert first_pass_warnings, "First occurrence in a session must warn" + assert not second_pass_warnings, ( + "Second occurrence in the SAME session must not re-warn" + ) + assert second_pass_debugs, ( + "Second occurrence should still be logged, just at DEBUG" + ) + @pytest.mark.asyncio async def test_resolver_exception_aborts_without_calling_provider(self) -> None: """Resolver present but resolve() raises must abort, NOT propagate and @@ -434,7 +496,7 @@ async def test_resolver_exception_aborts_without_calling_provider(self) -> None: @pytest.mark.asyncio async def test_resolver_empty_result_logs_warning(self, caplog) -> None: - """Aborting due to an empty resolution must be logged at WARNING.""" + """Falling back due to an empty resolution must be logged at WARNING.""" hook = _make_hook( providers={"provider-priority": _make_mock_provider()}, model_role_resolver=_make_resolver(return_value=[]), @@ -442,7 +504,7 @@ async def test_resolver_empty_result_logs_warning(self, caplog) -> None: ) with caplog.at_level("WARNING"): - await hook._call_provider("name this session") + await hook._call_provider("name this session", "session-1") warnings = [r for r in caplog.records if r.levelno >= 30] assert warnings, (