diff --git a/addons/godot_ai/client_configurator.gd b/addons/godot_ai/client_configurator.gd index 0f539ff..ccfb3b2 100644 --- a/addons/godot_ai/client_configurator.gd +++ b/addons/godot_ai/client_configurator.gd @@ -1676,7 +1676,7 @@ static func _is_symlink(path: String) -> bool: return dir.is_link(path) -static func get_server_command() -> Array[String]: +static func get_server_command(trace: Callable = Callable()) -> Array[String]: ## `mode_override() == "user"` skips the dev_venv tier even when a nearby ## .venv exists — the override then becomes an actual workaround for ## the "user venv misidentified as dev checkout" bug, not just a @@ -1687,7 +1687,7 @@ static func get_server_command() -> Array[String]: print("MCP | using dev venv: %s" % venv_python) return [venv_python, "-m", "godot_ai"] - var uvx := find_uvx() + var uvx := find_uvx(trace) if not uvx.is_empty(): var version := get_plugin_version() ## PEP 440 local build tags (e.g. 3.0.2+local.1) are not on PyPI. @@ -1715,7 +1715,7 @@ static func get_server_command() -> Array[String]: cmd.append_array(["--from", "godot-ai==%s" % pypi_version, "godot-ai"]) return cmd - var system_cmd := _find_system_install() + var system_cmd := _find_system_install(trace) if not system_cmd.is_empty(): print("MCP | using system install: %s" % system_cmd) return [system_cmd] @@ -1746,8 +1746,8 @@ static func get_server_launch_mode() -> String: const PREWARM_TIMEOUT_MS := 180000 -static func find_uvx() -> String: - return CliFinder.find(_uvx_cli_names()) +static func find_uvx(trace: Callable = Callable()) -> String: + return CliFinder.find(_uvx_cli_names(), trace) ## Pure argv builder for the pre-warm spawn, split out so tests can pin the @@ -2085,11 +2085,11 @@ static func find_worktree_src_dir(start_dir: String) -> String: ## directly: the finder adds the well-known-install-dirs and login-shell ## PATH tiers plus its per-exe cache, and this drops the private ## `_pick_best_path` cross-class reach (#711). -static func _find_system_install() -> String: +static func _find_system_install(trace: Callable = Callable()) -> String: ## Built with append, not a ternary of untyped literals — assigning a ## ternary's Array to Array[String] is a runtime error on newer Godot ## builds (same idiom as _uvx_cli_names above). var names: Array[String] = ["godot-ai"] if OS.get_name() == "Windows": names.push_front("godot-ai.exe") - return CliFinder.find(names) + return CliFinder.find(names, trace) diff --git a/addons/godot_ai/clients/_cli_finder.gd b/addons/godot_ai/clients/_cli_finder.gd index 394e76c..b22f508 100644 --- a/addons/godot_ai/clients/_cli_finder.gd +++ b/addons/godot_ai/clients/_cli_finder.gd @@ -29,9 +29,9 @@ const _LOOKUP_TIMEOUT_MS := 3000 ## Find any of the supplied exe names; returns the first hit. ## On Windows pass the .exe variant in `exe_names` if relevant. -static func find(exe_names: Array[String]) -> String: +static func find(exe_names: Array[String], trace: Callable = Callable()) -> String: for name in exe_names: - var hit := _find_one(name) + var hit := _find_one(name, trace) if not hit.is_empty(): return hit return "" @@ -49,19 +49,21 @@ static func invalidate(exe_name: String = "") -> void: _mutex.unlock() -static func _find_one(exe_name: String) -> String: +static func _find_one(exe_name: String, trace: Callable = Callable()) -> String: + var started := Time.get_ticks_msec() _mutex.lock() var already_searched: bool = _searched.get(exe_name, false) var cached: String = _cache.get(exe_name, "") _mutex.unlock() if already_searched: + _trace_lookup(trace, "cache", "resolved" if not cached.is_empty() else "cached_miss", started, {}, true) return cached # `_resolve()` does FileAccess + bounded subprocess lookup (forks # `bash -lc` / `which`), which can take 100ms-1s. Holding the mutex across that # would let a concurrent `invalidate()` on the main thread freeze the # editor for the duration of the subprocess — which defeats the whole # point of running CLI lookup off the main thread. - var hit := _resolve(exe_name) + var hit := _resolve(exe_name, trace) _mutex.lock() _cache[exe_name] = hit _searched[exe_name] = true @@ -69,14 +71,17 @@ static func _find_one(exe_name: String) -> String: return hit -static func _resolve(exe_name: String) -> String: +static func _resolve(exe_name: String, trace: Callable = Callable()) -> String: + var started := Time.get_ticks_msec() var is_windows := OS.get_name() == "Windows" # 1. Well-known locations for dir in _well_known_dirs(): var full := dir.path_join(exe_name) if FileAccess.file_exists(full): + _trace_lookup(trace, "well_known", "resolved", started) return full + _trace_lookup(trace, "well_known", "no_match", started) # 2. Login shell lookup (Unix only) if not is_windows: @@ -87,24 +92,58 @@ static func _resolve(exe_name: String) -> String: if shell.is_empty(): shell = "/bin/bash" var stripped := exe_name.trim_suffix(".exe") + started = Time.get_ticks_msec() var login_result := McpCliExec.run(shell, ["-lc", "command -v %s" % stripped], _LOOKUP_TIMEOUT_MS, false) if int(login_result.get("exit_code", -1)) == 0: var login_found: String = str(login_result.get("stdout", "")).strip_edges() if not login_found.is_empty() and FileAccess.file_exists(login_found): + _trace_lookup(trace, "login_shell", "resolved", started, login_result) return login_found + _trace_lookup(trace, "login_shell", _lookup_failure(login_result, false), started, login_result) # 3. which / where with inherited PATH var lookup := "where" if is_windows else "which" + started = Time.get_ticks_msec() var result := McpCliExec.run(lookup, [exe_name], _LOOKUP_TIMEOUT_MS, false) if int(result.get("exit_code", -1)) == 0: var output := str(result.get("stdout", "")) var lines := PackedStringArray(output.split("\n")) var found := _pick_best_path(lines) if is_windows else lines[0].strip_edges() if not found.is_empty(): + _trace_lookup(trace, "inherited_path", "resolved", started, result) return found + _trace_lookup(trace, "inherited_path", _lookup_failure(result, true), started, result) return "" +static func _lookup_failure(result: Dictionary, absence_exit: bool) -> String: + for flag in ["termination_failed", "cancelled", "timed_out", "spawn_failed"]: + if bool(result.get(flag, false)): + return flag + var code := int(result.get("exit_code", -1)) + if code == 0: + return "empty_output" if str(result.get("stdout", "")).strip_edges().is_empty() else "unusable_output" + return "not_found" if absence_exit and code == 1 else "nonzero_exit" + + +static func _trace_lookup( + trace: Callable, tier: String, status: String, started: int, + result: Dictionary = {}, cache_hit := false, +) -> void: + if not trace.is_valid(): + return + trace.call({ + "tier": tier, "status": status, + "elapsed_ms": clampi(Time.get_ticks_msec() - started, 0, 2147483647), + "cache_hit": cache_hit, + "exit_code": clampi(int(result.get("exit_code", -1)), -2147483648, 2147483647), + "timed_out": bool(result.get("timed_out", false)), + "spawn_failed": bool(result.get("spawn_failed", false)), + "cancelled": bool(result.get("cancelled", false)), + "termination_failed": bool(result.get("termination_failed", false)), + }) + + ## Executable extensions Windows' CreateProcessW can launch from a path ## (after the cmd.exe wrap in `_cli_exec.gd`). Order is preference: `.exe` ## is a native PE binary; `.cmd` / `.bat` go through the shell; `.com` is diff --git a/addons/godot_ai/plugin.cfg b/addons/godot_ai/plugin.cfg index 03d9b25..15856ad 100644 --- a/addons/godot_ai/plugin.cfg +++ b/addons/godot_ai/plugin.cfg @@ -3,5 +3,5 @@ name="Godot AI" description="MCP server and AI tools for Godot" author="Godot AI" -version="4.2.2" +version="4.2.3" script="plugin.gd" diff --git a/addons/godot_ai/plugin.gd b/addons/godot_ai/plugin.gd index 93a7ffe..62951b5 100644 --- a/addons/godot_ai/plugin.gd +++ b/addons/godot_ai/plugin.gd @@ -1355,6 +1355,11 @@ func _startup_trace_call_end(name: String, started_ms: int) -> void: ) +func _startup_trace_lookup(record: Dictionary) -> void: + if _startup_trace_enabled: + print("MCP startup trace | lookup=%s" % JSON.stringify(record)) + + func _startup_trace_finish(path: String) -> void: if not _startup_trace_enabled: return @@ -1392,7 +1397,8 @@ func _capture_lifecycle_plan() -> Dictionary: _startup_trace_call_end("worktree_source", worktree_started) var expected_version := ClientConfigurator.get_plugin_version() var command_started := _startup_trace_call_begin("server_command") - var server_command := ClientConfigurator.get_server_command() + var lookup_trace := _startup_trace_lookup if _startup_trace_enabled else Callable() + var server_command := ClientConfigurator.get_server_command(lookup_trace) _startup_trace_call_end("server_command", command_started) var pid_file := ProjectSettings.globalize_path(PortResolver.SERVER_PID_FILE) var startup_report := ProjectSettings.globalize_path(PortResolver.SERVER_STARTUP_REPORT) diff --git a/addons/godot_ai/utils/port_resolver.gd b/addons/godot_ai/utils/port_resolver.gd index 74dae41..f5a72b5 100644 --- a/addons/godot_ai/utils/port_resolver.gd +++ b/addons/godot_ai/utils/port_resolver.gd @@ -15,6 +15,12 @@ const SERVER_PID_FILE := "user://godot_ai_server.pid" const SERVER_STARTUP_REPORT := "user://godot_ai_server_startup.json" const WindowsPortReservation := preload("res://addons/godot_ai/utils/windows_port_reservation.gd") const LinuxProc := preload("res://addons/godot_ai/utils/linux_proc.gd") +const SNAPSHOT_DIAGNOSTIC_STAGES := ["single", "pair", "first", "final"] +const SNAPSHOT_DIAGNOSTIC_CATEGORIES := [ + "invalid_pid", "shell_exit", "empty_output", "outer_size", "outer_json", "outer_shape", + "snapshot_size", "snapshot_json", "snapshot_shape", "collector_null", "row_shape", + "row_pid", "row_chain", "row_identity", "lineage_cycle", +] static var _process_spawn_mutex := Mutex.new() enum PortOccupancy { UNKNOWN, FREE, OCCUPIED } @@ -392,18 +398,23 @@ static func pid_alive(pid: int, snapshot: Variant = null) -> bool: ## Linux captures the same bounded ancestry using procfs; macOS keeps ps. ## The process enumeration stays inside PowerShell; only the bounded target ## ancestry crosses back into Godot, without logging command-line metadata. -static func capture_process_snapshot(pid: int) -> Variant: +static func capture_process_snapshot(pid: int, diagnostics: Variant = null) -> Variant: if OS.get_name() == "Linux": return LinuxProc.process_snapshot(pid) if OS.get_name() != "Windows": return null if pid <= 1: - return {"capture_error": true} + return _snapshot_failure(diagnostics, "invalid_pid", "single") var script := _windows_process_snapshot_script(pid) var output: Array = [] - if execute_windows_powershell(script, output) != 0 or output.is_empty(): - return {"capture_error": true} - return parse_process_snapshot(str(output[0]), pid) + var began := Time.get_ticks_msec() + var code := execute_windows_powershell(script, output) + if code != 0 or output.is_empty(): + return _snapshot_failure( + diagnostics, "shell_exit" if code != 0 else "empty_output", + "single", -1, Time.get_ticks_msec() - began + ) + return parse_process_snapshot(str(output[0]), pid, diagnostics) static func _windows_process_snapshot_script(pid: int) -> String: @@ -426,63 +437,101 @@ static func _windows_process_snapshot_script(pid: int) -> String: ## Independent CIM maps in separate scriptblock scopes are ## captured within one shell invocation. No snapshot crosses a grant call. -static func _capture_windows_process_snapshot_pair(pid: int) -> Array: +static func _capture_windows_process_snapshot_pair(pid: int, diagnostics: Variant = null) -> Array: var query := _windows_process_snapshot_script(pid) var script := ( "$first = & { %s }; $final = & { %s }; " + "ConvertTo-Json -InputObject @([string]$first,[string]$final) -Compress" ) % [query, query] var output: Array = [] - if execute_windows_powershell(script, output) != 0 or output.is_empty(): + var began := Time.get_ticks_msec() + var code := execute_windows_powershell(script, output) + if code != 0 or output.is_empty(): + _snapshot_failure( + diagnostics, "shell_exit" if code != 0 else "empty_output", + "pair", -1, Time.get_ticks_msec() - began + ) return [{"capture_error": true}, {"capture_error": true}] - return _parse_process_snapshot_pair(str(output[0]), pid) + return _parse_process_snapshot_pair(str(output[0]), pid, diagnostics) -static func _parse_process_snapshot_pair(raw: String, pid: int) -> Array: +static func _parse_process_snapshot_pair( + raw: String, pid: int, diagnostics: Variant = null +) -> Array: if raw.length() > 4 * 1024 * 1024 + 16: + _snapshot_failure(diagnostics, "outer_size", "pair") return [{"capture_error": true}, {"capture_error": true}] var json := JSON.new() if json.parse(raw) != OK: + _snapshot_failure(diagnostics, "outer_json", "pair") return [{"capture_error": true}, {"capture_error": true}] var pair: Variant = json.data if not (pair is Array) or pair.size() != 2 or not (pair[0] is String and pair[1] is String): + _snapshot_failure(diagnostics, "outer_shape", "pair") return [{"capture_error": true}, {"capture_error": true}] - return [parse_process_snapshot(pair[0], pid), parse_process_snapshot(pair[1], pid)] + return [ + parse_process_snapshot(pair[0], pid, diagnostics, "first"), + parse_process_snapshot(pair[1], pid, diagnostics, "final"), + ] -static func parse_process_snapshot(raw: String, expected_pid: int) -> Dictionary: +static func parse_process_snapshot( + raw: String, expected_pid: int, diagnostics: Variant = null, stage := "single" +) -> Dictionary: if raw.length() > 1024 * 1024: - return {"capture_error": true} + return _snapshot_failure(diagnostics, "snapshot_size", stage, -1) var json := JSON.new() if json.parse(raw) != OK: - return {"capture_error": true} + return _snapshot_failure(diagnostics, "snapshot_json", stage, -1) var rows: Variant = json.data if not (rows is Array) or rows.size() > 16: - return {"capture_error": true} + return _snapshot_failure(diagnostics, "collector_null" if rows == null else "snapshot_shape", stage) var snapshot := {} var next_pid := expected_pid for row in rows: if not (row is Dictionary): - return {"capture_error": true} + return _snapshot_failure(diagnostics, "row_shape", stage, snapshot.size()) var value: Variant = row.get("pid") if ( not (value is int or value is float) or not is_finite(float(value)) or float(value) <= 1.0 or float(value) > 4294967295.0 or float(value) != float(int(value)) ): - return {"capture_error": true} + return _snapshot_failure(diagnostics, "row_pid", stage, snapshot.size()) var pid := int(value) if pid <= 1 or pid != next_pid or snapshot.has(pid): - return {"capture_error": true} + return _snapshot_failure(diagnostics, "row_chain", stage, snapshot.size()) snapshot[pid] = row if _process_snapshot_row(snapshot, pid).is_empty(): - return {"capture_error": true} + return _snapshot_failure(diagnostics, "row_identity", stage, snapshot.size() - 1) next_pid = int(row.parent_pid) if snapshot.has(next_pid): - return {"capture_error": true} + return _snapshot_failure(diagnostics, "lineage_cycle", stage, snapshot.size() - 1) return snapshot +## Diagnostics never carry proof rows, command lines, or shell output. The +## caller owns this sink: at most eight distinct failures, with bounded counts. +## Snapshots and authority remain unchanged. +static func _snapshot_failure( + diagnostics: Variant, category: String, stage: String, depth := -1, elapsed_ms := -1 +) -> Dictionary: + stage = stage if stage in SNAPSHOT_DIAGNOSTIC_STAGES else "unknown" + category = category if category in SNAPSHOT_DIAGNOSTIC_CATEGORIES else "unknown" + if diagnostics is Array: + for item in diagnostics: + if item.category == category and item.stage == stage and item.depth == depth: + item.count = mini(int(item.count) + 1, 10000) + return {"capture_error": true} + if diagnostics.size() < 8: + diagnostics.append({ + "category": category, "stage": stage, "depth": clampi(depth, -1, 16), + "elapsed_ms": clampi(elapsed_ms, -1, 600000), "count": 1, + }) + return {"capture_error": true} + + + ## An unavailable capture is not evidence that its PID has exited. static func capture_failed(snapshot: Variant) -> bool: return snapshot is Dictionary and bool(snapshot.get("capture_error", false)) @@ -666,12 +715,12 @@ static func process_fingerprint(pid: int, snapshot: Variant = null) -> String: ## `diagnostics`, when given, receives one word naming the check that ## refused the grant. It costs no extra probe and never changes the result. static func capture_process_kill_grant( - pid: int, require_brand := false, diagnostics: Array = [] + pid: int, require_brand := false, diagnostics: Array = [], snapshot_diagnostics: Variant = null ) -> Dictionary: if pid <= 1 or pid == OS.get_process_id(): diagnostics.append("invalid_pid") return {} - var pair: Array = _capture_windows_process_snapshot_pair(pid) if OS.get_name() == "Windows" else [] + var pair: Array = _capture_windows_process_snapshot_pair(pid, snapshot_diagnostics) if OS.get_name() == "Windows" else [] var first: Variant = pair[0] if not pair.is_empty() else capture_process_snapshot(pid) if capture_failed(first): diagnostics.append("identity_unavailable") diff --git a/addons/godot_ai/utils/server_lifecycle.gd b/addons/godot_ai/utils/server_lifecycle.gd index 903f52b..a46bb2b 100644 --- a/addons/godot_ai/utils/server_lifecycle.gd +++ b/addons/godot_ai/utils/server_lifecycle.gd @@ -850,17 +850,19 @@ func _effect_launch(payload: Dictionary) -> Dictionary: ## stable across two reads; otherwise a legitimate exec looks like PID reuse. var capture_started := Time.get_ticks_msec() var attempts: Array = [] - var exact_grant := PortResolver.capture_process_kill_grant(pid, true, attempts) + var snapshot_diagnostics: Array = [] + var exact_grant := PortResolver.capture_process_kill_grant(pid, true, attempts, snapshot_diagnostics) var fingerprint_deadline := capture_started + LAUNCH_FINGERPRINT_TIMEOUT_MS while exact_grant.is_empty() and Time.get_ticks_msec() < fingerprint_deadline: OS.delay_msec(100) - exact_grant = PortResolver.capture_process_kill_grant(pid, true, attempts) + exact_grant = PortResolver.capture_process_kill_grant(pid, true, attempts, snapshot_diagnostics) var fingerprint := str(exact_grant.get("fingerprint", "")) return { "ok": not fingerprint.is_empty(), "reason": "launch_unproven" if fingerprint.is_empty() else "", "message": ( _launch_unproven_message(pid, attempts, Time.get_ticks_msec() - capture_started) + + _snapshot_diagnostic_summary(snapshot_diagnostics) if fingerprint.is_empty() else "" ), @@ -873,6 +875,23 @@ func _effect_launch(payload: Dictionary) -> Dictionary: } +static func _snapshot_diagnostic_summary(diagnostics: Array) -> String: + var labels: Array[String] = [] + for item in diagnostics.slice(0, 8): + var stage: String = item.stage if item.stage in PortResolver.SNAPSHOT_DIAGNOSTIC_STAGES else "unknown" + var category: String = item.category if item.category in PortResolver.SNAPSHOT_DIAGNOSTIC_CATEGORIES else "unknown" + var label := "launch_grant/%s/%s" % [stage, category] + if int(item.depth) >= 0: + label += " at depth %d" % clampi(int(item.depth), 0, 16) + if int(item.count) > 1: + label += " x%d" % clampi(int(item.count), 1, 10000) + if int(item.elapsed_ms) >= 0: + label += " (first query %d ms)" % clampi(int(item.elapsed_ms), 0, 600000) + if not labels.has(label): + labels.append(label) + return "" if labels.is_empty() else " Snapshot diagnostics: " + "; ".join(labels) + "." + + ## Name which identity check failed so a Windows report can be acted on ## (#988, #1012 both surfaced as this bare sentence). Diagnostic only: the ## values are read once more after the capture budget and never grant