From 29e179f7879845f01c6813ad5dfbb19d08dc030e Mon Sep 17 00:00:00 2001 From: Ruben Fiszel Date: Wed, 5 Aug 2026 11:46:36 +0000 Subject: [PATCH] fix(debugger): report python debugger dependency install failures instead of timing out (#10531) * fix: report python debugger dependency install failures instead of timing out Co-Authored-By: Claude Opus 5 (1M context) * fix: surface swallowed installer errors and stream debugger prepare progress Co-Authored-By: Claude Opus 5 (1M context) * fix: reap the python debugger on a failed launch and bound prepare-deps Co-Authored-By: Claude Opus 5 (1M context) * fix: match uv failure output by stripping progress instead of matching errors Co-Authored-By: Claude Opus 5 (1M context) * fix: treat uv build, download and warning lines as install progress Co-Authored-By: Claude Opus 5 (1M context) --------- Co-authored-by: Claude Opus 5 (1M context) --- debugger/dap_debug_service.ts | 28 ++- debugger/dap_websocket_server.py | 178 ++++++++++++++++-- debugger/dap_websocket_server_bun.ts | 37 ++++ debugger/test_dap_server.py | 6 +- .../src/lib/components/debug/dapClient.ts | 20 +- 5 files changed, 249 insertions(+), 20 deletions(-) diff --git a/debugger/dap_debug_service.ts b/debugger/dap_debug_service.ts index 52490cdc9a..405cf15fde 100644 --- a/debugger/dap_debug_service.ts +++ b/debugger/dap_debug_service.ts @@ -528,6 +528,15 @@ abstract class BaseDebugSession { // Python Debug Session // ============================================================================ +const DEFAULT_DEBUGPY_TIMEOUT_MS = 10_000 + +// `launch` waits on dependency preparation in the Python server, which allows `windmill +// prepare-deps` up to 120s; anything shorter here reports a timeout while the install is +// still legitimately running. +const DEBUGPY_TIMEOUT_MS_BY_COMMAND: Record = { + launch: 180_000 +} + class PythonDebugSession extends BaseDebugSession { private debugpyWs: WebSocket | null = null private debugpySeq = 1 @@ -571,11 +580,13 @@ class PythonDebugSession extends BaseDebugSession { arguments: args } + const timeoutMs = DEBUGPY_TIMEOUT_MS_BY_COMMAND[command] ?? DEFAULT_DEBUGPY_TIMEOUT_MS + return new Promise((resolve, reject) => { const timeout = setTimeout(() => { this.pendingDebugpyRequests.delete(seq) - reject(new Error(`Debugpy command timeout: ${command}`)) - }, 10000) + reject(new Error(`Debugpy command timeout: ${command} (after ${timeoutMs}ms)`)) + }, timeoutMs) this.pendingDebugpyRequests.set(seq, { resolve: (value) => { @@ -918,6 +929,13 @@ class PythonDebugSession extends BaseDebugSession { this.debugpyWs.onclose = () => { logger.info('Debugpy WebSocket closed') this.debugpyWs = null + // A Python server that dies mid-request must fail it now; otherwise the caller + // waits out the command timeout, which for `launch` is minutes. + const aborted = Array.from(this.pendingDebugpyRequests.values()) + this.pendingDebugpyRequests.clear() + for (const pending of aborted) { + pending.reject(new Error('Debugpy connection closed')) + } } }) } @@ -1140,7 +1158,13 @@ sys.stdout.flush() }) } catch (error) { this.sendEvent('output', { category: 'stderr', output: `Failed to start Python: ${error}\n` }) + // Claim the terminated event before cleanup kills the process, otherwise the + // `exited` handler sends a second one whose empty body erases this error. + this.terminatedSent = true this.sendEvent('terminated', { error: String(error) }) + // A Python server that refused the launch stays in its connection loop, so + // nothing else ever reaps it, its websocket or the temp dir. + await this.cleanup() } } diff --git a/debugger/dap_websocket_server.py b/debugger/dap_websocket_server.py index 9407849695..7388c8e76e 100644 --- a/debugger/dap_websocket_server.py +++ b/debugger/dap_websocket_server.py @@ -277,6 +277,88 @@ class WindmillDebugger(bdb.Bdb): return {} +PREPARE_DEPS_TIMEOUT_SECONDS = 120 +PREPARE_DEPS_PROGRESS_INTERVAL_SECONDS = 5 + + +@dataclass +class PrepareResult: + """ + Outcome of dependency preparation. + + `error` holds anything worth telling the user, including a problem reported by an + otherwise successful preparation. Only `fatal` means the packages are known to be + missing: failing to reach the CLI at all says nothing about the script's imports and + must not block a session that would otherwise run. + """ + + venv_path: str | None = None + error: str | None = None + fatal: bool = False + + +def _prepare_error_detail(response: dict) -> str: + """ + Build the failure reason from a prepare-deps response. + + `stderr` carries the installer's own output and is only present on newer workers, so + fall back to `error` alone when it is missing. + """ + parts = [ + str(response[key]).strip() + for key in ("error", "stderr") + if response.get(key) and str(response[key]).strip() + ] + return "\n".join(parts) or "unknown error" + + +# Prefixes uv uses for routine resolve/install progress, which it writes to stderr on a +# perfectly successful run. `warning:` belongs here because uv's warnings are non-fatal by +# construction (the hardlink fallback fires whenever the cache and the venv are on +# different filesystems, which is the normal layout). The `+`/`-` forms are the +# per-package change list. +_INSTALLER_PROGRESS_PREFIXES = ( + "resolved ", + "prepared ", + "installed ", + "uninstalled ", + "downloading ", + "downloaded ", + "building ", + "built ", + "updated ", + "audited ", + "using ", + "creating ", + "warning:", + "+ ", + "- ", +) + + +def _installer_diagnostics(stderr: str) -> str: + """ + Strip an installer's routine progress from its stderr, keeping anything unexplained. + + uv renders failures several ways (`error:`, `× No solution found` with tree glyphs), so + matching failure shapes misses some of them. Matching progress instead errs toward a + spurious warning rather than toward the silence this exists to prevent. All of this + goes away once the response carries an explicit failure flag to key on. + """ + kept = [ + line + for line in stderr.splitlines() + if line.strip() and not line.strip().lower().startswith(_INSTALLER_PROGRESS_PREFIXES) + ] + return "\n".join(kept).strip() + + +def _first_line(detail: str, limit: int = 300) -> str: + """Condense a multi-line failure into the single line a DAP response message allows.""" + line = next((s.strip() for s in detail.splitlines() if s.strip()), detail.strip()) + return line[:limit] + + class DebugSession: """Manages a single debug session.""" @@ -305,10 +387,12 @@ class DebugSession: self.seq += 1 return seq - def prepare_dependencies(self, code: str) -> str | None: + def prepare_dependencies(self, code: str) -> PrepareResult: """ Prepare Python dependencies by calling the windmill CLI. - Returns the path to the venv's site-packages directory, or None if no dependencies needed. + + Blocks for as long as the install takes, so it must run off the event loop; use + `_prepare_dependencies_with_progress` instead of calling this directly. """ if self._prepared_venv_path: # The debug service installs dependencies itself so that the registry credentials @@ -318,7 +402,7 @@ class DebugSession: if not self.windmill_path: logger.info("No windmill binary path configured, skipping dependency preparation") - return None + return PrepareResult() logger.info(f"Preparing dependencies using {self.windmill_path}") @@ -335,7 +419,7 @@ class DebugSession: input=input_data, capture_output=True, text=True, - timeout=120, # 2 minute timeout for dependency installation + timeout=PREPARE_DEPS_TIMEOUT_SECONDS, ) elapsed = time.time() - start_time @@ -344,7 +428,11 @@ class DebugSession: if result.returncode != 0: logger.error(f"prepare-deps failed (stderr): {result.stderr}") logger.error(f"prepare-deps failed (stdout): {result.stdout}") - return None + detail = (result.stderr or "").strip() or (result.stdout or "").strip() + return PrepareResult( + error=detail or f"windmill prepare-deps exited with code {result.returncode}", + fatal=True, + ) # Log raw output for debugging logger.debug(f"prepare-deps stdout: {result.stdout[:500] if result.stdout else '(empty)'}") @@ -357,15 +445,18 @@ class DebugSession: json_start = output.find('{') if json_start == -1: logger.error(f"No JSON in prepare-deps output: {output}") - return None + return PrepareResult( + error=f"No JSON in prepare-deps output: {output[:500] or '(empty)'}" + ) json_str = output[json_start:] response = json.loads(json_str) logger.debug(f"prepare-deps response: {response}") if not response.get("success"): - logger.error(f"prepare-deps error: {response.get('error')}") - return None + detail = _prepare_error_detail(response) + logger.error(f"prepare-deps error: {detail}") + return PrepareResult(error=detail, fatal=True) venv_path = response.get("venv_path") cached = response.get("cached", False) @@ -378,18 +469,57 @@ class DebugSession: else: logger.info("No external dependencies detected in code") - return venv_path + # `uv pip install` failing for individual packages does not fail the whole + # response, so a "successful" preparation can still carry the reason an import + # is about to fail. + installer_error = _installer_diagnostics(str(response.get("stderr") or "")) + if installer_error: + logger.warning(f"prepare-deps reported an installer error: {installer_error}") + + return PrepareResult(venv_path=venv_path, error=installer_error or None) except subprocess.TimeoutExpired: - logger.error("prepare-deps timed out after 120s") - return None + message = f"prepare-deps timed out after {PREPARE_DEPS_TIMEOUT_SECONDS}s" + logger.error(message) + return PrepareResult(error=message, fatal=True) except json.JSONDecodeError as e: + raw = output[:500] if 'output' in dir() else '(not available)' logger.error(f"Failed to parse prepare-deps JSON output: {e}") - logger.error(f"Raw output was: {output[:500] if 'output' in dir() else '(not available)'}") - return None + logger.error(f"Raw output was: {raw}") + return PrepareResult(error=f"Failed to parse prepare-deps output: {e}\n{raw}") except Exception as e: logger.exception(f"Error preparing dependencies: {e}") - return None + return PrepareResult(error=f"Error preparing dependencies: {e}") + + async def _prepare_dependencies_with_progress(self, code: str) -> PrepareResult: + """ + Run dependency preparation on a worker thread, reporting progress while it runs. + + The install can take minutes on a cold cache; on the event loop it would stall + websocket keepalive until it returns and block the progress events below. + """ + await self.send_event( + "output", {"category": "stdout", "output": "Preparing dependencies...\n"} + ) + + task = asyncio.create_task(asyncio.to_thread(self.prepare_dependencies, code)) + waited = 0 + while True: + done, _ = await asyncio.wait( + {task}, timeout=PREPARE_DEPS_PROGRESS_INTERVAL_SECONDS + ) + if done: + break + waited += PREPARE_DEPS_PROGRESS_INTERVAL_SECONDS + await self.send_event( + "output", + { + "category": "stdout", + "output": f"Still preparing dependencies... ({waited}s)\n", + }, + ) + + return task.result() def _next_var_ref(self) -> int: ref = self._variables_ref_counter @@ -528,7 +658,25 @@ class DebugSession: # Prepare dependencies before modifying the code if code: - self._venv_path = self.prepare_dependencies(code) + prepared = await self._prepare_dependencies_with_progress(code) + if prepared.error: + prefix = ( + "Failed to prepare dependencies" + if prepared.fatal + else "Warning: dependency preparation reported a problem, running anyway" + ) + await self.send_event( + "output", + {"category": "stderr", "output": f"{prefix}:\n{prepared.error}\n"}, + ) + if prepared.fatal: + await self.send_response( + request, + success=False, + message=f"Failed to prepare dependencies: {_first_line(prepared.error)}", + ) + return + self._venv_path = prepared.venv_path # If callMain is True, append a call to main() with the provided args if self._call_main and code: diff --git a/debugger/dap_websocket_server_bun.ts b/debugger/dap_websocket_server_bun.ts index d6ed8967ad..ff060f3da6 100644 --- a/debugger/dap_websocket_server_bun.ts +++ b/debugger/dap_websocket_server_bun.ts @@ -222,6 +222,8 @@ function generateMainCallArgs(code: string, args: Record): stri const WINDMILL_BASE_URL = process.env.WINDMILL_BASE_URL || process.env.BASE_INTERNAL_URL // e.g., http://localhost:8000 const REQUIRE_SIGNED_REQUESTS = process.env.REQUIRE_SIGNED_DEBUG_REQUESTS !== 'false' +const PREPARE_DEPS_TIMEOUT_MS = 120_000 + // Opt-in cross-origin protection (CSWSH defense-in-depth); see // dap_debug_service.ts for the rationale. Only enforced for this file's // standalone Bun.serve entrypoint (the windmill-extra runtime imports the @@ -1579,6 +1581,20 @@ export class DebugSession { logger.info(`Preparing dependencies using ${this.windmillPath}`) + // The launch response is only sent once this returns, so without progress a cold + // cache looks like a frozen debugger for as long as the install takes. + this.sendEvent('output', { category: 'console', output: 'Preparing dependencies...\n' }) + let waited = 0 + const progress = setInterval(() => { + waited += 5 + this.sendEvent('output', { + category: 'console', + output: `Still preparing dependencies... (${waited}s)\n` + }) + }, 5000) + let killTimer: ReturnType | undefined + let timedOut = false + try { const input = JSON.stringify({ code, language }) + '\n' logger.info(`prepare-deps input length: ${input.length}`) @@ -1591,9 +1607,27 @@ export class DebugSession { stderr: 'pipe' }) + // Bound the wait: the only other ceiling is the DAP client's launch timeout, + // which is minutes, so a wedged installer would hang the session that long. + killTimer = setTimeout(() => { + timedOut = true + logger.error(`prepare-deps timed out after ${PREPARE_DEPS_TIMEOUT_MS}ms`) + proc.kill() + }, PREPARE_DEPS_TIMEOUT_MS) + // Wait for completion const output = await new Response(proc.stdout).text() const stderr = await new Response(proc.stderr).text() + + if (timedOut) { + const errorMsg = `prepare-deps timed out after ${PREPARE_DEPS_TIMEOUT_MS / 1000}s` + this.sendEvent('output', { + category: 'console', + output: `Warning: Failed to prepare dependencies: ${errorMsg}\n` + }) + return null + } + logger.info(`prepare-deps output: ${output.substring(0, 200)}`) logger.info(`prepare-deps stderr: ${stderr.substring(0, 200)}`) @@ -1648,6 +1682,9 @@ export class DebugSession { output: `Warning: Failed to prepare dependencies: ${error}\n` }) return null + } finally { + clearInterval(progress) + clearTimeout(killTimer) } } diff --git a/debugger/test_dap_server.py b/debugger/test_dap_server.py index 45e138f2a3..17430ea25f 100644 --- a/debugger/test_dap_server.py +++ b/debugger/test_dap_server.py @@ -45,6 +45,10 @@ def main(x: str, count: int = 1): # Breakpoints for the main() test: lines 3 and 4 (inside main function) MAIN_BREAKPOINT_LINES = [3, 4] +# `launch` waits on dependency installation, so the import test below needs far more than +# the default budget on a cold cache. +REQUEST_TIMEOUTS = {"launch": 180.0} + class DAPTestClient: def __init__(self, url: str = "ws://localhost:5679"): @@ -103,7 +107,7 @@ class DAPTestClient: # Wait for response with timeout try: - response = await asyncio.wait_for(future, timeout=10.0) + response = await asyncio.wait_for(future, timeout=REQUEST_TIMEOUTS.get(command, 10.0)) return response except asyncio.TimeoutError: print(f"Timeout waiting for response to {command}") diff --git a/frontend/src/lib/components/debug/dapClient.ts b/frontend/src/lib/components/debug/dapClient.ts index 71783b4ec0..d124637b9b 100644 --- a/frontend/src/lib/components/debug/dapClient.ts +++ b/frontend/src/lib/components/debug/dapClient.ts @@ -82,6 +82,14 @@ const initialState: DebugState = { export const debugState = writable({ ...initialState }) +const DEFAULT_REQUEST_TIMEOUT_MS = 10_000 + +// `launch` waits on dependency installation in the debug server, which can take minutes on a +// cold cache; anything shorter here reports a timeout while the install is still running. +const REQUEST_TIMEOUT_MS_BY_COMMAND: Record = { + launch: 180_000 +} + export class DAPClient { private ws: WebSocket | null = null private seq = 1 @@ -120,7 +128,13 @@ export class DAPClient { logs: s.logs, output: s.output })) + // Reject rather than drop: a dropped `launch` leaves its caller awaiting + // until the timeout below fires, which is minutes rather than seconds. + const aborted = Array.from(this.pendingRequests.values()) this.pendingRequests.clear() + for (const pending of aborted) { + pending.reject(new Error('DAP connection closed')) + } } this.ws.onerror = (error) => { @@ -164,11 +178,13 @@ export class DAPClient { arguments: args } + const timeoutMs = REQUEST_TIMEOUT_MS_BY_COMMAND[command] ?? DEFAULT_REQUEST_TIMEOUT_MS + return new Promise((resolve, reject) => { const timeout = setTimeout(() => { this.pendingRequests.delete(seq) - reject(new Error(`Request timeout: ${command}`)) - }, 10000) + reject(new Error(`Request timeout: ${command} (after ${timeoutMs}ms)`)) + }, timeoutMs) this.pendingRequests.set(seq, { resolve: (value) => {