diff --git a/start.sh b/start.sh index 62b62c7..049f6f7 100755 --- a/start.sh +++ b/start.sh @@ -276,8 +276,10 @@ else echo "Using existing ComfyUI installation" fi -# Warm up pip so ComfyUI-Manager's 5s timeout check doesn't fail on cold start -python -m pip --version > /dev/null 2>&1 +# Warm up pip so ComfyUI-Manager's 5s timeout check doesn't fail on cold start. +# Log wall time — Manager fails if `python -m pip --version` takes >5s. +echo "Warming up pip (Manager timeout is 5s)..." +time python -m pip --version # Start ComfyUI — keep container alive if it crashes so SSH/Jupyter remain accessible cd $COMFYUI_DIR @@ -292,11 +294,28 @@ fi echo "Starting ComfyUI with args: $FIXED_ARGS" python main.py $FIXED_ARGS & COMFY_PID=$! -trap "kill $COMFY_PID 2>/dev/null" SIGTERM SIGINT -wait $COMFY_PID || true + +# Distinguish a real ComfyUI crash from the pod being stopped/restarted/ +# terminated (RunPod sends SIGTERM to PID 1, which we forward to ComfyUI — +# without the flag the crash banner would print on every normal shutdown). +SHUTTING_DOWN=0 +trap 'SHUTTING_DOWN=1; kill $COMFY_PID 2>/dev/null' SIGTERM SIGINT + +COMFY_EXIT=0 +wait $COMFY_PID || COMFY_EXIT=$? + +if [ "$SHUTTING_DOWN" = "1" ]; then + echo "Pod is shutting down (stop/restart/terminate) — stopping ComfyUI, Jupyter and FileBrowser." + # Docker only signals PID 1; stop the nohup'd background services too so + # they exit cleanly instead of waiting for SIGKILL. + pkill -TERM -f "jupyter-lab" 2>/dev/null || true + pkill -TERM -x "filebrowser" 2>/dev/null || true + exit 0 +fi echo "=============================================" -echo " ComfyUI crashed — check the logs above." +echo " ComfyUI exited unexpectedly (exit code $COMFY_EXIT)." +echo " Check the logs above for the error/traceback." echo " SSH and JupyterLab are still available." echo " To restart after fixing:" echo " cd $COMFYUI_DIR && source .venv-cu128/bin/activate" diff --git a/tests/README.md b/tests/README.md index 58ca784..8339128 100644 --- a/tests/README.md +++ b/tests/README.md @@ -26,7 +26,7 @@ tests/ ├── runpodctl.py ← subprocess wrappers around the `runpodctl` binary ├── instances.py ← GPU catalog, budget resolution, exclude filter, CUDA detection ├── pod.py ← pod create/lifecycle/signals, registry auth - ├── checks.py ← SSH probe, CUDA functional check, Jupyter probes, log dumper + ├── checks.py ← SSH probe, CUDA / pip checks, Jupyter probes, log dumper └── runner.py ← test_pair / test_image (per-image orchestration) ``` @@ -113,16 +113,18 @@ runs this sequence and reports the outcome as soon as one step fails. | # | Step | Failure → | |---|------|---| | 1 | `runpodctl pod create` (with `--gpu-id`, `--container-disk-in-gb`, `--ports`, registry auth, optional `--min-cuda-version`). Transient `5xx` / `Something went wrong` errors are retried silently up to `CREATE_RETRIES` with linear backoff. | `UNAVAILABLE` (no capacity for this instance type — try next) / `CREATE_FAIL` (bad image tag, registry auth, malformed request — any non-capacity, non-transient orchestrator error after retries are exhausted) | -| 2 | Poll `runpodctl pod get` until `ssh.ip` / `ssh.port` are assigned and one-shot `ssh root@ip -p port 'echo ready'` succeeds (the real readiness signal — `desiredStatus` is always `RUNNING` after create) | `STUCK` if no SSH endpoint within `CREATE_TIMEOUT` (almost always a bad host in the scheduler pool — try another instance type) | +| 2 | Poll `runpodctl pod get` until `ssh.ip` / `ssh.port` are assigned and one-shot `ssh root@ip -p port 'echo ready'` succeeds (the real readiness signal — `desiredStatus` is always `RUNNING` after create). In parallel, poll the REST v2 status (`GET /v2/pods/{id}`) as a fail-fast signal: unlike `desiredStatus`, it distinguishes `STARTING`/`RUNNING` and surfaces `ERROR` when the container start is aborted (e.g. a host-side mount failure at `runc` init), so we bail immediately instead of sitting out `CREATE_TIMEOUT`. On `ERROR`/stall/timeout, the host-side system logs (`GET /v2/pods/{id}/logs?source=system`) are scanned for error markers (`SYS_LOG_ERROR_PATTERN`) — that's where image-pull and container-init failures are reported; container stdout stays empty when the container never starts. | `STUCK` if no SSH endpoint within `CREATE_TIMEOUT` (almost always a bad host in the scheduler pool — try another instance type); `FAIL` if the pod hits a terminal state (`ERROR`/`EXITED`/`TERMINATED`) | | 3 | **CUDA functional check** over SSH — see [Functional check](#functional-check). Image-driven: pytorch ref → `torch.cuda` + matmul; cuda/rocm ref → `nvidia-smi` + `nvcc`; neither → skip | `FAIL` (image is broken — stop iterating; another GPU won't help) | -| 4 | **JupyterLab in-pod check** (only when `test_jupyter: true`) — see [Jupyter check](#jupyter-check-opt-in). SSH in, wait for `:8888` to bind, `jupyter server list`, `curl /api/status` with token | `FAIL` (`start.sh` didn't bring up Jupyter — usually wrong python interpreter) | -| 5 | **JupyterLab public-proxy check** (only when `test_jupyter: true`) — `GET https://-8888.proxy.runpod.net/api/status` from the test machine | `FAIL` (port not exposed as `8888/http`, or proxy never registered) | -| 6 | **Per-port HTTP checks** (only when `test_ports: [...]`) — see [Per-port checks](#per-port-checks-opt-in). For every listed port: SSH in and `curl http://127.0.0.1:/`, then `GET https://-.proxy.runpod.net/` from the test machine. | `FAIL` (service didn't bind, returned `5xx`, or port wasn't exposed as `/http` so the proxy never registered it) | -| 7 | **ComfyUI reachability smoke** (when `test_comfyui: true`, also implied by `test_comfyui_functional`) — see [ComfyUI checks](#comfyui-checks-smoke--functional). Probe `:8188` in-pod (`curl 127.0.0.1:8188`) then via the public proxy. | `FAIL` (ComfyUI didn't bind, returned `5xx`, or `:8188` wasn't exposed as `8188/http`) | +| 4 | **Pip check** (always on — no manifest flag) — see [Pip check](#pip-check-always-on). Prefers ComfyUI venv if present, `python -m pip --version` + wall time. Fails if pip missing or >5s | `FAIL` (pip missing / too slow on this host's network volume) | +| 5 | **JupyterLab check** (only when `test_jupyter: true`) — see [Jupyter check](#jupyter-check-opt-in). Proxy-first: `GET https://-8888.proxy.runpod.net/api/status` from the test machine; on success the in-pod probe is skipped. On failure, SSH in and probe `127.0.0.1:8888` to diagnose. | `FAIL` (Jupyter not running, or up but port not exposed as `8888/http` — the in-pod diagnostic tells which) | +| 6 | **Per-port HTTP checks** (only when `test_ports: [...]`) — see [Per-port checks](#per-port-checks-opt-in). For every listed port, proxy-first: `GET https://-.proxy.runpod.net/`; in-pod `curl 127.0.0.1:` only as a diagnostic when the proxy fails. | `FAIL` (service didn't bind / returned `5xx`, or up but port not exposed as `/http`) | +| 7 | **ComfyUI reachability smoke** (when `test_comfyui: true`, also implied by `test_comfyui_functional`) — see [ComfyUI checks](#comfyui-checks-smoke--functional). Proxy-first probe of `:8188`, in-pod probe only on proxy failure. | `FAIL` (ComfyUI didn't bind, returned `5xx`, or `:8188` wasn't exposed as `8188/http`) | | 8 | **ComfyUI functional check** (only when `test_comfyui_functional: true`) — see [ComfyUI checks](#comfyui-checks-smoke--functional). Host-side against the public proxy URL (no SSH): provision the model(s) via ComfyUI-RunpodDirect's `/server_download/*` routes, POST the workflow to `/prompt`, poll `/history`, fetch the output via `/view` and validate it's a real PNG. Runs only after the reachability smoke (7) passes. | `FAIL` (couldn't provision the model, ComfyUI rejected the workflow, generation errored/timed out, or no valid PNG came out) | -| 9 | Sleep `DWELL_SEC`, re-probe SSH (catches "boots fine then crashes after 30s") | `FAIL` if SSH stops responding | -| 10 | `dump_pod_logs` — pull `uname`, `syslog`, `dmesg`, `/var/log/*.log`, `nvidia-smi` via SSH for the run log | _(diagnostic only)_ | -| 11 | `runpodctl pod delete` (always — even on Ctrl-C / exception via `atexit` + signal handlers) | _(diagnostic only)_ | +| 9 | **Container-log error scan** (always on, no SSH) — see [Log error scan](#log-error-scan-always-on). Pull container stdout via the REST log API (`GET /v2/pods/{id}/logs`) and grep for error/crash markers (case-insensitive, override with `LOG_ERROR_PATTERN`). Empty/failed fetches are retried (3×) and then FAIL as unverified. Skipped when no API key. Disable with `LOG_ERROR_SCAN=0`. | `FAIL` (error markers in container logs — e.g. ComfyUI-Manager's "Neither pip nor uv are available" — or the log API kept returning 0 lines) | +| 10 | Sleep `DWELL_SEC`, re-probe SSH (catches "boots fine then crashes after 30s") | `FAIL` if SSH stops responding | +| 11 | **Post-dwell re-verification** (skipped when `DWELL_SEC=0`). The SSH re-probe alone can't catch a late ComfyUI death — `start.sh` keeps the container alive via `sleep infinity` after a crash. So after the dwell: (a) if the group tests ComfyUI, re-probe `/system_stats` via the proxy (quick, 3 attempts); (b) re-run the container-log error scan to cover anything logged during the window. | `FAIL` (ComfyUI stopped answering during dwell, or new error markers / unverified scan) | +| 12 | `dump_pod_logs` — full container-log backfill (`LOG_API_TAIL` lines) via the REST log API, system-log error markers (`source=system`, filtered by `SYS_LOG_ERROR_PATTERN`), plus a `nvidia-smi` / `rocm-smi` snapshot via SSH | _(diagnostic only)_ | +| 13 | `runpodctl pod delete` (always — even on Ctrl-C / exception via `atexit` + signal handlers) | _(diagnostic only)_ | `test_image()` then iterates over the next instance candidate when the result was `UNAVAILABLE` or `STUCK`, and short-circuits on `PASS`, @@ -264,8 +266,8 @@ Field reference: | `exclude_instances` | fnmatch-style patterns (case-insensitive) subtracted from the candidate list AFTER `instances:`, budget, or `check_all_gpu` selection. Useful for blocking known-bad host pairings without rewriting the whole list — e.g. `"*Blackwell*"` skips every Blackwell GPU (sm\_100 / sm\_120 are not in the kernel set of PyTorch ≤ 2.6 wheels). | | `min_cuda_version` | `X.Y` string passed to `runpodctl pod create --min-cuda-version`. Only used as a **fallback** when the image tag itself doesn't encode a CUDA version (e.g. NGC `nvidia-pytorch:25.11`). Image tags like `cu1281` / `cuda1281` always win. | | `test_jupyter` | `true` / `false` — when true, the pod is created with `JUPYTER_PASSWORD=admin` in env and HTTP port 8888 exposed, then the script SSHes in and verifies JupyterLab is actually listening **with Jupyter-specific assertions** (`jupyter server list`, `/api/status` with token). Use for groups whose images use `container-template/start.sh` (`runpod/base`, `runpod/pytorch`, `runpod/autoresearch`, `rocm`). Skip for NGC `nvidia-pytorch` (different entrypoint). Default: `false`. | -| `test_ports` | List of TCP ports the image is expected to serve over HTTP. Each port is exposed as `/http` so Runpod's public proxy registers it, then the runner probes the port twice: (1) in-pod via SSH (`curl http://127.0.0.1:/`), (2) via the public proxy (`https://-.proxy.runpod.net/`). Generic counterpart to `test_jupyter` — no app-specific assertions, just "a server responds with HTTP `<500`". Use for ComfyUI (`8188`), FileBrowser (`8080`), or any app where you only need to verify "it's listening". Can coexist with `test_jupyter: true` (Jupyter on 8888 is still checked with the Jupyter-specific probes; any other port in `test_ports` gets the generic one). Default: empty. | -| `test_comfyui` | `true` / `false` — ComfyUI **reachability smoke**. A ComfyUI-branded alias for `test_ports: [8188]`: exposes `:8188` as `8188/http` and probes it twice — in-pod (`curl 127.0.0.1:8188`) and via the public Runpod proxy (`https://-8188.proxy.runpod.net/`). Accepts any HTTP `<500`. Answers **"is ComfyUI up and reachable from a browser?"** — not whether it can generate. Cheap (no download, no GPU work). Also enabled implicitly by `test_comfyui_functional`. Default: `false`. | +| `test_ports` | List of TCP ports the image is expected to serve over HTTP. Each port is exposed as `/http` so Runpod's public proxy registers it, then the runner probes the port twice: (1) in-pod via SSH (`curl http://127.0.0.1:/`), (2) via the public proxy (`https://-.proxy.runpod.net/`). Generic counterpart to `test_jupyter` — no app-specific assertions: the proxy probe requires HTTP 200 (anything else is retried until the deadline — the proxy itself 404s while the pod isn't routed yet), the in-pod probe accepts any HTTP `<500`. Use for ComfyUI (`8188`), FileBrowser (`8080`), or any app where you only need to verify "it's listening". Can coexist with `test_jupyter: true` (Jupyter on 8888 is still checked with the Jupyter-specific probes; any other port in `test_ports` gets the generic one). Default: empty. | +| `test_comfyui` | `true` / `false` — ComfyUI **reachability smoke**. A ComfyUI-branded alias for `test_ports: [8188]`: exposes `:8188` as `8188/http` and probes it twice — in-pod (`curl 127.0.0.1:8188`) and via the public Runpod proxy (`https://-8188.proxy.runpod.net/`). The proxy probe requires HTTP 200 (anything else is retried); the in-pod one accepts any HTTP `<500`. Answers **"is ComfyUI up and reachable from a browser?"** — not whether it can generate. Cheap (no download, no GPU work). Also enabled implicitly by `test_comfyui_functional`. Default: `false`. | | `test_comfyui_functional` | `true` / `false` — ComfyUI **end-to-end functional check**. Proves the image can actually **generate an image**, run **host-side against the public proxy URL** (`https://-8188.proxy.runpod.net`, no SSH): provisions the checkpoint(s) from [`tests/comfyui/models.json`](comfyui/models.json) via the baked-in [ComfyUI-RunpodDirect](https://github.com/MadiatorLabs/ComfyUI-RunpodDirect) node's `/server_download/*` routes, POSTs the workflow [`tests/comfyui/workflows/gsl_starter_1_1.api.json`](comfyui/workflows/gsl_starter_1_1.api.json) (the "1.1 Starter – Text to Image" template) to `/prompt`, polls `/history`, then fetches the result via `/view` and asserts it's a real, non-empty PNG. **Implies `test_comfyui`** — the reachability smoke runs first and the generation only runs if it passes (no point spending GPU time on an unreachable ComfyUI). Heavier: pulls a ~2 GB model + uses GPU time, so gate it behind an enabler. Default: `false`. | The `base_cpu` group is special: `runpodctl` 2.3.0 does not let us pick @@ -364,6 +366,10 @@ pytorch: | `REGISTRY_AUTH_ID` | _(empty)_ | Explicit Docker Hub registry auth id to pass as `--registry-auth-id`. Overrides auto-discovery. | | `REGISTRY_AUTH_NAME` | _(empty)_ | Display name to look up via `runpodctl registry list` when `REGISTRY_AUTH_ID` is not set. Falls back to the first entry. | | `DWELL_SEC` | `60` | Extra seconds to wait after SSH becomes reachable, then re-probe SSH to catch containers that boot, accept SSH, then crash. Set 0 to skip the re-probe. | +| `LOG_ERROR_SCAN` | `1` | Always-on container-log error scan via the REST log API (no SSH). Set `0` to disable. Auto-skipped when no API key is available. | +| `LOG_ERROR_PATTERN` | `\berr(or)?s?\b\|\bcrash(ed\|es\|ing)?\b` | Case-insensitive regex the container-log scan greps for. Matches `err`/`error`/`ERRORS`/`crashed` as words, not `stderr`. | +| `LOG_API_TAIL` | `1000` | How many historical container-log lines the REST log API backfills for the scan and the diagnostic dump. Max 5000. | +| `SYS_LOG_ERROR_PATTERN` | `\berr(or)?s?\b\|\bfail(ed\|ure)?\b\|\bcrash(ed\|es\|ing)?\b` | Case-insensitive regex greped against the HOST-side system-log stream (`source=system`) when a pod won't come up (terminal state, stall, timeout) and in the diagnostic dump. Broader than `LOG_ERROR_PATTERN` because host/runtime failures phrase themselves as `failed to …` or `container crashed` at least as often as `error …`. | | `CREATE_TIMEOUT` | `600` | Max seconds to wait for SSH to become reachable. Raise for ROCm workflows (`create-timeout: "1200"` on the action) — the official `rocm/pytorch:*` base images are 30-50GB and routinely take 8-15 minutes to pull. | | `POLL_INTERVAL` | `10` | Poll cadence for SSH probes. | | `MAX_PARALLEL` | `1` | How many images to smoke-test concurrently. Each worker holds at most one pod, so this caps simultaneous live pods. Keep modest to avoid Runpod rate limits and surprise bills. | @@ -380,6 +386,7 @@ pytorch: | `COMFYUI_WORKFLOW` | `tests/comfyui/workflows/gsl_starter_1_1.api.json` | Path to the ComfyUI **API-format** workflow POSTed to `/prompt`. Override to test a different template. | | `COMFYUI_MODELS_MANIFEST` | `tests/comfyui/models.json` | Path to the JSON list of models to provision before running (`filename`, `directory` = a ComfyUI `folder_paths` key, `url`, `sha256`). | | `COMFYUI_WAIT_TIMEOUT` | `600` | Seconds the `test_comfyui_functional` probe waits for `/system_stats` to answer **through the proxy** (cold ComfyUI cp -r + torch import + Manager fetch + eventually-consistent proxy). | +| `COMFYUI_ROUTES_TIMEOUT` | `60` | Seconds the RunpodDirect feature-detect (`GET /server_download/folder_paths`) keeps retrying before declaring the routes unavailable. Absorbs transient proxy 404/5xx from eventually-consistent proxy replicas. | | `COMFYUI_DOWNLOAD_TIMEOUT` | `900` | Seconds allowed for RunpodDirect to provision the model(s). DreamShaper 8 pruned is ~2.1 GB. | | `COMFYUI_GEN_TIMEOUT` | `300` | Seconds allowed for the generation itself (queue → PNG on disk), including the cold first checkpoint load into VRAM. | | `COMFYUI_SAVE_DIR` | _(empty)_ | Local directory to save the generated PNG into (a plain HTTP GET of `/view`, then written as `_.png`). Empty = validate from the `/view` response only, don't keep a copy (keeps CI stdout light). Set it to actually **see** the image — the pod is deleted right after the check. | @@ -409,48 +416,101 @@ groups don't silently skip the check: → no check. Pod must still boot and survive `DWELL_SEC`. +## Pip check + +No manifest flag — runs on every pod after the CUDA step whenever SSH +is available. Prefers the ComfyUI venv if present, else system +`python`. Runs `python -m pip --version`, logs `pip_wall_ms=…`. + +Wall time is measured in **milliseconds** (bash 5's `$EPOCHREALTIME`; +whole-second timestamps would record a 5.99s run as "5s" and let it +slip under the budget). Deliberately timed with shell built-ins, not a +python one-liner — invoking python for the clock would pre-warm the +interpreter from the network volume and bias the cold-start cost the +check exists to measure. + +**Fails when** pip is missing/broken, **or** wall time exceeds **5s** +(ComfyUI-Manager's hard `get_pip_cmd` timeout). Useful with +`check_all_gpu: true` to map which GPU hosts have slow network storage. + + +## Log error scan (always on) + +No manifest flag — runs **twice** on every pod (after the functional +checks and again after the dwell window, so a crash during dwell can't +slip past the scan), and needs **no SSH**: container stdout is pulled +host-side from the REST log API +(`GET https://api.runpod.io/v2/pods/{id}/logs`, SSE). This is +the one log source SSH can't reach — ComfyUI runs as PID 1 and its +stdout isn't readable from a separate SSH session. + +The backfill (`LOG_API_TAIL` lines, default 1000) is grepped with +`LOG_ERROR_PATTERN` (default `\berr(or)?s?\b|\bcrash(ed|es|ing)?\b`, +case-insensitive — matches `err` / `ERROR` / `errors` / `crashed` as +words but not `stderr`). Any match FAILs the pair and prints the +matched lines. + +An **empty fetch is never a pass**: every image logs on boot +(`start.sh` alone produces dozens of lines), so "scanned 0 log lines" +means the scan verified nothing. An empty or failed fetch is retried +(3 attempts, 10s apart) and then FAILs the pair as +`log scan unverified` instead of silently passing. + +Skipped (not failed) when no Runpod API key is available (same +discovery as the GPU catalog: `RUNPOD_API_KEY` env var or +`~/.runpod/config.toml`). Disable entirely with `LOG_ERROR_SCAN=0`. +The same API feed is also the primary source in every `dump_pod_logs` +diagnostic dump (full `LOG_API_TAIL` backfill); SSH is only used for a +GPU SMI snapshot (`nvidia-smi` / `rocm-smi`), which the log API can't +provide. + + ## Jupyter check (opt-in via manifest `test_jupyter: true`) -Two stages, both must pass: +Proxy-first, one probe in the happy path: -1. **In-pod.** SSH into the pod and `curl http://127.0.0.1:8888/api/status` - with our token. Catches silent `start.sh` failures (e.g. `python3 -m - jupyter` not finding the module on Ubuntu 22.04 — the kind of bug - that prints `Jupyter Lab started` in the container log while no - server is actually running). -2. **Public proxy.** From the test machine, `GET - https://-8888.proxy.runpod.net/api/status` with the token. - Catches port-type misconfigurations (`8888/tcp` instead of - `8888/http` — the proxy never wires up non-http ports) and DNS / - proxy registration issues that would prevent real users from - reaching Jupyter from the Runpod console. +1. **Public proxy.** From the test machine, `GET + https://-8888.proxy.runpod.net/api/status` with the token — + the end-user path. Passing proves BOTH that Jupyter is running and + that the port is exposed as `8888/http`, so the in-pod probe is + skipped. +2. **In-pod (diagnostic, only on proxy failure).** SSH into the pod and + `curl http://127.0.0.1:8888/api/status` with our token. Splits the + failure into two distinct reports: in-pod passes → Jupyter is up but + the port isn't exposed as `8888/http` (or proxy registration + failed); in-pod fails too → `start.sh` never brought Jupyter up + (e.g. `python3 -m jupyter` not finding the module). ## Per-port checks (opt-in via manifest `test_ports: [...]`) Generic counterpart to the Jupyter check — verifies that **some** HTTP -server binds each listed port and answers, both locally and through -Runpod's public proxy. No app-specific assertions, so it's the right -tool for ComfyUI (`8188`), FileBrowser (`8080`), Tensorboard, etc. - -For every port in the list, two probes run in sequence (both must pass): - -1. **In-pod.** SSH in and run a single unified retry loop for up to - `PORT_WAIT_TIMEOUT` seconds: at each iteration probe `/dev/tcp/127.0.0.1/` - for binding, and if the port is open also try `curl http://127.0.0.1:/`. - The probe **accepts any HTTP status `<500`** (200, 301, 401, 403 all - prove the server is alive — many apps return 401/403 on `/` without - auth and that's still a "the service is up" signal we want to see). - Output streams live to the host with a heartbeat every 30s so long - warm-up windows (ComfyUI cold start, etc.) don't look frozen. - Catches "service never started", "service died on first request", - and "service bound to a non-loopback interface". -2. **Public proxy.** From the test machine, `GET - https://-.proxy.runpod.net/`. Same `<500` acceptance - criterion. Catches the most common end-user-facing failure mode: - the port was declared `/tcp` (or not declared at all) so - Runpod's proxy never registered it — the in-pod probe would still - pass, but real users can't reach the service from a browser. +server binds each listed port and answers through Runpod's public +proxy. No app-specific assertions, so it's the right tool for ComfyUI +(`8188`), FileBrowser (`8080`), Tensorboard, etc. + +For every port in the list, proxy-first: + +1. **Public proxy.** From the test machine, `GET + https://-.proxy.runpod.net/`, retried for up to + `PORT_PROXY_TIMEOUT` seconds (must absorb the app's cold start plus + the proxy's ~10-30s registration lag). The probe requires a strict + **HTTP 200** — anything else is retried until the deadline and then + fails. Notably 404: the Runpod proxy answers 404 on its own while + the pod is missing from its routing table, so a 404 can't be told + apart from the app and must not pass the check. Every app we test + serves 200 on `/` (redirects are followed, so a healthy redirect + chain still ends in 200). Passing proves both "service up" and + "port exposed as `/http`", so the in-pod probe is skipped. +2. **In-pod (diagnostic, only on proxy failure).** SSH in and run a + retry loop for up to `PORT_WAIT_TIMEOUT` seconds: probe + `/dev/tcp/127.0.0.1/` for binding, then `curl + http://127.0.0.1:/`, accepting any HTTP `<500` (here there is + no proxy in the middle, so even a 404 genuinely comes from the app + and proves a server is listening), heartbeat every 30s. Splits the failure: in-pod passes → the port was declared + `/tcp` (or not at all) so the proxy never registered it; + in-pod fails too → the service never started / died / bound to the + wrong interface. Independent from `test_jupyter`. You can enable both — port 8888 will go through Jupyter-specific probes (server list + token), and any @@ -471,8 +531,9 @@ separate manifest fields, but the functional one implies the smoke one: **`test_comfyui` (reachability smoke).** A ComfyUI-branded alias for `test_ports: [8188]`: exposes `:8188` as `8188/http`, then probes it -in-pod (`curl 127.0.0.1:8188`) and through the public Runpod proxy, -accepting any HTTP `<500`. It only answers "is the server up and reachable +in-pod (`curl 127.0.0.1:8188`) and through the public Runpod proxy +(strict HTTP 200; anything else — including the 404 the proxy itself +emits until the pod is routed — is retried, then fails). It only answers "is the server up and reachable from a browser?". Use it on every ComfyUI image — it's cheap. (You don't also need `test_ports: [8188]`; this replaces it. Keep `test_ports` for *other* ports like `8080` FileBrowser.) @@ -518,9 +579,13 @@ failing reason surfaced): Otherwise `POST /server_download/start` (RunpodDirect writes into the right `folder_paths` dir with an 8-connection download and verifies size + sha256 server-side), then poll `GET /server_download/status/...` - until `completed`. Requires the RunpodDirect routes to exist — if - `GET /server_download/folder_paths` 404s (node missing from the image), - the check fails with a clear message rather than silently. + until `completed`. Requires the RunpodDirect routes to exist — the + feature-detect (`GET /server_download/folder_paths`) retries for up to + `COMFYUI_ROUTES_TIMEOUT` (default 60s) before failing, because the + Runpod proxy's replicas are eventually-consistent and a single-shot + probe used to misclassify a transient proxy 404/5xx as "node missing + from the image". The FAIL message includes the last HTTP code/error so + the two cases stay distinguishable. 3. **Confirm visibility.** Hit `/object_info/CheckpointLoaderSimple` and assert the freshly-downloaded checkpoint now shows up in the node's enum (retries briefly to absorb the rescan lag). diff --git a/tests/runpod_smoke/checks.py b/tests/runpod_smoke/checks.py index c936ec8..4c6af01 100644 --- a/tests/runpod_smoke/checks.py +++ b/tests/runpod_smoke/checks.py @@ -2,6 +2,8 @@ * ssh_probe — one-shot connection probe, used as the real readiness signal * cuda_check_command / run_cuda_check — torch.cuda or nvidia-smi assertion + * pip_check_command / run_pip_check — always-on `python -m pip --version` + with wall-clock timing (catches ComfyUI-Manager's 5s pip probe timeout) * jupyter_check_command / run_jupyter_check — in-pod Jupyter probe over SSH * run_jupyter_proxy_check — public proxy probe from the test machine * fetch_logs_via_ssh / dump_pod_logs — pull diagnostic info before terminating @@ -12,6 +14,7 @@ from __future__ import annotations +import json import os import re import subprocess @@ -246,6 +249,59 @@ def run_cuda_check(host: str, port: int, image: str) -> tuple[bool, str]: return (r.returncode == 0), combined +# --------------------------------------------------------------------------- +# Pip check (always on — no manifest enabler) +# --------------------------------------------------------------------------- + +# ComfyUI-Manager's get_pip_cmd() times out `python -m pip --version` at 5s. +_PIP_MANAGER_TIMEOUT_SEC = 5 + + +def pip_check_command() -> str: + """Prefer ComfyUI venv if present, else system python. Time pip --version. + + Timing is sub-second (bash 5's $EPOCHREALTIME, microsecond precision): + with whole-second timestamps a run of up to 5.99s could be recorded + as 5 and slip under ComfyUI-Manager's 5s budget. Falls back to whole + seconds via `date +%s` on shells without EPOCHREALTIME, so the check + degrades rather than erroring. Timestamps deliberately avoid invoking + python — a python-based clock would pre-warm the interpreter from the + network volume and bias the very cold-start cost we're measuring.""" + timeout_ms = _PIP_MANAGER_TIMEOUT_SEC * 1000 + return ( + "set -e; " + # ${EPOCHREALTIME//[.,]/} -> microseconds as an integer (the + # decimal separator is locale-dependent, hence [.,]). + "now_ms() { if [ -n \"$EPOCHREALTIME\" ]; " + "then t=${EPOCHREALTIME//[.,]/}; echo $((t / 1000)); " + "else echo $(( $(date +%s) * 1000 )); fi; }; " + "PY=/workspace/runpod-slim/ComfyUI/.venv-cu128/bin/python; " + "[ -x \"$PY\" ] || PY=/workspace/runpod-slim/ComfyUI/.venv/bin/python; " + "[ -x \"$PY\" ] || PY=python; " + "echo \"pip check interpreter: $PY\"; " + "START_MS=$(now_ms); " + "\"$PY\" -m pip --version; " + "ELAPSED_MS=$(($(now_ms)-START_MS)); " + "echo \"pip_wall_ms=$ELAPSED_MS\"; " + f"[ \"$ELAPSED_MS\" -le {timeout_ms} ] " + f" || {{ echo \"FAIL: pip took ${{ELAPSED_MS}}ms " + f"(>{_PIP_MANAGER_TIMEOUT_SEC}s ComfyUI-Manager timeout)\"; exit 1; }}; " + "echo 'pip check OK'" + ) + + +def run_pip_check(host: str, port: int) -> tuple[bool, str]: + """SSH into the pod and run the always-on pip probe.""" + ssh_cmd = [*_ssh_command_prefix(host, port), pip_check_command()] + try: + r = subprocess.run(ssh_cmd, capture_output=True, text=True, timeout=60) + except subprocess.TimeoutExpired: + return False, "pip check timed out after 60s" + except FileNotFoundError: + return False, _SSH_BINARY_NOT_FOUND + return (r.returncode == 0), (r.stdout + r.stderr).strip() + + # --------------------------------------------------------------------------- # Jupyter checks (opt-in) # --------------------------------------------------------------------------- @@ -485,6 +541,16 @@ def _kill_on_timeout() -> None: return (proc.returncode == 0), last_line +def _proxy_status_ok(code: int) -> bool: + """Only HTTP 200 counts as "service is healthy behind the proxy". + Everything else is retried until the deadline: the Runpod proxy + answers 404 on its own while the pod is missing from its routing + table (indistinguishable from the app here), and every app we test + (FileBrowser, ComfyUI, Tensorboard) serves 200 on / — redirects are + followed by urllib, so a healthy redirect chain still ends in 200.""" + return code == 200 + + def run_port_proxy_check( pod_id: str, test_port: int, ) -> tuple[bool, str]: @@ -493,10 +559,11 @@ def run_port_proxy_check( `/http` declarations get registered) AND the server actually answers end-to-end. - Like `port_check_command`, accepts 2xx-4xx as success — many apps - return 401/403 on / when no auth header is provided, which still - means "server is up and proxied". Only 5xx and transport errors - count as failure. + Success is strictly HTTP 200 (see _proxy_status_ok). Everything else + — notably 404, which the Runpod proxy itself returns while the pod + isn't registered in its routing table yet — is retried until the + deadline and then counts as failure, so a proxy-generated 404 can't + masquerade as a healthy service. """ url = f"https://{pod_id}-{test_port}.proxy.runpod.net/" deadline = time.monotonic() + config.PORT_PROXY_TIMEOUT @@ -518,14 +585,14 @@ def run_port_proxy_check( lines.append( f"attempt #{attempt}: HTTP {code} body={body[:160]!r}" ) - if code < 500: + if _proxy_status_ok(code): return True, "\n".join(lines) last_err = f"HTTP {code}" except urllib.error.HTTPError as e: - # 4xx is raised as HTTPError by urlopen; treat them as success - # (server responded, just unauthenticated/redirected). Only - # 5xx and the connection-level errors below count as failure. - if e.code < 500: + # 4xx/5xx are raised as HTTPError by urlopen — all retried + # (404 may come from the proxy itself while the pod isn't + # routed yet; anything else means the app isn't healthy yet). + if _proxy_status_ok(e.code): lines.append( f"attempt #{attempt}: HTTP {e.code} {e.reason} " "(server responding)" @@ -541,8 +608,9 @@ def run_port_proxy_check( time.sleep(5) lines.append( - f"FAIL: proxy unreachable after {config.PORT_PROXY_TIMEOUT}s " - f"({attempt} attempts), last error: {last_err}" + f"FAIL: no HTTP 200 via proxy after " + f"{config.PORT_PROXY_TIMEOUT}s ({attempt} attempts), " + f"last error: {last_err}" ) return False, "\n".join(lines) @@ -610,6 +678,183 @@ def run_jupyter_proxy_check(pod_id: str) -> tuple[bool, str]: return False, "\n".join(lines) +# --------------------------------------------------------------------------- +# Container logs via REST API (v2) + error scan +# --------------------------------------------------------------------------- + + +def fetch_pod_logs_api( + pod_id: str, + tail: int = 0, + source: str = "container", + deadline_sec: int = 15, +) -> Optional[list[str]]: + """Fetch pod logs from `GET /v2/pods/{id}/logs` (SSE stream). + + The endpoint backfills `tail` historical lines then keeps the stream + open for live lines — we only want the backfill, so we read until + `deadline_sec` or until the socket goes idle, then close. + + Returns log lines, or None when the API key is missing / the request + failed (caller falls back to SSH).""" + from .instances import _load_runpod_api_key + + api_key = _load_runpod_api_key() + if not api_key: + return None + + tail = tail or config.LOG_API_TAIL + url = ( + f"https://api.runpod.io/v2/pods/{pod_id}/logs" + f"?source={source}&tail={tail}" + ) + req = urllib.request.Request( + url, + headers={ + "Authorization": f"Bearer {api_key}", + "Accept": "text/event-stream", + "User-Agent": "test-images.py/1.0 (+runpod-smoketest)", + }, + ) + lines: list[str] = [] + deadline = time.monotonic() + deadline_sec + try: + # The 3s socket timeout doubles as the idle detector: once the + # backfill is drained the server goes quiet and readline() times + # out, which is our signal to stop. + with urllib.request.urlopen(req, timeout=3) as resp: + while time.monotonic() < deadline: + try: + raw = resp.readline() + except OSError: + break # idle — backfill drained + if not raw: + break # stream closed + text = raw.decode("utf-8", errors="replace").strip() + if not text.startswith("data:"): + continue + try: + payload = json.loads(text[len("data:"):].strip()) + except json.JSONDecodeError: + continue + line = payload.get("line") + if line is not None: + lines.append(line.rstrip()) + except (urllib.error.HTTPError, OSError) as exc: + log(f" (log API fetch failed: {exc})", indent=2) + return None + return lines + + +def pod_status_api(pod_id: str) -> Optional[str]: + """Fetch the pod lifecycle `status` from `GET /v2/pods/{id}` (REST v2). + + Returns one of PROVISIONING / STARTING / RUNNING / EXITED / ERROR / + TERMINATED, or None when the API key is missing or the request + failed — callers must treat None as "no signal" and fall back to + the CLI-derived state. + + Unlike the legacy `desiredStatus` (which reports RUNNING as soon as + the pod is scheduled, even when the container never starts), the v2 + `status` distinguishes STARTING from RUNNING and surfaces ERROR for + unrecoverable container-start failures — e.g. a host-side mount bug + that aborts `runc` at container init.""" + from .instances import _load_runpod_api_key + + api_key = _load_runpod_api_key() + if not api_key: + return None + req = urllib.request.Request( + f"https://api.runpod.io/v2/pods/{pod_id}", + headers={ + "Authorization": f"Bearer {api_key}", + "Accept": "application/json", + "User-Agent": "test-images.py/1.0 (+runpod-smoketest)", + }, + ) + try: + with urllib.request.urlopen(req, timeout=10) as resp: + payload = json.loads(resp.read()) + except (urllib.error.HTTPError, OSError, json.JSONDecodeError): + return None + status = payload.get("status") + return status if isinstance(status, str) else None + + +def system_log_errors(pod_id: str, max_lines: int = 20) -> Optional[list[str]]: + """Fetch host-side system logs (`GET /v2/pods/{id}/logs?source=system`) + and return the lines matching SYS_LOG_ERROR_PATTERN. + + System logs are where Runpod surfaces host/runtime failures that + never reach container stdout — image pull errors, and container-init + aborts like `error starting container: ... failed to fulfil mount + request`. Returns None when the log API is unavailable (no key / + request failed), [] when logs were fetched but nothing matched.""" + lines = fetch_pod_logs_api(pod_id, source="system") + if lines is None: + return None + pattern = re.compile(config.SYS_LOG_ERROR_PATTERN, re.IGNORECASE) + return [ln for ln in lines if pattern.search(ln)][:max_lines] + + +# Every image logs plenty on boot (start.sh alone), so an empty fetch +# means the log API glitched or the container never started — retry, +# and if it stays empty treat the scan as unverified (= FAIL), never +# as a silent pass. +_LOG_SCAN_ATTEMPTS = 3 +_LOG_SCAN_RETRY_SLEEP_SEC = 10 + + +def scan_pod_logs_for_errors(pod_id: str) -> tuple[bool, str]: + """Fetch container logs via the REST API and grep them for error + markers (config.LOG_ERROR_PATTERN, case-insensitive). + + Returns (ok, report). ok=True only when actual log lines were + fetched and none matched. An empty or failed fetch is retried up to + _LOG_SCAN_ATTEMPTS times and then reported as ok=False — our images + always produce startup logs, so "0 lines" means the scan verified + nothing. The scan is skipped (ok=True) only when no API key is + configured — retrying can't help there, and SSH-based diagnostics + still cover us.""" + from .instances import _load_runpod_api_key + + if not _load_runpod_api_key(): + return True, "(no API key — log scan skipped)" + + failures: list[str] = [] + for attempt in range(1, _LOG_SCAN_ATTEMPTS + 1): + lines = fetch_pod_logs_api(pod_id) + if lines: + break + failures.append( + f"attempt #{attempt}: " + + ("fetch failed" if lines is None else "0 log lines") + ) + if attempt < _LOG_SCAN_ATTEMPTS: + time.sleep(_LOG_SCAN_RETRY_SLEEP_SEC) + else: + return False, ( + "log scan UNVERIFIED — the log API returned no container " + f"logs after {_LOG_SCAN_ATTEMPTS} attempts " + f"({'; '.join(failures)}). start.sh always logs on boot, so " + "an empty result means the fetch is broken or the container " + "never started — not a clean pass." + ) + + pattern = re.compile(config.LOG_ERROR_PATTERN, re.IGNORECASE) + matches = [ln for ln in lines if pattern.search(ln)] + if not matches: + return True, f"scanned {len(lines)} log lines — no error markers" + report = [ + f"scanned {len(lines)} log lines — " + f"{len(matches)} matched /{config.LOG_ERROR_PATTERN}/i:" + ] + report.extend(f" {ln}" for ln in matches[:40]) + if len(matches) > 40: + report.append(f" ... (+{len(matches) - 40} more)") + return False, "\n".join(report) + + # --------------------------------------------------------------------------- # Diagnostic log fetch # --------------------------------------------------------------------------- @@ -647,77 +892,20 @@ def _gpu_smi_block(image: str) -> str: return "" -def _runtime_state_block(tail: int) -> str: - """Shell snippet that dumps in-container runtime state useful for - diagnosing port-check failures: - - * top processes (so we can see if main.py is still running, stuck in - cp -r, or already gone) - * listening TCP ports (so we can distinguish "ComfyUI never bound" from - "ComfyUI bound but firewalled/CORS-wedged"; ss prints the owning pid - so we link a port back to a process) - * size of /workspace/runpod-slim/ComfyUI (the first-boot cp -r of - ~8 GB is the biggest single warmup cost — knowing it's still growing - vs already done resolves "is it stuck or just slow" instantly) - * tails of side-server logs (start.sh redirects jupyter/filebrowser - stdout there; ComfyUI's own stdout goes to PID 1 stdout which we - can't read from another process, hence no comfy.log tail — see ps). - """ - return ( - "echo '=== ps (top 25 by RSS) ==='; " - "ps -eo pid,ppid,stat,rss,etime,cmd --sort=-rss --no-headers 2>/dev/null " - " | head -n 25 || ps aux 2>&1 | head -n 25; " - "echo '=== listening TCP ports ==='; " - "if command -v ss >/dev/null 2>&1; then " - " ss -tlnp 2>&1 | head -n 30; " - "elif command -v netstat >/dev/null 2>&1; then " - " netstat -tlnp 2>&1 | head -n 30; " - "else " - " echo '(neither ss nor netstat available)'; " - "fi; " - "echo '=== ComfyUI workspace state ==='; " - "if [ -d /workspace/runpod-slim/ComfyUI ]; then " - " du -sh /workspace/runpod-slim/ComfyUI 2>/dev/null " - " || echo '(du failed)'; " - " ls /workspace/runpod-slim/ComfyUI/.venv-cu128 >/dev/null 2>&1 " - " && echo 'venv: present' || echo 'venv: NOT yet created'; " - "else " - " echo '(workspace ComfyUI dir not yet populated -- still in cp -r?)'; " - "fi; " - f"echo '=== last {tail} lines of /jupyter.log ==='; " - f"tail -n {tail} /jupyter.log 2>/dev/null || echo '(no /jupyter.log)'; " - f"echo '=== last {tail} lines of /filebrowser.log ==='; " - f"tail -n {tail} /filebrowser.log 2>/dev/null || echo '(no /filebrowser.log)'; " - ) - - -def fetch_logs_via_ssh( - host: str, port: int, image: str, tail: int = 20, -) -> Optional[str]: - """SSH to the pod and grab the most useful diagnostic info from inside - the container. Returns stdout on success, None if SSH didn't work. +def fetch_logs_via_ssh(host: str, port: int, image: str) -> Optional[str]: + """SSH to the pod for the GPU SMI snapshot — the one diagnostic the + REST log API can't provide (container logs come from the API in + `dump_pod_logs`). Returns stdout on success, None if SSH didn't work. - `image` is used to pick the right vendor SMI (rocm-smi vs nvidia-smi) - — without it we'd dump both on every pod and one of them would always - spew 'command not found' into the log. + `image` picks the right vendor SMI (rocm-smi vs nvidia-smi) so we + don't spew 'command not found' on the other vendor's pods. """ if not config.SSH_LOG_FETCH: return None - remote_cmd = ( - "set +e; " - "echo '=== uname / hostname ==='; uname -a; hostname; " - f"echo '=== last {tail} /var/log/syslog lines ==='; " - f"tail -n {tail} /var/log/syslog 2>/dev/null || echo '(no /var/log/syslog)'; " - f"echo '=== last {tail} dmesg lines ==='; " - f"dmesg --no-pager 2>/dev/null | tail -n {tail} || echo '(dmesg unavailable)'; " - "echo '=== /var/log/*.log tails ==='; " - "for f in /var/log/*.log; do " - " [ -f \"$f\" ] || continue; " - " echo \"--- $f ---\"; tail -n 5 \"$f\" 2>/dev/null; " - "done; " - + _gpu_smi_block(image) - + _runtime_state_block(tail) - ) + smi_block = _gpu_smi_block(image) + if not smi_block: + return None # CPU image — nothing SSH-only left to collect + remote_cmd = "set +e; " + smi_block cmd = [*_ssh_command_prefix(host, port), remote_cmd] try: r = subprocess.run(cmd, capture_output=True, text=True, timeout=45) @@ -730,12 +918,10 @@ def fetch_logs_via_ssh( return f"__SSH_FAILED__\nreturncode={r.returncode}\nstderr: {r.stderr.strip()[:400]}" -def dump_pod_logs(pod_id: str, image: str, tail: int = 20) -> None: - """Print pod metadata + container logs (via direct SSH) before - terminating. `image` is forwarded to `fetch_logs_via_ssh` so the - diagnostic dump only runs the vendor SMI that actually exists on the - pod (no more 'rocm-smi: command not found' on NVIDIA hosts). - """ +def dump_pod_logs(pod_id: str, image: str) -> None: + """Print pod metadata + full container-log backfill via the REST log + API + a GPU SMI snapshot via SSH before terminating. `image` picks + the vendor SMI (rocm-smi vs nvidia-smi).""" data = runpodctl_json("pod", "get", pod_id, timeout=30) if not isinstance(data, dict): log("(could not fetch pod state)", indent=2) @@ -755,17 +941,37 @@ def dump_pod_logs(pod_id: str, image: str, tail: int = 20) -> None: ]: log(f" {key:20s} = {val!r}", indent=2) + # Container stdout via the REST log API — the one source SSH can't + # reach (PID-1 stdout). Full LOG_API_TAIL backfill (default 1000). + api_lines = fetch_pod_logs_api(pod_id) + if api_lines: + log(f"--- container logs via API ({len(api_lines)} lines) ---", indent=2) + for line in api_lines: + log(f" {line}", indent=2) + + # Host-side system logs: only the error-marker lines, since the full + # stream is mostly routine lifecycle noise. This is where container- + # init failures live — the container log stream is empty when the + # container never started at all. + sys_errors = system_log_errors(pod_id) + if sys_errors: + log( + f"--- system-log error markers via API ({len(sys_errors)}) ---", + indent=2, + ) + for line in sys_errors: + log(f" {line}", indent=2) + if not (host and port): - log(" (no SSH endpoint yet — skipping log fetch)", indent=2) + log(" (no SSH endpoint yet — skipping GPU SMI fetch)", indent=2) log(f" inspect via UI: https://www.runpod.io/console/pods/{pod_id}", indent=2) return - log(f"--- container/system logs via SSH (root@{host}:{port}) ---", indent=2) - logs = fetch_logs_via_ssh(host, int(port), image, tail=tail) + logs = fetch_logs_via_ssh(host, int(port), image) if logs is None: - log(" (SSH log fetch disabled or ssh binary not found)", indent=2) - log(f" inspect via UI: https://www.runpod.io/console/pods/{pod_id}", indent=2) + # SSH fetch disabled, ssh binary missing, or CPU image (no SMI). return + log(f"--- GPU SMI via SSH (root@{host}:{port}) ---", indent=2) if logs.startswith("__SSH_FAILED__"): log(" SSH could not reach the pod:", indent=2) for line in logs.splitlines()[1:]: diff --git a/tests/runpod_smoke/comfyui.py b/tests/runpod_smoke/comfyui.py index a466697..e6db4f1 100644 --- a/tests/runpod_smoke/comfyui.py +++ b/tests/runpod_smoke/comfyui.py @@ -80,6 +80,32 @@ def _load_json_file(path: str): # --------------------------------------------------------------------------- +def probe_comfyui_alive( + pod_id: str, retries: int = 3, retry_sleep: int = 5, +) -> tuple[bool, str]: + """Quick "is ComfyUI still answering?" probe: GET /system_stats via + the public proxy, a few retries to absorb transient proxy-replica + errors. Unlike `_wait_server` this is NOT a readiness wait — ComfyUI + already proved reachable earlier, so a short budget is enough. + + Used for the post-dwell re-check: ComfyUI can crash during the dwell + window while SSH stays up (start.sh keeps the container alive via + `sleep infinity` after a crash). Returns (ok, detail).""" + base = _base_url(pod_id) + last = "" + for attempt in range(1, retries + 1): + try: + code, _ = _get(base + "/system_stats", timeout=10) + if code == 200: + return True, f"HTTP 200 (attempt #{attempt})" + last = f"HTTP {code}" + except OSError as e: + last = f"{type(e).__name__}: {e}" + if attempt < retries: + time.sleep(retry_sleep) + return False, last + + def _wait_server(base: str, emit: Callable[[str], None]) -> bool: """Poll ``/system_stats`` through the proxy until it answers 200. The public proxy is eventually-consistent (a fresh pod takes ~10-30s to enter @@ -109,21 +135,50 @@ def _wait_server(base: str, emit: Callable[[str], None]) -> bool: def _runpoddirect_folder_paths( base: str, emit: Callable[[str], None], -) -> Optional[dict]: - """Return the RunpodDirect ``folder_paths`` map, or None if its routes - 404 (the node isn't installed in this image). Doubles as a feature-detect - for "can we download models over HTTP?".""" - try: - code, body = _get(base + "/server_download/folder_paths", timeout=20) - except OSError as e: - emit(f" warn: /server_download/folder_paths errored: {e}") - return None - if code != 200: - return None - try: - return json.loads(body) - except Exception: - return None +) -> tuple[Optional[dict], str]: + """Feature-detect ComfyUI-RunpodDirect: fetch its ``folder_paths`` map. + Returns ``(map | None, last_error)`` — None means the routes never + answered 200 within the retry window. + + Retries for up to COMFYUI_ROUTES_TIMEOUT rather than taking one shot: + the Runpod proxy is eventually-consistent and its replicas can disagree + — /system_stats may have answered through a replica that knows the pod + while the next request lands on one that 404s/5xxes. A single-shot + probe misclassified such transient proxy errors as "node not installed + in this image" (an intermittent CI FAIL on images where the node is + definitely baked in). A genuinely absent node costs one extra + COMFYUI_ROUTES_TIMEOUT of polling, which is acceptable for the + unambiguous verdict.""" + deadline = time.monotonic() + config.COMFYUI_ROUTES_TIMEOUT + attempt = 0 + last = "" + while True: + attempt += 1 + try: + code, body = _get(base + "/server_download/folder_paths", timeout=20) + if code == 200: + try: + return json.loads(body), "" + except Exception: + last = "HTTP 200 with non-JSON body" + else: + snippet = (body or b"")[:120].decode("utf-8", "replace") + last = f"HTTP {code}: {snippet}".strip() + except OSError as e: + last = f"{type(e).__name__}: {e}" + if time.monotonic() >= deadline: + emit( + f" /server_download/folder_paths never answered 200 in " + f"{config.COMFYUI_ROUTES_TIMEOUT}s ({attempt} attempts, " + f"last: {last})" + ) + return None, last + if attempt == 1: + emit( + f" /server_download/folder_paths not answering yet ({last}) " + f"— retrying for up to {config.COMFYUI_ROUTES_TIMEOUT}s" + ) + time.sleep(3) def _model_present( @@ -426,10 +481,13 @@ def emit(msg: str) -> None: return False, f"could not read ComfyUI test assets: {e}" if models: - if _runpoddirect_folder_paths(base, emit) is None: + folder_paths, routes_err = _runpoddirect_folder_paths(base, emit) + if folder_paths is None: return False, ( - "ComfyUI-RunpodDirect routes (/server_download/*) not available " - "on this image — cannot provision the model over HTTP" + "ComfyUI-RunpodDirect routes (/server_download/*) never " + f"answered within {config.COMFYUI_ROUTES_TIMEOUT}s " + f"(last: {routes_err}) — node missing from the image, or " + "the proxy kept failing; cannot provision the model over HTTP" ) for m in models: if not _ensure_model(base, m, emit): diff --git a/tests/runpod_smoke/config.py b/tests/runpod_smoke/config.py index c20c2ac..9dd7973 100644 --- a/tests/runpod_smoke/config.py +++ b/tests/runpod_smoke/config.py @@ -121,12 +121,11 @@ def auto_terminate_deadline() -> str: # SSH # --------------------------------------------------------------------------- -# Container logs aren't exposed via runpodctl 2.3.0's JSON, so we SSH -# directly to the pod's exposed port 22 (mapped to a random high port on -# a public IP by Runpod) to grab them. The endpoint is discovered from -# `pod get`'s ssh.ip / ssh.port fields once the pod is scheduled. +# SSH is used for the readiness probe, the in-pod functional checks, and +# a GPU SMI snapshot in the diagnostic dump. The endpoint is discovered +# from `pod get`'s ssh.ip / ssh.port fields once the pod is scheduled. # Override SSH_IDENTITY if your key lives in a non-standard location. -# Set SSH_LOG_FETCH=0 to skip SSH-based log fetching entirely. +# Set SSH_LOG_FETCH=0 to skip the SSH-based SMI snapshot entirely. SSH_IDENTITY = os.environ.get("RUNPOD_SSH_KEY", "") SSH_LOG_FETCH = os.environ.get("SSH_LOG_FETCH", "1") == "1" SSH_OPTS = [ @@ -143,6 +142,38 @@ def auto_terminate_deadline() -> str: "-o", "HostKeyAlgorithms=+ssh-rsa", ] +# --------------------------------------------------------------------------- +# Container logs via REST API (v2) +# --------------------------------------------------------------------------- + +# GET https://api.runpod.io/v2/pods/{id}/logs streams container stdout as +# SSE — the ONE thing SSH can't see (PID-1 stdout isn't readable from +# another process inside the pod). Primary source in dump_pod_logs and +# the feed for the always-on log error scan. +# LOG_ERROR_SCAN=0 disable the error-scan step entirely +# LOG_ERROR_PATTERN=... override the regex (case-insensitive) +# LOG_API_TAIL=N how many historical lines to backfill (max 5000) +LOG_ERROR_SCAN = os.environ.get("LOG_ERROR_SCAN", "1") == "1" +# \berr(or)?s?\b: matches 'err' / 'error' / 'ERRORS' as words, but NOT +# 'stderr' / 'error-free' substrings inside longer identifiers. +# crash(ed/es/ing) is included too: apps report post-boot failures as +# 'worker crashed' / 'process crashing' without any 'error' nearby. +LOG_ERROR_PATTERN = os.environ.get( + "LOG_ERROR_PATTERN", r"\berr(or)?s?\b|\bcrash(ed|es|ing)?\b" +) +LOG_API_TAIL = int(os.environ.get("LOG_API_TAIL", "1000")) + +# Error markers for the HOST-side system-log stream (`source=system`) — +# checked when a pod won't come up (stall hint, TIMEOUT, terminal state) +# and in the diagnostic dump. Broader than LOG_ERROR_PATTERN because +# host/runtime failures phrase themselves as 'failed to ...' at least as +# often as 'error ...' (e.g. `error starting container: ... failed to +# fulfil mount request`), and 'container crashed' appears with neither. +SYS_LOG_ERROR_PATTERN = os.environ.get( + "SYS_LOG_ERROR_PATTERN", + r"\berr(or)?s?\b|\bfail(ed|ure)?\b|\bcrash(ed|es|ing)?\b", +) + # --------------------------------------------------------------------------- # Jupyter @@ -187,8 +218,9 @@ def auto_terminate_deadline() -> str: # so the Jupyter-specific knob can stay tighter (Jupyter responds fast # once bound) without making us impatient with slower-to-boot apps. # Same override pattern as PORT_WAIT_TIMEOUT — bump together for slow -# apps (proxy probe runs AFTER in-pod probe confirms the server is up, -# but Runpod's proxy is eventually-consistent and can lag by ~10-30s). +# apps. The proxy probe now runs FIRST (end-user path), so this window +# must absorb the app's full cold start PLUS the proxy's own +# eventually-consistent registration lag (~10-30s). PORT_PROXY_TIMEOUT = int(os.environ.get("PORT_PROXY_TIMEOUT", "300")) @@ -230,6 +262,13 @@ def auto_terminate_deadline() -> str: # first successful HTTP response. COMFYUI_WAIT_TIMEOUT = int(os.environ.get("COMFYUI_WAIT_TIMEOUT", "600")) +# Seconds the RunpodDirect feature-detect (`/server_download/folder_paths`) +# keeps retrying before declaring the routes unavailable. Retrying matters: +# the Runpod proxy's replicas are eventually-consistent, and a single-shot +# probe used to misclassify a transient proxy 404/5xx as "node not +# installed in this image" — an intermittent CI FAIL. +COMFYUI_ROUTES_TIMEOUT = int(os.environ.get("COMFYUI_ROUTES_TIMEOUT", "60")) + # Seconds allowed for provisioning the model(s) via RunpodDirect. DreamShaper # 8 pruned is ~2.1 GB; over a fast datacenter link its 8-connection download # lands in ~1 min, but a cold HuggingFace cache / throttling can be slower. diff --git a/tests/runpod_smoke/log.py b/tests/runpod_smoke/log.py index 18d0491..3208059 100644 --- a/tests/runpod_smoke/log.py +++ b/tests/runpod_smoke/log.py @@ -3,13 +3,16 @@ `log()` is the single place where everything emits to stdout. A small lock prevents output from parallel workers being interleaved mid-line; each pool thread gets a stable `W` tag the first time it logs so the -output stays readable in MAX_PARALLEL > 1 runs. +output stays readable in MAX_PARALLEL > 1 runs. While a worker is testing +a specific GPU instance the tag is extended to `W-` (set via +`set_worker_context`) so interleaved lines are attributable to a GPU. """ from __future__ import annotations import threading from datetime import datetime +from typing import Optional _log_lock = threading.Lock() @@ -32,9 +35,21 @@ def ensure_worker_tag() -> None: _thread_local.tag = f"W{_next_worker_id}" +def set_worker_context(ctx: Optional[str]) -> None: + """Attach/clear a per-thread context (the GPU instance under test). + + While set, parallel-run lines are tagged `[W-]` instead of + `[W]`. No-op for the serial path (no worker tag there — the + sequential log is unambiguous already). Pass None to clear.""" + _thread_local.ctx = ctx + + def log(msg: str, indent: int = 0) -> None: ts = datetime.now().strftime("%H:%M:%S") tag = getattr(_thread_local, "tag", "") + ctx = getattr(_thread_local, "ctx", None) + if tag and ctx: + tag = f"{tag}-{ctx}" tag_part = f"[{tag}] " if tag else "" with _log_lock: print(f"[{ts}] {tag_part}{' ' * indent}{msg}", flush=True) diff --git a/tests/runpod_smoke/pod.py b/tests/runpod_smoke/pod.py index fbf989a..72268eb 100644 --- a/tests/runpod_smoke/pod.py +++ b/tests/runpod_smoke/pod.py @@ -18,7 +18,7 @@ from typing import Optional from . import config -from .checks import ssh_probe +from .checks import pod_status_api, ssh_probe, system_log_errors from .instances import detect_cuda_version from .log import log from .runpodctl import runpodctl, runpodctl_json @@ -62,18 +62,6 @@ re.IGNORECASE, ) -RUNTIME_ERROR_RE = re.compile( - r"toomanyrequests" - r"|rate\s+limit" - r"|failed\s+to\s+pull\s+image" - r"|error\s+creating\s+container" - r"|manifest\s+(?:unknown|not\s+found)" - r"|access\s+denied" - r"|no\s+such\s+image", - re.IGNORECASE, -) - - # --------------------------------------------------------------------------- # Active-pod tracking + signal-safe cleanup # --------------------------------------------------------------------------- @@ -331,78 +319,6 @@ def pod_state(pod_id: str) -> dict: } -def pod_status(pod_id: str) -> Optional[str]: - """Returns `desiredStatus` — note this is always RUNNING after creation - so it can ONLY be used to detect terminal states (EXITED/FAILED/DEAD).""" - return pod_state(pod_id).get("desired") - - -# Top-level fields on `pod get` that may carry a runtime error message -# directly. Checked verbatim with `isinstance(value, str)`. -_DIRECT_ERROR_FIELDS = ("lastError", "errorMessage", "statusMessage", - "lastStatusChange") - -# Same as above but expected on the nested `runtime` dict that Runpod -# returns alongside top-level fields. -_RUNTIME_ERROR_FIELDS = ("lastError", "errorMessage", "statusMessage") - -# Fields whose value is a list of event objects (or strings); each item's -# `message` is harvested. `events` is the standard one; the other two -# show up on older `pod get` responses. -_EVENT_LIST_FIELDS = ("events", "statusEvents", "containerEvents") - -# Fields whose value is a single block of log lines that may contain -# pull-time errors not surfaced anywhere else. -_LOG_BLOCK_FIELDS = ("containerLogs", "logs") - - -def _collect_string_field(target: list[str], src: dict, key: str) -> None: - val = src.get(key) - if isinstance(val, str) and val: - target.append(val) - - -def _collect_event_messages(target: list[str], events: object) -> None: - if not isinstance(events, list): - return - for ev in events: - msg = ev.get("message") if isinstance(ev, dict) else str(ev) - if isinstance(msg, str) and msg: - target.append(msg) - - -def _gather_runtime_error_candidates(data: dict) -> list[str]: - """Walk every plausible place Runpod stuffs a runtime/pull error, - return a flat list of candidate lines. Doesn't filter — that's - `pod_runtime_error`'s job.""" - runtime = data.get("runtime") or {} - candidates: list[str] = [] - for key in _DIRECT_ERROR_FIELDS: - _collect_string_field(candidates, data, key) - for key in _RUNTIME_ERROR_FIELDS: - _collect_string_field(candidates, runtime, key) - for key in _EVENT_LIST_FIELDS: - _collect_event_messages(candidates, data.get(key) or runtime.get(key)) - for key in _LOG_BLOCK_FIELDS: - val = data.get(key) or runtime.get(key) - if isinstance(val, str): - candidates.extend(val.splitlines()) - return candidates - - -def pod_runtime_error(pod_id: str) -> Optional[str]: - """Inspect pod-get response for container-runtime errors (pull failures, - bad images, etc.) that appear *before* the pod ever reaches RUNNING. - Returns a short error string or None.""" - data = runpodctl_json("pod", "get", pod_id, timeout=30) - if not isinstance(data, dict): - return None - for line in _gather_runtime_error_candidates(data): - if RUNTIME_ERROR_RE.search(line): - return line.strip()[:300] - return None - - # --------------------------------------------------------------------------- # Wait for the pod to become reachable # --------------------------------------------------------------------------- @@ -411,6 +327,31 @@ def pod_runtime_error(pod_id: str) -> Optional[str]: # Pod-lifecycle states that mean "we will never become RUNNING — stop polling". _TERMINAL_DESIRED = {"EXITED", "FAILED", "DEAD", "TERMINATED"} +# Terminal statuses of the REST v2 `GET /v2/pods/{id}` endpoint. ERROR is +# the valuable one: the legacy desiredStatus NEVER reports it (it shows +# RUNNING even when the container start is aborted by the runtime, e.g. +# a host-side mount failure at `runc` init), so without the v2 status we +# would sit out the full CREATE_TIMEOUT on a pod that can never boot. +_TERMINAL_API_STATUSES = {"EXITED", "ERROR", "TERMINATED"} + + +def _log_system_errors(pod_id: str, context: str) -> None: + """Fetch host-side system logs via the REST API and print the + error-marker lines. Used when a pod won't come up: the container log + stream is empty when the container never started, so system logs are + the only place failures like image-pull errors or container-init + aborts are visible.""" + errors = system_log_errors(pod_id) + if errors is None: + log("system logs unavailable (no API key / request failed)", indent=2) + return + if not errors: + log(f"system logs: no error markers ({context})", indent=2) + return + log(f"system-log error markers ({context}):", indent=2) + for line in errors: + log(f" {line}", indent=2) + def _print_stall_hint(pod_id: str, elapsed: int) -> None: """One-time hint for pods that sit with no SSH endpoint for too long. @@ -472,11 +413,13 @@ def wait_for_running(pod_id: str) -> tuple[str, str]: 'RUNNING' SSH probe to root@: succeeded — the container's sshd is up, which means the container has fully booted and we can trust it as healthy. - 'TERMINAL' desiredStatus flipped to EXITED/FAILED/DEAD/TERMINATED. + 'TERMINAL' desiredStatus flipped to EXITED/FAILED/DEAD/TERMINATED, + OR the REST v2 `status` reported ERROR/EXITED/TERMINATED + (ERROR = container start aborted, only v2 surfaces it). 'TIMEOUT' SSH never reachable within CREATE_TIMEOUT — pod stuck initializing (capacity issue or image broken). - SSH probing is the real health-check now. We poll `pod get` to discover + SSH probing is the real health-check. We poll `pod get` to discover ssh.ip / ssh.port (assigned by Runpod once a machine is allocated), then try `ssh root@ip -p port 'echo ready'` until it succeeds. This works because: @@ -486,10 +429,19 @@ def wait_for_running(pod_id: str) -> tuple[str, str]: * A successful SSH means the container booted + sshd started — the canonical signal of readiness, much stronger than `desiredStatus` (always RUNNING) or `uptimeSeconds` (stale in this CLI version). + + Alongside SSH we also poll the REST v2 pod status (`GET /v2/pods/{id}`) + as a FAIL-FAST signal, not as the readiness gate: v2 distinguishes + STARTING/RUNNING/ERROR where desiredStatus reports RUNNING for all + three. On ERROR (and on stall/timeout) the host-side system logs + (`source=system`) are scanned for error markers — that's where + image-pull and container-init failures are reported; container stdout + stays empty when the container never starts. """ start = time.time() deadline = start + config.CREATE_TIMEOUT last_summary: Optional[tuple] = None + last_api_status: Optional[str] = None ssh_attempts = 0 stall_hinted = False # one-time hint when pod has no ssh endpoint for a while @@ -504,8 +456,19 @@ def wait_for_running(pod_id: str) -> tuple[str, str]: port = st.get("ssh_port") or 0 elapsed = int(time.time() - start) - if desired in _TERMINAL_DESIRED: - return "TERMINAL", f"pod entered {desired} after {elapsed}s" + # REST v2 status — None when the API key is missing or the call + # failed; the loop degrades gracefully to CLI-state + SSH-only. + api_status = pod_status_api(pod_id) + if api_status and api_status != last_api_status: + log(f"t+{elapsed}s API status: {api_status}", indent=2) + last_api_status = api_status + + if desired in _TERMINAL_DESIRED or api_status in _TERMINAL_API_STATUSES: + terminal = ( + api_status if api_status in _TERMINAL_API_STATUSES else desired + ) + _log_system_errors(pod_id, f"pod entered {terminal}") + return "TERMINAL", f"pod entered {terminal} after {elapsed}s" if host and port: ssh_attempts += 1 @@ -515,10 +478,11 @@ def wait_for_running(pod_id: str) -> tuple[str, str]: if outcome is not None: return outcome else: - summary = (desired, host, port, False) + summary = (desired, api_status, host, port, False) if summary != last_summary: log( f"t+{elapsed}s desired={desired!r} " + f"api_status={api_status!r} " f"uptime={st.get('uptime') or 0}s " "ssh endpoint not assigned yet", indent=2, @@ -526,14 +490,17 @@ def wait_for_running(pod_id: str) -> tuple[str, str]: last_summary = summary if elapsed >= config.STALL_HINT_AFTER and not stall_hinted: _print_stall_hint(pod_id, elapsed) + _log_system_errors(pod_id, f"stalled {elapsed}s") stall_hinted = True time.sleep(config.POLL_INTERVAL) + _log_system_errors(pod_id, f"timeout after {config.CREATE_TIMEOUT}s") return "TIMEOUT", ( f"SSH endpoint never became reachable in {config.CREATE_TIMEOUT}s " f"({ssh_attempts} probes) — pod stuck initializing. Likely causes: " "(1) slow/throttled image pull (check UI for pull progress), " "(2) Docker Hub rate limit if many parallel pulls of the same image, " - "(3) host scheduling delay on a saturated DC" + "(3) host scheduling delay on a saturated DC — " + "see system-log error markers above (if any)" ) diff --git a/tests/runpod_smoke/runner.py b/tests/runpod_smoke/runner.py index cc50a7e..6423d30 100644 --- a/tests/runpod_smoke/runner.py +++ b/tests/runpod_smoke/runner.py @@ -24,13 +24,15 @@ run_cuda_check, run_jupyter_check, run_jupyter_proxy_check, + run_pip_check, run_port_check, run_port_proxy_check, + scan_pod_logs_for_errors, ssh_probe, ) -from .comfyui import run_comfyui_check +from .comfyui import probe_comfyui_alive, run_comfyui_check from .instances import detect_cuda_version, resolve_gpu_id -from .log import log +from .log import log, set_worker_context from .pod import ( TRANSIENT_RE, UNAVAILABLE_RE, @@ -200,121 +202,154 @@ def _run_cuda_step( return None +def _run_pip_step( + host: str, port: int, pod_id: str, image: str, +) -> Optional[_Outcome]: + """Always-on pip probe — no manifest enabler. + + Runs `python -m pip --version` (preferring the ComfyUI venv when + present) and records wall time. Fails if pip is missing or slower + than ComfyUI-Manager's 5s get_pip_cmd timeout — the intermittent + error seen on slow network volumes.""" + if not (host and port): + return None + log("running pip check (always on)...", indent=2) + ok, output = run_pip_check(host, port) + for line in (output or "").splitlines(): + log(f" {line}", indent=2) + if not ok: + log( + "pip check FAILED -- python -m pip missing or slower than " + "ComfyUI-Manager's 5s timeout", + indent=2, + ) + dump_pod_logs(pod_id, image) + return "FAIL", "pip check failed" + log("pip check passed", indent=2) + return None + + def _run_jupyter_steps( host: str, port: int, pod_id: str, group: str, image: str, ) -> Optional[_Outcome]: """Jupyter checks: only when the group opted in via `test_jupyter`. - Two stages, both must pass: - 1. IN-POD: SSH into the pod and probe 127.0.0.1:8888. Catches - start.sh regressions (e.g. wrong python interpreter for - `-m jupyter`) that don't surface in container stdout. - 2. PROXY: from the test machine, hit - https://-8888.proxy.runpod.net/. Catches port-type - mistakes (`8888/tcp` instead of `8888/http`) — proxy never - registers a non-http port, so end users can't reach Jupyter - even though the in-pod check would happily pass.""" + PROXY-FIRST: the public-proxy probe + (https://-8888.proxy.runpod.net/api/status) is the end-user + path and subsumes the in-pod check — if it answers, Jupyter is up + AND the port is exposed as 8888/http, so the in-pod probe is + skipped. Only when the proxy fails do we SSH in and probe + 127.0.0.1:8888 to tell apart "Jupyter never started" (start.sh + regression) from "Jupyter is up but the port isn't 8888/http".""" if not (host and port and config.GROUP_TEST_JUPYTER.get(group, False)): return None log( - f"running Jupyter Lab check (in-pod) for group '{group}'...", + f"running Jupyter Lab check (public proxy) for pod {pod_id}...", + indent=2, + ) + ok, output = run_jupyter_proxy_check(pod_id) + for line in (output or "").splitlines(): + log(f" {line}", indent=2) + if ok: + log("jupyter check (public proxy) passed — in-pod check skipped", indent=2) + return None + + # Proxy failed — SSH in to pinpoint which side is broken. + log( + "jupyter check (public proxy) FAILED — running in-pod check " + "to diagnose...", indent=2, ) ok, output = run_jupyter_check(host, port) for line in (output or "").splitlines(): log(f" {line}", indent=2) - if not ok: + if ok: log( - "jupyter check (in-pod) FAILED -- start.sh did not " - "bring up JupyterLab", + "in-pod check passed -> Jupyter is up but unreachable via " + "proxy — port likely not exposed as 8888/http", indent=2, ) dump_pod_logs(pod_id, image) - return "FAIL", "Jupyter Lab check failed (in-pod)" - log("jupyter check (in-pod) passed", indent=2) + return "FAIL", "Jupyter reachable in-pod but not via proxy (port type?)" + log( + "in-pod check FAILED too -> start.sh did not bring up JupyterLab", + indent=2, + ) + dump_pod_logs(pod_id, image) + return "FAIL", "Jupyter Lab not running (proxy + in-pod both failed)" + +def _check_port_proxy_first( + host: str, port: int, pod_id: str, tp: int, label: str, +) -> Optional[tuple[str, str]]: + """Shared proxy-first reachability check for one HTTP port. + + 1. PROXY: `https://-.proxy.runpod.net/` — the end-user + path. Passing proves both "service is up" and "port exposed as + /http", so the in-pod probe is skipped. + 2. IN-POD (diagnostic, only on proxy failure): SSH in and curl + 127.0.0.1: to tell apart "service never started" from + "service up but port not exposed as /http". + + Returns None on pass, or ("FAIL", detail). `label` prefixes log + lines (e.g. 'port 8080' / 'ComfyUI reachability').""" log( - f"running Jupyter Lab check (public proxy) for pod {pod_id}...", + f"running {label} check (public proxy) on :{tp} for pod {pod_id}...", indent=2, ) - ok, output = run_jupyter_proxy_check(pod_id) + ok, output = run_port_proxy_check(pod_id, tp) for line in (output or "").splitlines(): log(f" {line}", indent=2) - if not ok: + if ok: + log(f"{label} check (public proxy) passed — in-pod check skipped", indent=2) + return None + + log( + f"{label} check (public proxy) FAILED — running in-pod check " + "to diagnose...", + indent=2, + ) + ok, last_line = run_port_check( + host, port, tp, + on_line=lambda line: log(f" {line}", indent=2), + ) + if ok: log( - "jupyter check (public proxy) FAILED -- port likely " - "not exposed as 8888/http", + f"in-pod check passed -> service on :{tp} is up but " + f"unreachable via proxy — port likely not exposed as {tp}/http", indent=2, ) - dump_pod_logs(pod_id, image) - return "FAIL", "Jupyter Lab check failed (public proxy)" - log("jupyter check (public proxy) passed", indent=2) - return None + return "FAIL", f"{label}: reachable in-pod but not via proxy on :{tp}" + log( + f"in-pod check FAILED too -- " + f"{last_line or 'service did not bind / returned HTTP 5xx'}", + indent=2, + ) + return "FAIL", f"{label}: service not responding on :{tp} (proxy + in-pod)" def _run_port_steps( host: str, port: int, pod_id: str, group: str, image: str, ) -> Optional[_Outcome]: """Generic per-port HTTP checks driven by the `test_ports:` manifest - field. For each port we run two probes in sequence: - 1. IN-POD: SSH in and `curl http://127.0.0.1:/`. Catches the - "service didn't start at all" / "bound to wrong interface" / - "exited immediately" class of bugs that don't surface in - `desiredStatus`. - 2. PROXY: from the test machine, hit - `https://-.proxy.runpod.net/`. Catches port-type - mistakes (`/tcp` instead of `/http`) — the proxy - only registers `/http` ports, so end users can't reach the - service from a browser even if the in-pod check passed. - - Any failure is a FAIL on the whole pair — pinpoints which port and - which probe broke. Each port is tested independently, but we abort - on the first failure (a broken pod isn't going to recover for the - next port and we already have the diagnostic info we need). - """ + field — proxy-first via `_check_port_proxy_first` (in-pod probe only + runs as a diagnostic when the proxy fails). + + Each port is tested independently, but we abort on the first failure + (a broken pod isn't going to recover for the next port and we + already have the diagnostic info we need).""" test_ports = config.GROUP_TEST_PORTS.get(group) or [] if not (host and port and test_ports): return None for tp in test_ports: - log( - f"running port check (in-pod) for {tp} in group '{group}'...", - indent=2, + outcome = _check_port_proxy_first( + host, port, pod_id, tp, f"port {tp}", ) - # Stream bash output live (heartbeat every 30s) so the operator - # sees the probe is alive during the long warm-up window. Without - # this the run looks frozen for up to PORT_WAIT_TIMEOUT seconds. - ok, last_line = run_port_check( - host, port, tp, - on_line=lambda line: log(f" {line}", indent=2), - ) - if not ok: - log( - f"port {tp} check (in-pod) FAILED -- " - f"{last_line or 'service did not bind / returned HTTP 5xx'}", - indent=2, - ) - dump_pod_logs(pod_id, image) - return "FAIL", f"port {tp} check failed (in-pod)" - log(f"port {tp} check (in-pod) passed", indent=2) - - log( - f"running port check (public proxy) for {tp} on pod {pod_id}...", - indent=2, - ) - ok, output = run_port_proxy_check(pod_id, tp) - for line in (output or "").splitlines(): - log(f" {line}", indent=2) - if not ok: - log( - f"port {tp} check (public proxy) FAILED -- " - f"likely not exposed as {tp}/http", - indent=2, - ) + if outcome is not None: dump_pod_logs(pod_id, image) - return "FAIL", f"port {tp} check failed (public proxy)" - log(f"port {tp} check (public proxy) passed", indent=2) + return outcome return None @@ -325,9 +360,10 @@ def _run_comfyui_steps( """ComfyUI checks, two tiers driven by two manifest flags: 1. SMOKE (`test_comfyui: true`, also implied by the functional flag) - — reachability of ComfyUI on :8188, probed twice: in-pod over SSH - (`curl 127.0.0.1:8188`) and via the public Runpod proxy. Answers - "is ComfyUI up and reachable from a browser?". + — reachability of ComfyUI on :8188, proxy-first: the public + Runpod proxy is probed first (the end-user path); the in-pod + probe over SSH only runs as a diagnostic when the proxy fails. + Answers "is ComfyUI up and reachable from a browser?". 2. FUNCTIONAL (`test_comfyui_functional: true`) — the end-to-end "can it actually generate an image" gate. Runs entirely HOST-SIDE @@ -348,43 +384,13 @@ def _run_comfyui_steps( cp = config.COMFYUI_PORT - # --- Tier 1: reachability smoke (in-pod + public proxy) --------------- - log( - f"running ComfyUI reachability check (in-pod) on :{cp} " - f"for group '{group}'...", - indent=2, - ) - ok, last_line = run_port_check( - host, port, cp, - on_line=lambda line: log(f" {line}", indent=2), + # --- Tier 1: reachability smoke (proxy-first) ------------------------- + outcome = _check_port_proxy_first( + host, port, pod_id, cp, "ComfyUI reachability", ) - if not ok: - log( - f"ComfyUI reachability (in-pod) FAILED -- " - f"{last_line or 'ComfyUI did not bind / returned HTTP 5xx'}", - indent=2, - ) + if outcome is not None: dump_pod_logs(pod_id, image) - return "FAIL", f"ComfyUI reachability check failed (in-pod) on :{cp}" - log("ComfyUI reachability (in-pod) passed", indent=2) - - log( - f"running ComfyUI reachability check (public proxy) on :{cp} " - f"for pod {pod_id}...", - indent=2, - ) - ok, output = run_port_proxy_check(pod_id, cp) - for line in (output or "").splitlines(): - log(f" {line}", indent=2) - if not ok: - log( - f"ComfyUI reachability (public proxy) FAILED -- " - f"likely not exposed as {cp}/http", - indent=2, - ) - dump_pod_logs(pod_id, image) - return "FAIL", f"ComfyUI reachability check failed (public proxy) on :{cp}" - log("ComfyUI reachability (public proxy) passed", indent=2) + return outcome # --- Tier 2: end-to-end functional generation ------------------------ if not func: @@ -412,6 +418,36 @@ def _run_comfyui_steps( return None +def _run_log_scan_step(pod_id: str, image: str) -> Optional[_Outcome]: + """Always-on container-log error scan via the REST log API (no SSH). + + Greps the container stdout backfill for error markers + (LOG_ERROR_PATTERN, default \\berr(or)?s?\\b case-insensitive) — + catches failures that never surface as a dead port or crashed pod, + e.g. ComfyUI-Manager's 'Neither pip nor uv are available'. Skipped + (not failed) when the API key is missing. Disable with + LOG_ERROR_SCAN=0.""" + if not config.LOG_ERROR_SCAN: + return None + log("scanning container logs for error markers (via API)...", indent=2) + ok, report = scan_pod_logs_for_errors(pod_id) + for line in report.splitlines(): + log(f" {line}", indent=2) + if not ok: + # Two failure modes: error markers matched, or the fetch stayed + # empty and the scan verified nothing (see scan_pod_logs_for_errors). + detail = ( + "log scan unverified — log API returned no container logs" + if report.startswith("log scan UNVERIFIED") + else "error markers found in container logs" + ) + log(f"log scan FAILED -- {detail}", indent=2) + dump_pod_logs(pod_id, image) + return "FAIL", detail + log("log scan passed", indent=2) + return None + + def _run_dwell_step(pod_id: str, image: str) -> Optional[_Outcome]: """Brief dwell to catch containers that boot, accept SSH, then crash. Most real images hit this in the first ~30s if they're going to crash. @@ -439,6 +475,43 @@ def _run_dwell_step(pod_id: str, image: str) -> Optional[_Outcome]: ) +def _run_post_dwell_steps( + pod_id: str, image: str, group: str, +) -> Optional[_Outcome]: + """Re-verify the pod AFTER the dwell window. + + The dwell SSH re-probe alone can't catch a late ComfyUI death: + start.sh keeps the container (and SSH) alive via `sleep infinity` + after a crash, and the pre-dwell log scan ran before the crash + happened. So, when dwell actually waited, we (1) re-probe ComfyUI + through the proxy if this group tests it, and (2) re-scan the + container logs for error markers picked up during the window.""" + if config.DWELL_SEC <= 0: + return None + + # (1) ComfyUI must still answer — quick probe, not a readiness wait. + if config.GROUP_TEST_COMFYUI.get(group, False) or \ + config.GROUP_TEST_COMFYUI_FUNCTIONAL.get(group, False): + log("re-probing ComfyUI after dwell...", indent=2) + ok, detail = probe_comfyui_alive(pod_id) + if not ok: + log( + f"ComfyUI re-probe FAILED after dwell ({detail}) — " + "it died during the dwell window", + indent=2, + ) + dump_pod_logs(pod_id, image) + return "FAIL", ( + f"ComfyUI stopped answering during the {config.DWELL_SEC}s " + f"dwell (post-dwell probe: {detail})" + ) + log(f"ComfyUI re-probe passed ({detail})", indent=2) + + # (2) Final log scan — covers anything logged during the window. + log("re-scanning container logs after dwell...", indent=2) + return _run_log_scan_step(pod_id, image) + + def test_pair(image: str, instance: str, group: str) -> _Outcome: """Returns (status, detail). Statuses: 'PASS' — image booted, CUDA check OK, survived dwell @@ -493,6 +566,9 @@ def test_pair(image: str, instance: str, group: str) -> _Outcome: # (no fancy abstraction) so the failure points stay easy to read # in stack traces / logs. outcome = _run_cuda_step(host, port, image, group, pod_id) + if outcome is not None: + return outcome + outcome = _run_pip_step(host, port, pod_id, image) if outcome is not None: return outcome outcome = _run_jupyter_steps(host, port, pod_id, group, image) @@ -502,9 +578,15 @@ def test_pair(image: str, instance: str, group: str) -> _Outcome: if outcome is not None: return outcome outcome = _run_comfyui_steps(host, port, pod_id, group, image) + if outcome is not None: + return outcome + outcome = _run_log_scan_step(pod_id, image) if outcome is not None: return outcome outcome = _run_dwell_step(pod_id, image) + if outcome is not None: + return outcome + outcome = _run_post_dwell_steps(pod_id, image, group) if outcome is not None: return outcome @@ -537,7 +619,13 @@ def test_image( last_create_error = "" last_create_inst = "" for inst in instances: - result, detail = test_pair(image, inst, group) + # Tag every line from this attempt with the instance name + # ([W1-A40]) so interleaved parallel logs stay attributable. + set_worker_context(inst) + try: + result, detail = test_pair(image, inst, group) + finally: + set_worker_context(None) if result == "PASS": return "PASS", "", inst if result == "FAIL":