diff --git a/runner/server.py b/runner/server.py index e8a3571a..8c153278 100644 --- a/runner/server.py +++ b/runner/server.py @@ -5818,6 +5818,28 @@ def _relay_last_finish(env: dict) -> str: return str(_turn_relay_flags(env).get("last_finish") or "").replace("-", "_") +def _relay_refusal_unsaid(env: dict, *said: str) -> str: + """The provider's refusal of this turn's last call on its route, as the relay read it, when the + reason the turn would otherwise give (`said`) does not carry it; "" otherwise. + + A CLI reports a refusal only as far as its client could read the body. Qwen Code 0.26.3 reads + the reason only under an `error` key, and vLLM up to 0.10.0 puts `message` at the top level + (`{"object":"error","message":...}`; nested from 0.10.1), so a turn vLLM refused for a window + too small read "API Error: 400 status code (no body)", while vLLM had said "This model's maximum + context length is 28672 tokens. However, you requested 49351 tokens ..." (#612, measured through + the relay with 0.26.3 at a stub, and at a real vLLM v0.8.5.post1 in #578). The relay passed that + body on byte for byte and kept its words on the route (`last_refusal`, _refusal_words, which + reads both shapes); only the hermes path read them. A CLI whose reason already has the words + keeps its own sentence: the comparison is on the message's start, which survives a CLI's own + prefix ("[API Error: 400 ...]"). A refusal with no message beyond its status says nothing the + CLI's "400" does not.""" + words = str(_turn_relay_flags(env).get("last_refusal") or "") + msg = words.split(": ", 1)[1].strip() if ": " in words else "" + if not msg or any(msg[:60] in s for s in said): + return "" + return f"The model provider refused the request ({words})" + + def _relay_served_model(env: dict) -> str: """What the relay saw the provider serve on this turn's route, "" when the turn did not ride the relay or nothing answered yet (see _turn_relay_flags for which route that is).""" @@ -6134,6 +6156,10 @@ def _forward(self, body: bytes | None) -> None: plain, body = body, leveled headers["content-length"] = str(len(body)) effort_back = False # the level was taken out after a refusal; a success now means it was the cause + # A new call: an earlier call's refusal is not this one's. Kept, it was a turn's reason when + # this call then went unanswered (a dropped connection, a timeout) and the CLI failed of that + # (_relay_refusal_unsaid, #612). A refusal of this call sets it again below. + flags.pop("last_refusal", None) resp = None tried_slim = False dropped_once = False @@ -6142,6 +6168,10 @@ def _forward(self, body: bytes | None) -> None: method=self.command, headers=headers) try: resp = urllib.request.urlopen(req, timeout=HR_RELAY_UPSTREAM_TIMEOUT_S) + # Answered: this call's own refusal was repaired (its retry without stream_options, + # an unknown field, a level), and a turn that fails later fails for another reason, + # which the refusal must not be read as (_relay_refusal_unsaid, #612). + flags.pop("last_refusal", None) if effort_back: # the provider took the call without the level: not offered again for this model flags[f"effort_refused:{effort_model}"] = True @@ -14377,8 +14407,14 @@ def _settle(ev: dict) -> None: # providers' phrasings ("HTTP 503", "Error code: 429", "503 Service Unavailable") and # tightening it to exclude a bare number would risk missing a real refusal — the frames # are what does not belong in the search. - refusal = next((ln.strip() for ln in tail.splitlines() - if _PROVIDER_REFUSAL.search(ln)), "") + # The provider's own words come before a line of the CLI's that merely names the status: the + # relay saw the refusal the CLI could not read ("API Error: 400 status code (no body)" from + # Qwen Code on vLLM 0.10.0's body, #612), and "429 status code (no body)" would otherwise be + # the line the search below picks. + # Compared with the reason the turn would give without them, not with everything the CLI + # printed: words in the stderr tail behind a result's "(no body)" are not what a person reads. + said = next((ln.strip() for ln in tail.splitlines() if _PROVIDER_REFUSAL.search(ln)), "") + refusal = _relay_refusal_unsaid(env, _failure_reason(said, str(ev_err), tail, rc)) or said if not refusal and _relay_last_finish(env) == "content_filter": # THE PROVIDER DECLINED, and the CLI's own account of a failure it could not see is not # the reason. A refused request comes back as an answer with no content and no diff --git a/runner/tests/test_relay_refusal_reason.py b/runner/tests/test_relay_refusal_reason.py new file mode 100644 index 00000000..95bfcfc7 --- /dev/null +++ b/runner/tests/test_relay_refusal_reason.py @@ -0,0 +1,169 @@ +"""A failed turn's reason is the provider's refusal as the relay read it, when the CLI could not read +it (#612). + +Qwen Code 0.26.3 reads a refusal's reason only under an `error` key. vLLM up to 0.10.0 puts `message` +at the top level, so a turn vLLM refused for a window too small read "API Error: 400 status code (no +body)" while the relay held vLLM's sentence on the route. Measured with the real CLI at a stub +through the relay, and on a real vLLM v0.8.5.post1 in #578. + +Each test runs a turn through _run_turn_bg, the generic path whose reason the gateway shows ("The +turn failed: "), with a fake CLI that makes its calls through the route _build_qwen +registers, prints the stream-json events Qwen Code 0.26.3 printed on such a refusal (captured +2026-10-29), and exits 1 as it did. +""" +import json +import os +import sys +import threading +import time +from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer + +sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..")) +from server import Auth, _build_qwen, _claude_passthrough, _relay_refusal_unsaid, _run_turn_bg, _turns # noqa: E402 + +VLLM_SAID = ("This model's maximum context length is 8192 tokens. However, you requested 49350 tokens " + "(16582 in the messages, 32768 in the completion). Please reduce the length of the messages " + "or completion.") +# vLLM <=0.10.0's ErrorResponse, as the #578 capture proxy recorded it, and OpenAI's shape (vLLM >=0.10.1) +FLAT = json.dumps({"object": "error", "message": VLLM_SAID, "type": "BadRequestError", "param": None, "code": 400}).encode() +NESTED = json.dumps({"error": {"message": VLLM_SAID, "type": "BadRequestError", "param": None, "code": 400}}).encode() + +# The fake CLI: each body in FAKE_CALLS goes to the route as a chat-completions call, then the events +# Qwen Code printed for a failed run, with FAKE_SAYS as its message, and exit 1. +_CLI = r''' +import json, os, sys, urllib.error, urllib.request +for body in json.loads(os.environ["FAKE_CALLS"]): + req = urllib.request.Request(os.environ["OPENAI_BASE_URL"] + "/chat/completions", method="POST", + data=json.dumps(body).encode(), + headers={"authorization": "Bearer " + os.environ["OPENAI_API_KEY"], + "content-type": "application/json"}) + try: + urllib.request.urlopen(req, timeout=10).read() + except urllib.error.HTTPError as e: + e.read() +if os.environ.get("FAKE_STDERR"): + print(os.environ["FAKE_STDERR"], file=sys.stderr, flush=True) +says, sid = os.environ["FAKE_SAYS"], "9c87656f-c69b-48cb-8b6d-b0eecd6b670f" +for ev in ({"type": "system", "subtype": "init", "session_id": sid, "model": "qwen3-4b"}, + {"type": "assistant", "session_id": sid, "parent_tool_use_id": None, + "message": {"type": "message", "role": "assistant", "model": "qwen3-4b", + "content": [{"type": "text", "text": says}], "stop_reason": None}}, + {"type": "result", "subtype": "error_during_execution", "session_id": sid, "is_error": True, + "num_turns": 1, "usage": {"input_tokens": 0, "output_tokens": 0}, "error": {"message": says}}): + print(json.dumps(ev), flush=True) +sys.exit(1) +''' + + +def _call(stream_options: bool) -> dict: + body = {"model": "qwen3-4b", "stream": True, "messages": [{"role": "user", "content": "hi"}]} + if stream_options: + body["stream_options"] = {"include_usage": True} + return body + + +class _Provider(BaseHTTPRequestHandler): + """Refuses with `refusal` every call it is told to refuse; answers a one-word stream otherwise.""" + refusal = FLAT + refuse = staticmethod(lambda body: True) + + def do_POST(self): + body = json.loads(self.rfile.read(int(self.headers.get("content-length") or 0)) or b"{}") + if "drop me" in json.dumps(body): + self.close_connection = True # the connection closes with no answer at all + return + if type(self).refuse(body): + out, code, ctype = type(self).refusal, 400, "application/json" + else: + chunk = {"id": "c1", "object": "chat.completion.chunk", "model": "qwen3-4b", + "choices": [{"index": 0, "delta": {"content": "DONE"}, "finish_reason": "stop"}]} + out, code, ctype = b"data: " + json.dumps(chunk).encode() + b"\n\ndata: [DONE]\n\n", 200, "text/event-stream" + self.send_response(code) + self.send_header("content-type", ctype) + self.send_header("content-length", str(len(out))) + self.end_headers() + self.wfile.write(out) + + def log_message(self, *a): + pass + + +def _turn(tmp_path, refusal: bytes, refuse, calls: list[dict], says: str, stderr: str = "") -> dict: + handler = type("Provider", (_Provider,), {"refusal": refusal, "refuse": staticmethod(refuse)}) + up = ThreadingHTTPServer(("127.0.0.1", 0), handler) + threading.Thread(target=up.serve_forever, daemon=True).start() + cli = tmp_path / "fake_qwen.py" + cli.write_text(_CLI) + env = {**os.environ, "FAKE_CALLS": json.dumps(calls), "FAKE_SAYS": says, "FAKE_STDERR": stderr} + _build_qwen("openai-api", Auth(api_key="sk-local", base_url=f"http://127.0.0.1:{up.server_address[1]}/v1"), + "qwen3-4b", "hi", str(tmp_path), env) + tid = f"t-{time.time()}" + _turns[tid] = {"status": "running", "events": [], "result": "", "done": False, + "started": time.time(), "backend": "qwen", "model": "qwen3-4b"} + try: + _run_turn_bg(tid, [sys.executable, str(cli)], env, str(tmp_path), _claude_passthrough, "qwen3-4b", + timeout_seconds=30) + return _turns[tid] + finally: + _turns.pop(tid, None) + up.shutdown() + + +def test_a_refusal_the_cli_could_not_read_is_the_turns_reason(tmp_path): + """The bug: the reason was Qwen Code's "API Error: 400 status code (no body)".""" + rec = _turn(tmp_path, FLAT, lambda b: True, [_call(True)], "[API Error: 400 status code (no body)]") + assert rec["status"] == "failed" + assert rec["error"] == f"The model provider refused the request (400: {VLLM_SAID})" + + +def test_a_cli_that_read_the_refusal_keeps_its_own_sentence(tmp_path): + """OpenAI's shape (vLLM >=0.10.1): Qwen Code says the reason itself, and its sentence stands + as it did before #612.""" + says = f"[API Error: 400 {VLLM_SAID}]" + rec = _turn(tmp_path, NESTED, lambda b: True, [_call(True)], says) + assert rec["status"] == "failed" + assert VLLM_SAID in rec["error"] and "The model provider refused" not in rec["error"] + + +def test_a_refusal_the_relay_repaired_is_not_the_reason_for_a_later_failure(tmp_path): + """The provider refuses the call with stream_options and answers it without (the relay's own + one-time retry repairs it); the CLI then fails for a reason of its own. The repaired refusal was + left on the route before #612, and is not what this turn failed of.""" + says = "Error: the tool registry failed to load" + rec = _turn(tmp_path, FLAT, lambda b: "stream_options" in b, [_call(True)], says) + assert rec["status"] == "failed" + assert "Please reduce the length" not in rec["error"] + assert "tool registry failed to load" in rec["error"] + + +def test_a_later_refusal_after_an_answer_is_still_the_reason(tmp_path): + """Clearing on an answer forgets only what came before it: the turn's last call refused is + still read, after an answered one on the same route.""" + calls = [_call(False), {**_call(False), "messages": [{"role": "user", "content": "too long"}]}] + rec = _turn(tmp_path, FLAT, lambda b: "too long" in json.dumps(b), calls, + "[API Error: 400 status code (no body)]") + assert rec["error"] == f"The model provider refused the request (400: {VLLM_SAID})" + + +def test_a_refusal_before_a_call_that_went_unanswered_is_not_the_reason(tmp_path): + """The CLI got past a refused call and its next call was never answered (the connection closed), + which is what it failed of. The earlier refusal is not this turn's reason: each call starts the + route's record afresh.""" + calls = [{**_call(False), "messages": [{"role": "user", "content": "too long"}]}, + {**_call(False), "messages": [{"role": "user", "content": "drop me"}]}] + rec = _turn(tmp_path, FLAT, lambda b: "too long" in json.dumps(b), calls, "Connection error.") + assert rec["status"] == "failed" + assert "Please reduce the length" not in rec["error"] and "Connection error." in rec["error"] + + +def test_words_only_in_the_stderr_tail_are_not_what_the_turn_says(tmp_path): + """The CLI printed the provider's sentence to stderr and its result said "(no body)": the reason a + person reads is the result's, so the provider's words are still unsaid and lead it.""" + rec = _turn(tmp_path, FLAT, lambda b: True, [_call(True)], "[API Error: 400 status code (no body)]", + stderr=f"debug: upstream said {VLLM_SAID}") + assert rec["error"] == f"The model provider refused the request (400: {VLLM_SAID})" + + +def test_no_route_or_no_words_leaves_the_reason_to_the_cli(): + assert _relay_refusal_unsaid({}, "anything") == "" # the turn did not ride the relay + assert _relay_refusal_unsaid({"X": "not-a-relay-token"}, "") == ""