fix: bound auto-title timeouts to one window and name them in the log
A title request against a slow local model (a reasoning model on modest hardware) hit `auxiliary.title_generation.timeout`, was retried on the same provider twice more with backoff, and only then fell back — roughly four configured windows, exactly the 3x30s the reporter read off the Ollama access log — while the auto-title thread outlived the deadline the user thought they had set. The failure was logged at INFO as a "connection error", the same label as an unreachable endpoint, so the only WARNING the operator saw came from the fallback provider complaining about a model it never had, which reads as "your base_url was ignored". Title generation joins compression and vision in the existing critical-path rung that skips the same-provider retry after a full-budget timeout, and the fallback ladder now classifies a timeout before the connection-error rung and logs it at WARNING with the endpoint, the budget and the config key to raise. The route carries its effective timeout so the message can say how long it waited. Docs list the title default and the one-window rule. Slim redo of the retry/fallback half of #100013 on the existing rung; its 10s default and concurrency change are not carried. Fixes #89445 Part of #66251 Co-authored-by: AJ Fasano <ajfasano@gmail.com>
This commit is contained in:
@@ -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
|
||||
|
||||
1
contributors/emails/ajfasano@gmail.com
Normal file
1
contributors/emails/ajfasano@gmail.com
Normal file
@@ -0,0 +1 @@
|
||||
eyeonall
|
||||
@@ -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(
|
||||
|
||||
73
tests/agent/test_auxiliary_title_timeout_bound.py
Normal file
73
tests/agent/test_auxiliary_title_timeout_bound.py
Normal file
@@ -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
|
||||
@@ -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 <task>: request to <base_url> timed out after <N>s (raise auxiliary.<task>.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
|
||||
|
||||
Reference in New Issue
Block a user