diff --git a/agent/auxiliary_client.py b/agent/auxiliary_client.py index b98ea49d27..3f64241cdb 100644 --- a/agent/auxiliary_client.py +++ b/agent/auxiliary_client.py @@ -3339,8 +3339,10 @@ def _is_invalid_aux_response_error(exc: Exception) -> bool: # stalls the serialised turn queue). A same-provider retry after a full-budget timeout costs another # whole ``timeout`` window, so they skip straight to fallback; fast blips still retry. # Fast blips (a streaming-close or a 5xx) still retry, since those are cheap. See issue #54465 for the -# compression case. -_TIMEOUT_NO_RETRY_TASKS = frozenset({"compression", "vision"}) +# compression case. Title generation joins them because its retries multiplied the user's +# ``auxiliary.title_generation.timeout`` (~4x: three full windows plus backoff) on a slow local +# model, and the auto-title thread outlived the deadline the user thought they had set (#89445, #66251). +_TIMEOUT_NO_RETRY_TASKS = frozenset({"compression", "vision", "title_generation"}) def _should_skip_same_provider_retry(task: Optional[str], exc: Exception) -> bool: @@ -7018,7 +7020,10 @@ class _LadderStep(NamedTuple): _FALLBACK_REASONS: Tuple[Tuple[Callable[[Exception], bool], str], ...] = ( (_is_auth_error, "auth error"), (_is_payment_error, "payment error"), (_is_rate_limit_error, "rate limit"), (_is_model_incompatible_error, "model incompatible with route"), - (_is_invalid_aux_response_error, "invalid provider response"), (_is_connection_error, "connection error"), + (_is_invalid_aux_response_error, "invalid provider response"), + # Before the connection-error rung (its superset): a full-budget timeout must be named as one, or + # a slow local model reads as an unreachable endpoint (#89445). + (_is_timeout_error, "request timed out"), (_is_connection_error, "connection error"), ) @@ -7060,7 +7065,7 @@ _LadderRoute = NamedTuple("_LadderRoute", [ ("resolved_provider", str), ("resolved_model", Optional[str]), ("resolved_base_url", Optional[str]), ("resolved_api_key", Optional[str]), ("resolved_api_mode", Optional[str]), ("final_model", Optional[str]), ("main_runtime", Optional[Dict[str, Any]]), - ("route_info", Optional[Dict[str, str]]), + ("route_info", Optional[Dict[str, str]]), ("timeout", Optional[float]), ]) @@ -7300,8 +7305,16 @@ def _ladder_provider_fallback(first_err: Exception, route: _LadderRoute): _mark_provider_unhealthy( _recoverable_pool_provider(resolved_provider, route.client, main_runtime=route.main_runtime) or resolved_provider, base_url=route.base_info) - logger.info("Auxiliary %s%s: %s on %s (%s), trying fallback", - task or "call", tag, reason, resolved_provider, first_err) + if reason == "request timed out": + # WARNING, naming the endpoint, the budget and the knob: the only other trace of a slow + # local model is the fallback provider's complaint about a model it never had (#89445). + logger.warning("Auxiliary %s%s: request to %s timed out after %ss (raise auxiliary.%s.timeout " + "for slow or reasoning models) on %s, trying fallback", + task or "call", tag, route.base_info or resolved_provider, route.timeout, + task or "call", resolved_provider) + else: + logger.info("Auxiliary %s%s: %s on %s (%s), trying fallback", + task or "call", tag, reason, resolved_provider, first_err) # Skip only the failed model for model-specific failures; 401/402 are provider-wide, so # auth keeps skipping the credential surface, while billing is scoped to the endpoint: # separate custom URLs can carry separate credentials (or no billing relationship at all). @@ -7365,7 +7378,8 @@ def _aux_recovery_ladder( tag = " (async)" if async_mode else "" route = _LadderRoute( client, task, tag, async_mode, base_info, resolved_provider, resolved_model, - resolved_base_url, resolved_api_key, resolved_api_mode, final_model, main_runtime, route_info) + resolved_base_url, resolved_api_key, resolved_api_mode, final_model, main_runtime, route_info, + kwargs.get("timeout")) resp, first_err, kwargs = yield from _ladder_parameter_rungs(first_err, route, kwargs, max_tokens) if first_err is None: return resp diff --git a/contributors/emails/ajfasano@gmail.com b/contributors/emails/ajfasano@gmail.com new file mode 100644 index 0000000000..56d46a4b9b --- /dev/null +++ b/contributors/emails/ajfasano@gmail.com @@ -0,0 +1 @@ +eyeonall diff --git a/tests/agent/test_auxiliary_auto_never_guesses_provider.py b/tests/agent/test_auxiliary_auto_never_guesses_provider.py index 6fc0d5e71b..8076c51696 100644 --- a/tests/agent/test_auxiliary_auto_never_guesses_provider.py +++ b/tests/agent/test_auxiliary_auto_never_guesses_provider.py @@ -44,7 +44,7 @@ def test_quarantined_fallback_hands_over_to_the_next_configured_entry(): configured entry must still get its turn instead of the request dying on the original error.""" healthy = MagicMock(name="second-fallback") route = aux._LadderRoute(None, "compression", "", False, "", "xai-oauth", None, None, None, None, None, - {"provider": "xai-oauth"}, None) + {"provider": "xai-oauth"}, None, None) with patch.object(aux, "_try_configured_fallback_chain", return_value=(healthy, "m2", "fallback_chain[1](nous)")), \ patch.object(aux, "_try_payment_fallback") as discovery: client, model, label = aux._next_fallback_after_quarantine( diff --git a/tests/agent/test_auxiliary_title_timeout_bound.py b/tests/agent/test_auxiliary_title_timeout_bound.py new file mode 100644 index 0000000000..85ee84cc38 --- /dev/null +++ b/tests/agent/test_auxiliary_title_timeout_bound.py @@ -0,0 +1,73 @@ +"""Auto-title timeouts are bounded by ONE ``auxiliary.title_generation.timeout`` window and named as +timeouts (#89445, #66251). + +On a slow local model the title request used to be retried on the same provider after every +full-budget timeout (three windows plus backoff ≈ 4x the configured deadline) and the failure was +logged at INFO as a ``connection error`` — indistinguishable from an unreachable endpoint — while +the only WARNING came from the fallback provider complaining about a model it never had.""" + +import logging +from unittest.mock import MagicMock, patch + +from agent.auxiliary_client import call_llm + + +class _Timeout(Exception): + pass + + +_Timeout.__name__ = "APITimeoutError" + + +def _route_patches(client): + return ( + patch("agent.auxiliary_client._resolve_task_provider_model", + return_value=("mac-ollama", "qwen3.6:27b", None, None, None)), + patch("agent.auxiliary_client._get_cached_client", return_value=(client, "qwen3.6:27b")), + patch("agent.auxiliary_client._validate_llm_response", side_effect=lambda resp, _task, **_kw: resp), + patch("agent.auxiliary_client._try_configured_fallback_chain", return_value=(None, None, "")), + patch("agent.auxiliary_client._try_main_agent_model_fallback", return_value=(None, None, "")), + ) + + +def test_title_timeout_hits_the_provider_once_and_names_the_deadline(caplog): + primary = MagicMock() + primary.base_url = "http://100.121.173.79:11434/v1" + primary.chat.completions.create.side_effect = _Timeout("Request timed out.") + p = _route_patches(primary) + caplog.set_level(logging.INFO, logger="agent.auxiliary_client") + with p[0], p[1], p[2], p[3], p[4]: + try: + call_llm(task="title_generation", messages=[{"role": "user", "content": "hi"}], timeout=30) + except _Timeout: + pass + else: + raise AssertionError("timeout must surface once every fallback is exhausted") + # One request per deadline: the auto-title thread may not outlive the configured budget. + assert primary.chat.completions.create.call_count == 1 + warnings = [r.getMessage() for r in caplog.records if r.levelno == logging.WARNING] + timed_out = [m for m in warnings if "timed out after 30s" in m] + assert timed_out, warnings + assert "http://100.121.173.79:11434/v1" in timed_out[0] + assert "auxiliary.title_generation.timeout" in timed_out[0] + assert not any("connection error on" in m for m in warnings), warnings + + +def test_connection_refused_is_still_a_connection_error(caplog): + """Control: a genuinely unreachable endpoint keeps its own label — the timeout rung must not swallow it.""" + class _ConnErr(Exception): + pass + _ConnErr.__name__ = "APIConnectionError" + primary = MagicMock() + primary.base_url = "http://127.0.0.1:1/v1" + primary.chat.completions.create.side_effect = _ConnErr("Connection refused") + p = _route_patches(primary) + caplog.set_level(logging.INFO, logger="agent.auxiliary_client") + with p[0], p[1], p[2], p[3], p[4]: + try: + call_llm(task="title_generation", messages=[{"role": "user", "content": "hi"}], timeout=30) + except _ConnErr: + pass + messages = [r.getMessage() for r in caplog.records] + assert any("connection error on mac-ollama" in m for m in messages), messages + assert not any("timed out after" in m for m in messages), messages diff --git a/website/docs/user-guide/configuration.md b/website/docs/user-guide/configuration.md index a2d7c82594..7827f8918f 100644 --- a/website/docs/user-guide/configuration.md +++ b/website/docs/user-guide/configuration.md @@ -1537,7 +1537,7 @@ auxiliary: ``` :::tip -Each auxiliary task has a configurable `timeout` (in seconds). Defaults: vision 120s, approval 30s, compression 120s. Increase these if you use slow local models for auxiliary tasks. Vision also has a separate `download_timeout` (default 30s) for the HTTP image download — increase this for slow connections or self-hosted image servers. +Each auxiliary task has a configurable `timeout` (in seconds). Defaults: vision 120s, approval 30s, compression 120s, title generation 30s, every other task 30s. Increase these if you use slow local models for auxiliary tasks — a reasoning model that emits a thinking block before its answer routinely needs more than 30s for a title, and a request that hits the deadline is logged as `Auxiliary : request to timed out after s (raise auxiliary..timeout …)` before Hermes tries the fallback chain. Title generation, compression and vision give up on the primary route after one full timeout window (no same-provider retry) so a slow model cannot multiply the wait. Vision also has a separate `download_timeout` (default 30s) for the HTTP image download — increase this for slow connections or self-hosted image servers. ::: :::info