[OMEGA-423] Fix nginx proxy cutting off slow LLM responses (#321) - #351
Leul-Negash wants to merge 13 commits into
Conversation
Every LLM request in the Docker image goes through the nginx proxy, and the LLM routes used the global 120s proxy_read_timeout and proxy_send_timeout. When a response takes longer, nginx returns 504, the OpenAI client retries twice with the same result, and AIProvider.chat ends up returning "", so the agent never answers. The OpenAI client waits up to 600s, so set 600s on the anthropic, asicloud, openai, asione, openaiapi and openrouter routes, the same override the OpenClaw route already has. The channel routes keep the 120s default. Add a unit test that reads the template and fails when an LLM route waits less than 600s, and register it in run_mandatory.
timur-ashkenov
left a comment
timur-ashkenov
left a comment
There was a problem hiding this comment.
@Leul-Negash Could we handle the final provider timeout explicitly?
After the configured timeout and exhausted retries, the agent should stop waiting and send the user a clear status message, such as: “LLM request timed out. Please try again later.” Returning an empty LLM result leaves the task silently abandoned.
paul-v-snet
changed the title
After a provider request runs out of time and the client's retries are gone, chat() returned an empty string. The loop then had no command to run, so the turn ended without a word and the task looked abandoned, which is the symptom reported in #321. A timeout now comes back as a (send ...) command carrying a short status message, the same shape the token-limit case already uses, so the loop delivers it on the channel the user is on. It covers the client's own timeout and the 408/504/524 statuses a gateway returns when the upstream did not answer in time; every other failure still returns an empty string, as before. Add unit tests for which failures count as a timeout, what chat() returns in each case, and that the message parses into a single send command.
The unit tier runs on the CI runner with plain pytest, where openai and httpx are not installed, so importing them collected as an error and the job failed. Stub openai and the configuration module before loading lib_llm_ext, the same way test_openclaw_unit.py does, and drop the httpx import.
|
@timur-ashkenov Done in 4f9f90e. A timed-out request now returns a Verified in the image with the provider pointed at an endpoint answering 504 immediately: after the retries the agent runs Added One check: by "stop waiting" did you mean the total wait as well? Right now the route timeout plus two client retries can take up to ~30 minutes before the message goes out. I can shorten the client timeout or reduce the retries if you want that capped. |
@Leul-Negash , Yes, I meant the total wait should be bounded as well. Waiting up to ~30 minutes before notifying the user would still reproduce the poor user experience from the issue. I suggest keeping the 600-second timeout for one legitimately slow response, but avoiding additional retries after a timeout/504. The agent should send the timeout status once that first request reaches its limit. |
The client retried a timed-out request twice before raising, so with the 600s route timeout a user could wait about half an hour before the status message went out. Build the chat clients with max_retries=0, so one request runs to its timeout and the message goes out then. The loop asks again on its next iteration anyway. Embeddings are untouched, they build their own clients in src/rag.py. Add tests that both the proxy and the direct client are built with a single attempt.
|
@timur-ashkenov Understood, bounded in ed1ab86. The chat clients are now built with Verified against an endpoint answering 504 immediately: no retries logged, one request per cycle, and the message reaches the channel a second after the request fails. Two more tests check both the proxy and the direct client are built with a single attempt. |
@Leul-Negash Could we confirm that disabling retries globally is intentional?
I agree that the total wait must be bounded, but this changes retry behavior across all providers. Could we either document and explicitly accept this trade-off, or use a retry policy that preserves limited retries for non-timeout transient failures? |
Turning the SDK retries off bounded the wait, but it also removed their recovery for transient failures on every provider. The SDK cannot express the split: it decides status retries in _should_retry, yet repeats a timed-out request unconditionally. So the decision moves into _retrying(). Transient failures (409, 429, 500, 502, 503 and connection errors) get up to three attempts with a short backoff. A timeout, or a gateway timeout status, is never retried: it already spent the request timeout and the user is waiting. Nothing is retried once a 60-second budget is gone, so a failure that already cost minutes does not restart the wait. All three chat implementations go through it. Embeddings keep the client defaults, they build their own clients in src/rag.py. Add tests for the classification, the attempt limit, the budget, and that a timeout is attempted once.
|
@timur-ashkenov Fair point, that was too broad. Fixed in 7bd71f8. Retries are back for transient failures and skipped only for timeouts. The SDK cannot split it that way: status retries go through Checked in the image: the endpoint answering 504 gives one attempt per cycle and the status message on the channel, the one answering 503 gives three attempts with the backoff and no status message. Tests cover the classification, the attempt limit, the budget, and that a timeout is attempted once. CI is green. |
|
Tested: images built from this PR at 7bd71f8 and from main 6657798, each started by scripts/omega with What I checked
529 and Retry-After now end in silenceA 529 followed by a normal answer: main retries and replies in 1.5 s. With the PR, the stub gets one request, the agent logs A 429 with Both come from TRANSIENT_STATUSES, which stops at 503, and from the fixed 0.5 s and 1 s sleeps, which do not read Retry-After. The comment above the list says it holds the statuses the SDK retries by default, but on main the SDK also retries 529 and 522. A second timeout in a row is droppedThe timeout message is the same text every time, and send drops a message equal to the last one it sent. Right after the 700 s case, the next message hit a 504. At 05:14:17, the agent logged A smaller issue: the message says "the retries were exhausted", while a timeout gets one request. Verdict: FAIL |
Retry classification followed a hand-written status list that stopped at 503, so 529 and 522 were reported as failures instead of retried. It now follows the same rule as the SDK, 409, 429 and any 5xx, with the timeout statuses left to _is_timeout_error so they are reported rather than retried. The wait between attempts ignored Retry-After, so a 429 asking for five seconds got three attempts inside 1.5s and then silence. _retry_delay uses Retry-After when the provider sends one in seconds, falls back to the backoff for the HTTP-date form, and refuses a retry whose wait would not fit in the budget. The timeout notice was the same text every time, and send drops a message equal to the last one it sent, so a second timeout in a row left that turn silent. The notice now carries the time. Classifying an error no longer reads the exception classes off the client module directly. With a client that does not define them the lookup raised inside the except block and masked the error being classified. Also drop the claim that the retries were exhausted, since a timeout is attempted once. Add tests for the 5xx rule, Retry-After in seconds and as a date, a wait that exceeds the budget, and two notices in a row differing.
|
@TossSky Thanks, all four are fixed in 1004c10. 529 and 522: the status list was mine and it stopped at 503. Classification now follows the same rule as the SDK, 409, 429 and any 5xx, with 408, 504 and 524 left to the timeout path so they are reported instead of retried. Retry-After: the sleeps were fixed at 0.5s and 1s. Second timeout in a row: right, the text was identical and
Rechecked in the image with a stub that scripts the answers: 529 then a normal answer is retried after 0.5s and the reply arrives; 429 with One thing worth flagging: with a gateway that answers 504 instantly the user gets a notice every cycle. In production a 504 means the proxy already waited 600s, so they are spaced out, and I left it uncapped rather than adding suppression back. Happy to add a minimum interval if you would rather have one. |
| sent, so without it a second timeout in a row would leave that turn silent, | ||
| which is the symptom this whole change is about. | ||
| """ | ||
| message = LLM_TIMEOUT_MESSAGE.format(time=time.strftime("%H:%M:%S")) |
There was a problem hiding this comment.
@Leul-Negash The timestamp is only precise to one second, so two immediate timeout/504 cycles within the same second still produce identical (send ...) commands. Since send drops a message equal to the previous one, the second user message can again be silently lost. Please use a per-notification unique value (for example, a monotonic nonce or sub-second timestamp).
There was a problem hiding this comment.
@timur-ashkenov Good catch, fixed in 76ef473.
The notice now carries the time to the millisecond, and the admin line carries a count that rises with every notice, so two of them differ even when the clock does not move between them. A test freezes the clock and checks that two notices in a row are still different; while checking by hand I hit the case for real, two notices inside the same millisecond, and they differ by the count.
Unit tests are at 39 in test_llm_timeout_message.py and 127 in the unit tier. CI is green.
The notice carried the time to the second, so two cycles failing inside the same second rendered the same message, and send drops a message equal to the last one it sent: that turn went silent again. The notice now carries the time to the millisecond and a count that rises with every notice, so two of them differ even when the clock does not move. The test freezes the clock and checks exactly that.
|
Tested: image built from this PR at 76ef473, started by scripts/omega with What I checked
A notice is sent on every timed-out cycle, even with no new messageWith the default config, the loop calls the model up to 50 times after startup and up to 50 times again after each new message. Every call that times out sends its own notice. With an instant 504 on every request, the channel got 50 notices in 50 s before any message was sent, and 50 more after one message. With a provider address that never answers, nginx gives up connecting after 30 s and returns 504, and a notice arrived every 31 s with no message sent. The minimum interval you offered would only space these out. Timeouts in a row need one notice, and nothing more until a call succeeds or a new message comes in. Raising the route timeout above 600 s would not helpThe notice suggests raising the route timeout in the proxy, but the SDK client is created without a timeout and keeps its default 600 s read timeout, so a request would still end at 600 s. Verdict: FAIL |
The loop calls the provider up to maxNewInputLoops times after startup and again after each message, and every timed-out call sent its own notice: with an instant 504 that put 50 notices on the channel in 50 seconds. A provider now reports a timeout once per run of them. The run ends when a call succeeds, or when a prompt carries a human message, since that turn is waiting for an answer of its own. In between the timeout is logged and nothing is sent. The notice also suggested raising the route timeout in the proxy, but the client kept its own 600 s default, so the request ended there regardless. The client is now created with that timeout explicitly, and the notice names the number and says both limits have to be raised to allow longer answers.
| @@ -21,6 +22,43 @@ | |||
| "reasoning levels need a higher token limit." | |||
| ) | |||
|
|
|||
| LLM_TIMEOUT_MESSAGE = ( | |||
| "LLM request timed out at {time}. Please try again later." | |||
| "\n\n" | |||
| "If you are the Omega administrator: the provider did not answer within the " | |||
| "{timeout} s request timeout, and a timed-out request is not retried. This is " | |||
| "timeout notice {count} since the agent started. The failed request is in the " | |||
| "agent log; check the provider status. The limit is enforced by the client and " | |||
| "by the provider\'s route in the proxy, so allowing longer answers means " | |||
| "raising both." | |||
| ) | |||
|
|
|||
| # Statuses a gateway returns when the upstream did not answer in time. | |||
| GATEWAY_TIMEOUT_STATUSES = (408, 504, 524) | |||
|
|
|||
| # The request timeout the client enforces. It matches the proxy route timeout, so | |||
| # a slow answer is cut once, by whichever limit is reached first, and the notice | |||
| # can name a single number. | |||
| CHAT_REQUEST_TIMEOUT_SECONDS = 600 | |||
|
|
|||
| # One attempt per chat request inside the SDK. Its retry loop repeats a timed-out | |||
| # request unconditionally, which would multiply the request timeout before the | |||
| # user hears anything. Transient failures are retried by _retrying() below | |||
| # instead, where a timeout can be excluded. | |||
| CHAT_MAX_RETRIES = 0 | |||
|
|
|||
| # Failures worth trying again right away. The SDK retries 409, 429 and any 5xx, | |||
| # so keep that rule rather than a list that misses one (529 and 522 both reach | |||
| # here); the timeout statuses are excluded by _is_timeout_error above, so they are | |||
| # reported instead of retried. | |||
| TRANSIENT_STATUSES = (409, 429) | |||
| # First attempt plus two retries, and only while the whole call stays inside the | |||
| # budget: a failure that already cost minutes is not "transient", and the user is | |||
| # waiting for an answer. | |||
| CHAT_ATTEMPTS = 3 | |||
| CHAT_RETRY_BUDGET_SECONDS = 60 | |||
| CHAT_RETRY_BACKOFF_SECONDS = 0.5 | |||
|
|
|||
|
|
|||
| logger = get_logger(__name__) | |||
|
|
|||
| @@ -67,6 +105,87 @@ def _llm_empty_response_command() -> str: | |||
| """ | |||
| return f"(send {quote_arg(LLM_EMPTY_RESPONSE_MESSAGE)})" | |||
|
|
|||
| def _is_timeout_error(error: BaseException) -> bool: | |||
| """True when the request ran out of time rather than failing outright: the | |||
| client's own timeout, or a timeout status from the gateway in front of the | |||
| provider (the proxy answers 504 when the upstream is still thinking). | |||
| """ | |||
| # The classes are looked up rather than referenced: classifying a failure must | |||
| # never raise one of its own, whatever the installed client exposes. | |||
| if isinstance(error, getattr(openai, "APITimeoutError", ())): | |||
| return True | |||
| return getattr(error, "status_code", None) in GATEWAY_TIMEOUT_STATUSES | |||
|
|
|||
| _timeout_notices = 0 | |||
|
|
|||
| def _llm_timeout_command() -> str: | |||
| """Return a status message as a MeTTa `send` command when the request times | |||
| out, so the turn ends with the user told instead of in silence. | |||
|
|
|||
| `send` drops a message equal to the last one it sent, so two notices must | |||
| never render the same: a second timeout would leave that turn silent, which is | |||
| the symptom this whole change is about. The time alone does not guarantee it, | |||
| since two cycles can fail inside the same second, so the notice carries the | |||
| time to the millisecond and a count that rises with every notice. | |||
| """ | |||
| global _timeout_notices | |||
| _timeout_notices += 1 | |||
| stamp = datetime.now().strftime("%H:%M:%S.%f")[:-3] | |||
| message = LLM_TIMEOUT_MESSAGE.format( | |||
| time=stamp, count=_timeout_notices, timeout=CHAT_REQUEST_TIMEOUT_SECONDS) | |||
| return f"(send {quote_arg(message)})" | |||
|
|
|||
| def _is_transient_error(error: BaseException) -> bool: | |||
| """True for a failure that another attempt may get past. A timeout is not | |||
| one of them: it already spent the request timeout, so retrying it only keeps | |||
| the user waiting. | |||
| """ | |||
| if _is_timeout_error(error): | |||
| return False | |||
| if isinstance(error, getattr(openai, "APIConnectionError", ())): | |||
| return True | |||
| status = getattr(error, "status_code", None) | |||
| if status is None: | |||
| return False | |||
| return status in TRANSIENT_STATUSES or status >= 500 | |||
|
|
|||
| def _retry_delay(error: BaseException, attempt: int) -> float: | |||
| """How long to wait before the next attempt: the provider's Retry-After when | |||
| it sends one in seconds, otherwise a short exponential backoff. A Retry-After | |||
| given as an HTTP date falls back to the backoff. | |||
| """ | |||
| headers = getattr(getattr(error, "response", None), "headers", None) | |||
| value = headers.get("retry-after") if hasattr(headers, "get") else None | |||
| if value is not None: | |||
| try: | |||
| return max(0.0, float(value)) | |||
| except (TypeError, ValueError): | |||
| pass | |||
| return CHAT_RETRY_BACKOFF_SECONDS * (2 ** (attempt - 1)) | |||
|
|
|||
| def _retrying(call, provider: str): | |||
| """Run call(), retrying only transient failures and only briefly. | |||
|
|
|||
| The SDK's own retries are off (CHAT_MAX_RETRIES), so this is the single place | |||
| that decides what gets another attempt: transient failures do, a timeout does | |||
| not, and nothing is retried once the budget is spent. | |||
| """ | |||
| started = time.monotonic() | |||
| for attempt in range(1, CHAT_ATTEMPTS + 1): | |||
| try: | |||
| return call() | |||
| except Exception as error: | |||
| if attempt == CHAT_ATTEMPTS or not _is_transient_error(error): | |||
| raise | |||
| delay = _retry_delay(error, attempt) | |||
| if time.monotonic() - started + delay >= CHAT_RETRY_BUDGET_SECONDS: | |||
| logger.warning( | |||
| f"[{provider}.chat]: retry budget spent, giving up: {error}") | |||
| raise | |||
| logger.warning( | |||
| f"[{provider}.chat]: transient failure, retrying in {delay:.1f}s: {error}") | |||
| time.sleep(delay) | |||
|
|
|||
| def _split_system_user(content: str) -> Tuple[str, str]: | |||
| """ | |||
| MeTTa sends: | |||
| @@ -129,6 +248,39 @@ def __init__(self, name: str, var_name: str, model_name: str, base_url: str): | |||
| self._model_name = model_name | |||
| self._base_url = base_url | |||
| self._client = None # lazy initialization | |||
| self._timeout_notice_sent = False | |||
|
|
|||
| def _start_of_turn(self, content: str) -> None: | |||
| """A prompt carrying a human message starts a fresh turn, which deserves | |||
| its own answer even if the previous cycle already timed out. | |||
|
|
|||
| The tail is read straight from the prompt rather than through | |||
| _split_system_user, which substitutes a placeholder when it is empty. The | |||
| loop fills the tail only on the cycle where the message is new, so any | |||
| tail here means a turn of its own. | |||
| """ | |||
| _, delimiter, tail = content.partition(PROMPT_DELIMITER) | |||
| if (tail if delimiter else content).strip(): | |||
| self._timeout_notice_sent = False | |||
|
|
|||
| def _answered(self) -> None: | |||
| """The provider answered, so the next timeout is a new run.""" | |||
| self._timeout_notice_sent = False | |||
|
|
|||
| def _timeout_reply(self) -> str: | |||
| """The notice for a timed-out request, once per run of timeouts. | |||
|
|
|||
| The loop keeps calling for up to maxNewInputLoops cycles, so a notice per | |||
| cycle would fill the chat with the same text. The run ends when a call | |||
| succeeds or a new human message arrives; until then the timeout is logged | |||
| and nothing is sent. | |||
| """ | |||
| if self._timeout_notice_sent: | |||
| logger.warning( | |||
| f"[{self.name}.chat]: timed out again, the user was already told") | |||
| return "" | |||
| self._timeout_notice_sent = True | |||
| return _llm_timeout_command() | |||
|
|
|||
| def _ensure_client(self): | |||
| """Initialize client on first use.""" | |||
| @@ -145,9 +297,13 @@ def _create_client(self) -> Optional[openai.OpenAI]: | |||
| return openai.OpenAI( | |||
| api_key="proxy", | |||
| base_url=base_url, | |||
| max_retries=CHAT_MAX_RETRIES, | |||
| timeout=CHAT_REQUEST_TIMEOUT_SECONDS, | |||
| ) | |||
| if self._var_name in os.environ: | |||
| return openai.OpenAI(api_key=os.environ.get(self._var_name), base_url=self._base_url) | |||
| return openai.OpenAI(api_key=os.environ.get(self._var_name), base_url=self._base_url, | |||
| max_retries=CHAT_MAX_RETRIES, | |||
| timeout=CHAT_REQUEST_TIMEOUT_SECONDS) | |||
|
|
|||
| return None | |||
|
|
|||
| @@ -169,19 +325,24 @@ def _build_messages(self, content: str): | |||
|
|
|||
| def chat(self, content: str, max_tokens: int = 6000, reasoning: str = "medium", **kwargs) -> str: | |||
| """Send chat request, initializing client if needed.""" | |||
| self._start_of_turn(content) | |||
| self._ensure_client() | |||
|
|
|||
| if self._client is None: | |||
| raise RuntimeError(f"{self.name} not configured (set {self._var_name})") | |||
|
|
|||
| try: | |||
| response = self._client.chat.completions.create( | |||
| model=self._model_name, | |||
| messages=self._build_messages(content), | |||
| max_tokens=max_tokens, | |||
| **kwargs | |||
| response = _retrying( | |||
| lambda: self._client.chat.completions.create( | |||
| model=self._model_name, | |||
| messages=self._build_messages(content), | |||
| max_tokens=max_tokens, | |||
| **kwargs | |||
| ), | |||
| self._name, | |||
| ) | |||
|
|
|||
| self._answered() | |||
| raw = response.choices[0].message.content or "" | |||
| finish_reason = getattr(response.choices[0], "finish_reason", None) | |||
| _log_raw(self._name, self._model_name, raw) | |||
| @@ -194,6 +355,8 @@ def chat(self, content: str, max_tokens: int = 6000, reasoning: str = "medium", | |||
| return resp | |||
| except Exception as e: | |||
| logger.exception(f"[AIProvider.chat]: Exception while communicating with LLM: {e}") | |||
| if _is_timeout_error(e): | |||
| return self._timeout_reply() | |||
| return "" | |||
|
|
|||
| def _clean_text(self, text: str) -> str: | |||
There was a problem hiding this comment.
@Leul-Negash _start_of_turn() treats every non-empty prompt tail as a new human message. With the still-supported spamShield: True, the loop sends DO NOT RE-SEND OR SPAM! on every follow-up cycle, resets _timeout_notice_sent, and resumes one timeout notice per cycle. Please reset only when the tail is an actual HUMAN-MSG: payload.
There was a problem hiding this comment.
@timur-ashkenov Fixed in 84a4520.
The reset now requires the loop's HUMAN-MSG: tag, so the spamShield reminder and an empty tail leave the run alone. Checked in the image with spamShield: True set in config.yaml and an endpoint answering 504 at once: 40 prompts carried the reminder, 21 failing cycles produced 2 notices and 19 suppressions, and the second notice went out a second after a real message arrived on the channel.
Two things I tightened on the way, in 4afcfa5 and 7d72e81: the OpenRouter client overrides _create_client, so it was the one client still on the library default while the notice named 600 s, and the route test now reads CHAT_REQUEST_TIMEOUT_SECONDS from the provider source instead of repeating the number. A test also checks the marker against the tag loop.metta writes, so renaming it cannot quietly break the reset.
Unit tier is at 137.
_start_of_turn treated any non-empty prompt tail as a new message. With spamShield on, the loop puts its reminder there on every follow-up cycle, which reset the run and brought back one notice per cycle. The reset now requires the loop's HUMAN-MSG: tag, however the tail wraps it, so the reminder and the empty tail leave the run alone. The OpenRouter client is created with the request timeout as well; it overrides _create_client, so it was the one client still relying on the library default while the notice named that limit. Tests cover the reminder not starting a run, the tag starting one in each form the tail can take, and the OpenRouter client carrying the timeout.
It overrides _create_client, so the limits it passes are worth a test of their own rather than being assumed from the base provider.
Two values were written in more than one place and could drift apart without anything noticing: the request timeout, which the proxy route has to match, and the HUMAN-MSG: tag, which the notice reset keys off. The route test now reads CHAT_REQUEST_TIMEOUT_SECONDS out of the provider source instead of repeating the number, and a test checks the marker against the tag the loop actually writes. The source is read rather than imported, since the provider SDK is not installed where this suite runs.
This branch has not been deployed
3 participants
Description
Fixes #321.
In the Docker image every LLM request goes through the nginx proxy. The LLM routes use the global 120s
proxy_read_timeout/proxy_send_timeout, so a response that takes longer comes back as 504. The OpenAI client retries twice, gets 504 again, andAIProvider.chatreturns"", so the agent never replies. That matches the two 504s two minutes apart in the #321 logs.This sets 600s on the six LLM routes (
anthropic,asicloud,openai,asione,openaiapi,openrouter), which is how long the OpenAI client waits and the same override the OpenClaw route got in 27979ed. Channel routes keep the 120s default.It also adds
Autotests/unit/test_nginx_llm_timeouts.py, which fails if an LLM route waits less than 600s, and registers it inrun_mandatory.How Has This Been Tested?
Ran the image with the
OpenAIAPIprovider pointed at a local OpenAI-compatible endpoint that answers after 150s, on thetestchannel:main: nginx loggedupstream timed outand returned 504 at 120s, three times, thenException while communicating with LLM: 504 Gateway Time-outand nothing was sent.The new test fails on
main(12 failed) and passes here (12 passed).Autotests/unit73 passed,tests/65 passed, andnginx -tpasses on the rendered template inside the image.I couldn't test against ASICloud directly. @olegryabchikov-dot, could you retest the Dune prompt on this branch when you have a chance?
Checklist