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) <noreply@anthropic.com> * fix: surface swallowed installer errors and stream debugger prepare progress Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> * fix: reap the python debugger on a failed launch and bound prepare-deps Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> * fix: match uv failure output by stripping progress instead of matching errors Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> * fix: treat uv build, download and warning lines as install progress Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> --------- Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-09-08 08:04:25 +00:00 · 2026-08-05 13:46:36 +02:00
parent 7d153d5750
commit 29e179f787
5 changed files with 249 additions and 20 deletions
@@ -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<string, number> = {
+	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()
 		}
 	}

@@ -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:
@@ -222,6 +222,8 @@ function generateMainCallArgs(code: string, args: Record<string, unknown>): 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<typeof setTimeout> | 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)
 		}
 	}

@@ -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}")
@@ -82,6 +82,14 @@ const initialState: DebugState = {

 export const debugState = writable<DebugState>({ ...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<string, number> = {
+	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) => {