diff --git a/README.md b/README.md index a3db1ddf..790c75aa 100644 --- a/README.md +++ b/README.md @@ -105,7 +105,7 @@ For the complete list of all available environment variables, examples, and deta ### When vLLM will not start -Some startup failures a restart cannot fix: the model does not fit the GPU, `MAX_MODEL_LEN` is larger than the KV cache the GPU can hold, a flag or value vLLM rejects, a gated model without `HF_TOKEN`, a model that requires repository-provided code without `TRUST_REMOTE_CODE=true`. Exiting on those crash-loops the worker: each attempt repeats the startup (for most of these, the download and the model load), and submitted jobs receive no result. +Some startup failures a restart cannot fix: the model does not fit the GPU, `MAX_MODEL_LEN` is larger than the KV cache the GPU can hold, a flag or value vLLM rejects, a gated model without `HF_TOKEN`, a model that requires repository-provided code without `TRUST_REMOTE_CODE=true`, a model whose own vLLM code states a requirement this worker's GPU or settings don't meet (for example the FlashInfer attention backend, or a newer GPU generation). Exiting on those crash-loops the worker: each attempt repeats the startup (for most of these, the download and the model load), and submitted jobs receive no result. The worker recognises these and stays up instead, answering every job with the cause and the fix: @@ -119,7 +119,7 @@ The worker recognises these and stays up instead, answering every job with the c } ``` -The same message is logged by the worker, and the full vLLM traceback stays in the worker logs above it. Anything unrecognised still exits non-zero, because a failed download or a bad host is worth another attempt. +The same message is logged by the worker, and the full vLLM traceback stays in the worker logs above it. Anything unrecognised still exits non-zero, because a failed download or a bad host is worth another attempt. For model code (`vllm/model_executor/models/`, `vllm/models/`), only an error whose message states a requirement ("requires", "only supports", "not supported on") counts; any other error there, and any failed start that shows a CUDA, NCCL, NVML, cuBLAS/cuDNN, ECC or Xid fault, still restarts. A requirement can depend on the GPU type, so on an endpoint that lists several, a worker on a GPU the model can't use answers jobs with the cause instead of leaving them to a worker that can: remove those GPU types from the endpoint. ## Option 2: Build Docker Image with Model Inside diff --git a/src/startup_errors.py b/src/startup_errors.py index 669abac9..97ef1106 100644 --- a/src/startup_errors.py +++ b/src/startup_errors.py @@ -57,6 +57,143 @@ # --- Disk ------------------------------------------------------------------- _NO_SPACE = re.compile(r"No space left on device|ENOSPC|errno 28|Disk quota exceeded|EDQUOT|errno 122", re.I) +# vLLM's log prefixes: "(EngineCore pid=1014) ERROR 10-21 20:41:12 [core.py:1543] " +# on logged lines, and a bare "(APIServer pid=496) " on raw output (vLLM 0.30). +_LOG_PREFIX = re.compile(r"^\([\w.-]+ pid=\d+\) (?:[A-Z]+ [\d-]+ [\d:]+ \[[^\]]*\] ?)?") +# A logged record's prefix has a level and a timestamp; only lines that share one +# belong to the same record. Raw output has no such boundary. +_RECORD = re.compile(r"\) [A-Z]+ [\d-]+ [\d:]+ \[") +_FRAME = re.compile(r'^\s+File "([^"]+)", line \d+') +_EXCEPTION = re.compile(r"^(?:AssertionError|RuntimeError|NotImplementedError|ValueError)(?:: .*)?$") +_ANY_EXCEPTION = re.compile(r"^[A-Za-z_][\w.]*(?:Error|Exception|Interrupt|Exit)\b(?::|$)") +# Wrappers vLLM raises after an engine process fails; they don't replace the cause. +_WRAPPER = re.compile(r"Engine core initialization failed|WorkerProc initialization failed") +_TRACEBACK_BREAK = re.compile( + r"^(?:Traceback \(most recent call last\):|The above exception|During handling of the above)" +) +# Model implementations: vllm/model_executor/models/.py, and the per-model +# packages under vllm/models// (since v0.22; v0.32.0 ships deepseek_v4, +# kimi_k3, minimax_m3 and others there). +_MODEL_CODE = re.compile(r"/vllm/(?:model_executor/)?models/") +# The model's code states what it needs: "Flint requires FlashInfer attention", +# "... requires the FlashInfer TRTLLM BF16 MoE backend", "only supported on ...". +# Where an error is raised says nothing about permanence (a driver fault inside +# load_weights also ends in model code); a stated requirement does. Autograd's +# "requires grad" errors are not configuration requirements. +_REQUIREMENT = re.compile( + r"\brequires?\b(?![ _]grad)|\bonly supports?\b|\bonly supported\b|\bnot supported (?:on|with|for|by)\b", + re.I, +) +# Host faults anywhere in the failed launch, including a CUDA error wrapped by a +# model-code exception: another host can succeed. Fault signatures only, so +# torch's NVML/pynvml warnings on a healthy host don't count. +_HOST_FAULT = re.compile( + r"CUDA (?:driver |unknown )?error|cudaError|CUDA-capable device|NVIDIA driver on your system is too old|" + r"NCCL error|nccl(?:System|Unhandled|Internal)\w*Error|Watchdog caught collective operation timeout|" + r"NVML_SUCCESS == r|NVMLError|nvml\w*Error|CUBLAS_STATUS|CUDNN_STATUS|illegal memory access|" + r"uncorrectable ECC|\bXid\b", + re.I, +) +# Transport trouble inside the quoted error itself (a retried download that +# succeeded elsewhere in the log must not count, so this only checks the message). +_TRANSPORT_FAULT = re.compile( + r"Connection (?:reset|refused|aborted)|timed out|Max retries exceeded|Temporary failure in name resolution|" + r"Too Many Requests|Service Unavailable|Bad Gateway|Gateway Time-?out|Internal Server Error", + re.I, +) + +# An engine process killed by a signal ("Failed core proc(s): {'EngineCore': -9}") +# died of something else, whatever model code logged earlier. +_ENGINE_KILLED = re.compile(r"Failed core proc\(s\): \{[^}]*: -\d+") +# A traceback logged below ERROR was caught and handled; it didn't end the launch. +_NOT_AN_ERROR_RECORD = re.compile(r"\) (?:DEBUG|INFO|WARNING) ") + + +def _without_nvlink_probe(output: str) -> str: + """Drop vLLM's "NVLink detection failed. This is normal ..." record (an NVMLError traceback + logged on PCIe hosts with tensor parallelism), so it isn't read as a host fault.""" + kept, skip_prefix = [], None + for raw in output.splitlines(): + prefix, line = _split_prefix(raw) + if "NVLink detection failed" in line and _RECORD.search(prefix): + skip_prefix = prefix + continue + if skip_prefix is not None and prefix == skip_prefix: + continue + skip_prefix = None + kept.append(raw) + return "\n".join(kept) + + +def _split_prefix(raw: str): + line = raw.rstrip() + match = _LOG_PREFIX.match(line) + return (match.group(0), line[match.end():]) if match else ("", line) + + +def model_code_error(output: str) -> Optional[str]: + """The stated requirement a model's own vLLM code failed on, if that is all that went wrong. + + Matches an exception whose innermost frame is model code and whose message + states a requirement the setup does not meet: flint asserts the FlashInfer + attention backend, and its BF16 MoE needs a Blackwell-only kernel. Those + fail identically on every start. Returns None when the failed launch shows + a host fault, when the matched exception's chain shows a transport fault, + or when a different exception (other than vLLM's wrappers) comes after the + match, since then the match isn't what ended the launch. + """ + if _HOST_FAULT.search(_without_nvlink_probe(output)) or _ENGINE_KILLED.search(output): + return None + found = None + last_file = None + message, message_prefix = None, None + chain, after_separator = [], False + + def finish(lines): + text = " ".join(lines) + if _REQUIREMENT.search(text) and not _TRANSPORT_FAULT.search(" ".join(chain + [text])): + return text[:300] + return None + + for raw in output.splitlines(): + prefix, line = _split_prefix(raw) + if message is not None: + # A multi-line message continues only inside one logged record (same + # timestamped prefix). The next record, multiprocessing's "Process + # EngineCore:", or a warning printed after a raw traceback are not part of it. + if (_RECORD.search(message_prefix) and prefix == message_prefix and line + and not line.startswith(" ") and not _FRAME.match(line) and not _TRACEBACK_BREAK.match(line)): + message.append(line) + continue + found = finish(message) or found + chain.append(" ".join(message)) + message = None + if _TRACEBACK_BREAK.match(line): + if line.startswith("Traceback") and not after_separator: + chain = [] # a new, unchained traceback + after_separator = not line.startswith("Traceback") + last_file = None + continue + frame = _FRAME.match(line) + if frame: + last_file = frame.group(1) + continue + if line.startswith(" ") or not line: + continue # source and caret lines under a frame + if (_EXCEPTION.match(line) and last_file and _MODEL_CODE.search(last_file) + and not _NOT_AN_ERROR_RECORD.search(prefix)): + message, message_prefix = [line], prefix + elif _ANY_EXCEPTION.match(line): + chain.append(line) + # A different exception after the match, other than vLLM's wrapper or a + # repeat of the same cause (logged copy, then raw copy), ended the launch. + if found and not _WRAPPER.search(line) and not found.startswith(line[:80]): + found = None + last_file = None # any other unindented line ends the frame list + if message is not None: + found = finish(message) or found + return found + # The model-access messages are shared with model_preflight.py, which detects # the same failures before the cold start; whether the user hits the fast path @@ -235,4 +372,15 @@ def classify(output: str, model: Optional[str] = None, oom_retried: bool = False f"weights are cached there instead." ) + raised = model_code_error(output) + if raised: + return ( + f"{named} failed inside vLLM's implementation of the model during " + f"startup: {raised.rstrip('.')}. The model's code requires something this " + f"worker's GPU or settings don't provide, so restarting this worker will not " + f"change it. Check the model card and vLLM's recipe for the attention backend " + f"(ATTENTION_BACKEND), GPU generation or dtype it needs. If the endpoint lists " + f"several GPU types, also remove the ones the model can't use." + ) + return None diff --git a/tests/test_startup_errors.py b/tests/test_startup_errors.py index 35ba86fd..2c512d28 100644 --- a/tests/test_startup_errors.py +++ b/tests/test_startup_errors.py @@ -230,3 +230,236 @@ def test_non_memory_failures_do_not_match(self): assert not memory_shortfall(REVISION_NOT_FOUND) assert not memory_shortfall(GATED) assert not memory_shortfall("Connection reset by peer while downloading") + + +# Tails of real worker logs (RecursiveSI/flint on an H200, vLLM 0.32.0rc1 day-0 +# image) in the order vLLM prints them, trimmed to the frames that matter: +# EngineCore logs the root cause with a prefix, multiprocessing prints an +# unprefixed "Process EngineCore:" and the raw traceback, and the API server's +# own traceback ends in a generic RuntimeError. +_EC = "(EngineCore pid=1079) ERROR 10-21 20:16:36 [core.py:1543] " +API_SERVER_TAIL = """(APIServer pid=503) INFO 10-21 20:16:36 [utils.py:628] [shutdown] Process manager: send sigterm to process EngineCore +Traceback (most recent call last): + File "/usr/local/lib/python3.12/dist-packages/vllm/v1/engine/utils.py", line 1468, in wait_for_engine_startup + raise RuntimeError( +RuntimeError: Engine core initialization failed. See root cause above. Failed core proc(s): {} +""" + + +def _flint_log(frames, exception): + traceback = ["Traceback (most recent call last):", *frames, exception] + logged = "".join(_EC + line + "\n" for line in ["EngineCore failed to start.", *traceback]) + raw = "Process EngineCore:\n" + "".join(line + "\n" for line in traceback) + return logged + raw + API_SERVER_TAIL + + +FLINT_ATTN = "AssertionError: Flint requires FlashInfer attention" +FLINT_MOE = ( + "RuntimeError: Flint BF16 decode MoE requires the FlashInfer TRTLLM BF16 MoE backend " + "without padding (got UnquantizedMoeBackend.TRITON)" +) +FLINT_NEEDS_FLASHINFER = _flint_log([ + ' File "/usr/local/lib/python3.12/dist-packages/vllm/v1/engine/core.py", line 1515, in run_engine_core', + " engine_core = EngineCoreProc(*args, engine_index=dp_rank, **kwargs)", + ' File "/usr/local/lib/python3.12/dist-packages/vllm/models/flint/model.py", line 479, in __init__', + " self.self_attn = FlintAttention(", + " ^^^^^^^^^^^^^^^", + ' File "/usr/local/lib/python3.12/dist-packages/vllm/models/flint/model.py", line 316, in __init__', + ' assert isinstance(impl, FlashInferImpl), "Flint requires FlashInfer attention"', + " ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^", +], FLINT_ATTN) +FLINT_MOE_NEEDS_BLACKWELL = _flint_log([ + ' File "/usr/local/lib/python3.12/dist-packages/vllm/model_executor/warmup/kernel_warmup.py", line 294, in kernel_warmup', + " mixed_batch_attention_warmup(worker)", + ' File "/usr/local/lib/python3.12/dist-packages/vllm/models/flint/ops/moe.py", line 806, in forward', + " self._check(routed_experts)", + ' File "/usr/local/lib/python3.12/dist-packages/vllm/models/flint/ops/moe.py", line 792, in _check', + " raise RuntimeError(", +], FLINT_MOE) + + +def _traceback(innermost: str, exception: str, function: str = "__init__") -> str: + return ( + "Traceback (most recent call last):\n" + ' File "/usr/local/lib/python3.12/dist-packages/vllm/v1/engine/core.py", line 157, in __init__\n' + " kv_cache_config = self._initialize_kv_caches(vllm_config)\n" + f' File "/usr/local/lib/python3.12/dist-packages/{innermost}", line 42, in {function}\n' + " raise\n" + f"{exception}\n" + ) + + +class TestModelCodeErrors: + @pytest.mark.parametrize("output,cause", [(FLINT_NEEDS_FLASHINFER, FLINT_ATTN), (FLINT_MOE_NEEDS_BLACKWELL, FLINT_MOE)]) + def test_quote_exactly_the_root_cause(self, output, cause): + message = classify(output, model="RecursiveSI/flint") + + # Exactly the exception, not the next log line ("Process EngineCore:") or the wrapper. + assert f"during startup: {cause}. The model's code requires" in message + assert "Process EngineCore" not in message and "Engine core initialization failed" not in message + assert "ATTENTION_BACKEND" in message and "several GPU types" in message + + @pytest.mark.parametrize( + "harmless", + [ + # torch on a Runpod host with partial NVML support (seen in this image's logs) + "UserWarning: nvmlDeviceGetComputeRunningProcesses failed; omitting per-process memory info " + "from CUDA out-of-memory messages. This is expected on platforms with partial NVML support.", + "FutureWarning: The pynvml package is deprecated. Please install nvidia-ml-py instead.", + # a download retry that then succeeded + "WARNING huggingface_hub: HTTPSConnectionPool(host='cas-bridge.xethub.hf.co', port=443): " + "Read timed out. (read timeout=10) Retrying in 1s [Retry 1/5].", + # c10d's connect retry with tensor parallelism + "[W1021 20:16:30 socket.cpp:767] [c10d] The client socket has failed to connect to [::1]:29500 " + "(errno: 111 - Connection refused).", + "(EngineCore pid=1079) INFO 10-21 20:16:34 [parallel_state.py:1911] world_size=1 rank=0 backend=nccl", + ], + ) + def test_harmless_lines_elsewhere_in_the_launch_do_not_block_it(self, harmless): + message = classify(harmless + "\n" + FLINT_NEEDS_FLASHINFER, model="RecursiveSI/flint") + + assert message and FLINT_ATTN in message + + @pytest.mark.parametrize( + "exception", + [ + "NotImplementedError: FooAttention only supports compute capability 9.0 and above", + "ValueError: Sliding window attention is not supported on this platform", + "RuntimeError: FooMoE requires the CUTLASS backend", + ], + ) + def test_stated_requirements_in_classic_model_code(self, exception): + assert exception in classify(_traceback("vllm/model_executor/models/foo.py", exception)) + + def test_multiline_requirement_within_one_record(self): + lines = _traceback("vllm/models/foo/model.py", "RuntimeError: Foo decode kernel\nrequires sm100 (got sm90)").splitlines() + output = "".join(_EC + line + "\n" for line in lines) + + assert "RuntimeError: Foo decode kernel requires sm100 (got sm90)" in classify(output) + + def test_raw_tracebacks_are_never_joined_with_the_next_line(self): + # torch prints this at process exit; raw output has no record boundary. + teardown = ("[rank0]:[W1021 20:16:37.1 ProcessGroupNCCL.cpp:1538] Warning: WARNING: destroy_process_group() " + "was not called before program exit, which can leak resources.\n") + message = classify(FLINT_NEEDS_FLASHINFER.replace(API_SERVER_TAIL, teardown + API_SERVER_TAIL), model="RecursiveSI/flint") + assert f"during startup: {FLINT_ATTN}. The model's code" in message + + bare = _traceback("vllm/models/foo/model.py", "AssertionError") + "Note: this kernel requires a warm cache\n" + assert classify(bare) is None + + def test_a_parenthesised_message_line_is_not_a_log_prefix(self): + exception = "RuntimeError: Foo MoE requires the TRTLLM backend\n(got TRITON) on this GPU" + lines = _traceback("vllm/models/foo/model.py", exception).splitlines() + output = "".join(_EC + line + "\n" for line in lines) + + assert "requires the TRTLLM backend (got TRITON) on this GPU" in classify(output) + + def test_vllms_nvlink_probe_record_is_not_a_host_fault(self): + nvlink = "".join( + "(EngineCore pid=1079) ERROR 10-21 20:16:30 [cuda.py:834] " + line + "\n" + for line in ["NVLink detection failed. This is normal if your machine has no NVLink equipped.", + "Traceback (most recent call last):", + ' File "/usr/local/lib/python3.12/dist-packages/pynvml.py", line 2380, in _nvmlCheckReturn', + " raise NVMLError(ret)", + "pynvml.NVMLError_NotSupported: Not Supported"]) + message = classify(nvlink + FLINT_NEEDS_FLASHINFER, model="RecursiveSI/flint") + + assert message and FLINT_ATTN in message + + def test_raw_output_with_vllm_030_short_prefix(self): + lines = _traceback("vllm/models/foo/model.py", "RuntimeError: FooMoE requires the CUTLASS backend").splitlines() + output = "".join(f"(APIServer pid=496) {line}\n" for line in lines) + + assert "RuntimeError: FooMoE requires the CUTLASS backend" in classify(output) + + @pytest.mark.parametrize( + "innermost,function,exception", + [ + # Where an error is raised says nothing about permanence: model code can be + # the innermost Python frame of a native failure during weight loading. + ("vllm/model_executor/models/llama.py", "load_weights", "RuntimeError: CUDA driver error: initialization error"), + ("vllm/model_executor/models/llama.py", "load_weights", + "RuntimeError: NVML_SUCCESS == r INTERNAL ASSERT FAILED at \"/pytorch/c10/cuda/CUDACachingAllocator.cpp\":1131"), + ("vllm/model_executor/models/llama.py", "load_weights", "RuntimeError: Failed to load weights: Connection reset by peer"), + ("vllm/model_executor/models/llama.py", "load_weights", + "RuntimeError: Download requires the shard, but the request timed out"), + ("vllm/models/flint/ops/moe.py", "forward", "RuntimeError: CUDA error: an illegal memory access was encountered"), + # No stated requirement: could be anything. + ("vllm/model_executor/models/foo.py", "__init__", "AssertionError"), + ("vllm/model_executor/models/foo.py", "forward", "ValueError: Error during index put operation"), + ("safetensors/torch.py", "load_file", "ValueError: truncated file"), + # Autograd misuse is a bug, not a configuration requirement. + ("vllm/model_executor/models/foo.py", "forward", + "RuntimeError: a leaf Variable that requires grad is being used in an in-place operation."), + # A stated requirement, but not raised by model code. + ("vllm/v1/engine/core.py", "__init__", "RuntimeError: this step requires a restart"), + ], + ) + def test_everything_else_still_restarts(self, innermost, function, exception): + assert classify(_traceback(innermost, exception, function)) is None + + def test_a_wrapped_cuda_cause_still_restarts(self): + # Synthetic wrapper text: vLLM's _merge_multimodal_embeddings re-raises a failed + # index_put as ValueError; "requires" is added so only the CUDA cause can veto it. + cause = _traceback("vllm/model_executor/models/utils.py", "RuntimeError: CUDA error: too many resources requested for launch") + wrapper = _traceback("vllm/model_executor/models/utils.py", "ValueError: Error during index put operation requires retry") + output = cause + "\nThe above exception was the direct cause of the following exception:\n\n" + wrapper + + assert classify(output) is None + + def test_a_cuda_error_on_a_continuation_line_still_restarts(self): + output = _traceback("vllm/models/foo/model.py", "RuntimeError: Foo requires a warmup pass\nCUDA error: unspecified launch failure") + + assert classify(output) is None + + def test_the_next_log_record_is_not_part_of_the_message(self): + # A bare model-code assertion, then an INFO record that happens to say "requires". + logged = "".join(_EC + line + "\n" for line in _traceback("vllm/models/foo/model.py", "AssertionError").splitlines()) + output = logged + "(EngineCore pid=1079) INFO 10-21 20:16:37 [deepep.py:88] DeepEP v2 requires NCCL >= 2.30.4\n" + + assert classify(output) is None + + def test_a_handled_warning_traceback_does_not_count(self): + warned = _traceback("vllm/models/foo/model.py", "RuntimeError: FooMoE requires the CUTLASS backend") + output = "".join(f"(EngineCore pid=1079) WARNING 10-21 20:16:36 [moe.py:40] {line}\n" for line in warned.splitlines()) + + assert classify(output) is None + + def test_an_engine_killed_by_a_signal_is_not_blamed_on_model_code(self): + output = FLINT_NEEDS_FLASHINFER.replace("Failed core proc(s): {}", "Failed core proc(s): {'EngineCore': -9}") + + assert classify(output) is None + + def test_a_later_unrelated_failure_is_what_ended_the_launch(self): + output = FLINT_NEEDS_FLASHINFER.replace( + API_SERVER_TAIL, + _traceback("safetensors/torch.py", "safetensors_rust.SafetensorError: Error while deserializing header: " + "MetadataIncompleteBuffer", "load_file") + API_SERVER_TAIL, + ) + + assert classify(output) is None + + @pytest.mark.parametrize("cause", ["ConnectionResetError: [Errno 104] Connection reset by peer", + "requests.exceptions.HTTPError: 503 Server Error: Service Unavailable"]) + def test_a_transport_fault_in_the_chain_still_restarts(self, cause): + output = (_traceback("huggingface_hub/file_download.py", cause, "http_get") + + "\nThe above exception was the direct cause of the following exception:\n\n" + + _traceback("vllm/models/foo/model.py", "ValueError: Foo vision requires preprocessor_config.json")) + + assert classify(output) is None + + def test_a_stale_model_frame_does_not_attach_to_a_later_error(self): + output = ( + _traceback("vllm/models/foo/model.py", "safetensors_rust.SafetensorError: Error while deserializing header") + + "RuntimeError: FooMoE requires the CUTLASS backend\n" + ) + + assert classify(output) is None + + def test_oom_raised_in_model_code_keeps_the_memory_advice(self): + output = _traceback( + "vllm/model_executor/models/llama.py", + "torch.OutOfMemoryError: CUDA out of memory. Tried to allocate 2.00 GiB.", + ) + + assert "ran out of GPU memory" in classify(output)