Skip to content

Commit 8cb10ec

Browse files
dsarnoclaude
andauthored
Fix opaque 10s game_eval timeout on compile/runtime errors (#490)
game_eval now returns fast, specific errors instead of an opaque ~10s INTERNAL_ERROR: - Compile/parse error -> EVAL_COMPILE_ERROR (editor grace timer, gated on an eval_ack so a busy/unserviced game isn't mistaken for a parse failure). - Runtime error -> EVAL_RUNTIME_ERROR with the real text + line (editor-driven eval_check probe; per-request tracking + a per-eval wrapper-function token so unrelated background errors and overlapping evals never cross-attribute). - Genuine hang -> #488's 8s guard (focused) / refined editor timeout (backgrounded). Root cause: a backgrounded play-in-editor game's idle loop freezes (only the debugger capture callback stays live), so detection is editor-driven. Composes with #488's hung-await deadline guard. Tests: Python (new error codes + propagation) and GDScript (logger token lookup, per-request/token isolation incl. unrelated-error and overlapping-eval cases, ack-gated compile grace, editor-side handlers). Self-update smoke verified; no per-frame work added to the game main thread. Closes #490. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
1 parent 8933203 commit 8cb10ec

10 files changed

Lines changed: 804 additions & 23 deletions

File tree

plugin/addons/godot_ai/debugger/mcp_debugger_plugin.gd

Lines changed: 160 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -30,6 +30,20 @@ const DEFAULT_TIMEOUT_SEC := 8.0
3030
## silent black hole. On CI the game subprocess has been observed
3131
## taking ~15s to boot + register.
3232
const GAME_READY_WAIT_SEC := 20.0
33+
## #490: how long to wait for the game's mcp:eval_compiled beacon before
34+
## concluding the eval source failed to compile. A parse error aborts the
35+
## game-side handler before it can reply, so without this we'd wait the
36+
## full eval timeout for a syntax mistake. reload() of valid source is
37+
## sub-millisecond, so 3s is comfortably clear of false positives.
38+
const EVAL_COMPILE_GRACE_SEC := 3.0
39+
## #490: once an eval compiles, the editor polls the game every this many
40+
## seconds with mcp:eval_check. A backgrounded play-in-editor game has a
41+
## frozen idle loop (no _process / SceneTreeTimer ticks) so it can't
42+
## self-report a runtime error that aborted the eval — but its debugger
43+
## capture callback still answers a probe. The editor's own loop keeps
44+
## ticking, so it drives the poll. 0.35s keeps detection well under a second
45+
## without flooding the channel; most evals reply before the first probe.
46+
const EVAL_PROBE_INTERVAL_SEC := 0.35
3347

3448
var _log_buffer: McpLogBuffer
3549
var _game_log_buffer: McpGameLogBuffer
@@ -140,6 +154,15 @@ func _capture(message: String, data: Array, _session_id: int) -> bool:
140154
"mcp:eval_error":
141155
_on_eval_error(data)
142156
return true
157+
"mcp:eval_ack":
158+
_on_eval_ack(data)
159+
return true
160+
"mcp:eval_compiled":
161+
_on_eval_compiled(data)
162+
return true
163+
"mcp:eval_runtime_error":
164+
_on_eval_runtime_error(data)
165+
return true
143166
"mcp:game_command_response":
144167
_on_game_command_response(data)
145168
return true
@@ -326,6 +349,15 @@ func _clear_pending(request_id: String) -> void:
326349
var cb: Callable = pending.get("timeout_callable", Callable())
327350
if timer != null and timer.timeout.is_connected(cb):
328351
timer.timeout.disconnect(cb)
352+
## #490: eval requests also carry a compile-grace timer and a runtime probe.
353+
var grace: SceneTreeTimer = pending.get("grace_timer")
354+
var gcb: Callable = pending.get("grace_callable", Callable())
355+
if grace != null and grace.timeout.is_connected(gcb):
356+
grace.timeout.disconnect(gcb)
357+
var probe: SceneTreeTimer = pending.get("probe_timer")
358+
var pcb: Callable = pending.get("probe_callable", Callable())
359+
if probe != null and probe.timeout.is_connected(pcb):
360+
probe.timeout.disconnect(pcb)
329361
_pending.erase(request_id)
330362

331363

@@ -398,19 +430,32 @@ func _send_eval(
398430
var pending_entry = _pending.get(request_id)
399431
if pending_entry == null:
400432
return
401-
_pending.erase(request_id)
433+
_clear_pending(request_id)
402434
var conn: McpConnection = pending_entry.connection
403435
if conn == null or not is_instance_valid(conn):
404436
return
405437
_send_error(conn, request_id, ErrorCodes.INTERNAL_ERROR,
406-
"Game eval timed out after %.0fs — eval code may be stuck in an infinite loop / await, OR triggered a GDScript runtime error that halted execution before responding. Check logs_read(source='game') for push_error/runtime errors from this run." % timeout_sec)
438+
"Game eval compiled and started running but never returned within %.0fs — the code is likely stuck in an infinite loop or awaiting a signal/timer that never fires. Check logs_read(source='game')." % timeout_sec)
407439
if _log_buffer:
408440
_log_buffer.log("[debug] !! eval timeout (%s)" % request_id)
409441
timer.timeout.connect(timeout_callable)
442+
443+
## #490: arm the compile-grace timer. _on_eval_grace concludes a parse error
444+
## only when the game acked the eval (it received the message and started
445+
## reload()) but never sent mcp:eval_compiled — see there for why a missing
446+
## ack must NOT be read as a compile error.
447+
var grace: SceneTreeTimer = tree.create_timer(EVAL_COMPILE_GRACE_SEC)
448+
var grace_callable := func() -> void: _on_eval_grace(request_id)
449+
grace.timeout.connect(grace_callable)
450+
410451
_pending[request_id] = {
411452
"connection": connection,
412453
"timer": timer,
413454
"timeout_callable": timeout_callable,
455+
"grace_timer": grace,
456+
"grace_callable": grace_callable,
457+
"acked": false,
458+
"compiled": false,
414459
}
415460

416461
session.send_message("mcp:eval", [request_id, code])
@@ -462,6 +507,119 @@ func _on_eval_error(data: Array) -> void:
462507
_log_buffer.log("[debug] <- mcp:eval_error (%s): %s" % [request_id, message])
463508

464509

510+
## #490: the game sends this at the top of _handle_eval, BEFORE reload() (so it
511+
## survives a parse-error abort). It positively signals "the game received this
512+
## eval and started compiling it" — letting _on_eval_grace tell a real parse
513+
## error (acked, never compiled) apart from a message the game hasn't serviced
514+
## yet (never acked — main thread blocked by a long frame/load or a CPU-bound
515+
## prior eval).
516+
func _on_eval_ack(data: Array) -> void:
517+
if data.is_empty():
518+
return
519+
var request_id: String = data[0]
520+
var pending_entry = _pending.get(request_id)
521+
if pending_entry == null:
522+
return
523+
pending_entry["acked"] = true
524+
if _log_buffer:
525+
_log_buffer.log("[debug] <- mcp:eval_ack (%s)" % request_id)
526+
527+
528+
## #490: compile-grace timer fired. Conclude a parse error ONLY when the game
529+
## acked the eval (started reload()) but never sent mcp:eval_compiled. If it
530+
## never acked, the game simply hasn't serviced the message yet — NOT a parse
531+
## error — so leave _pending intact and let the normal eval timeout handle it
532+
## rather than false-failing a valid eval and dropping its eventual real reply.
533+
func _on_eval_grace(request_id: String) -> void:
534+
var pending_entry = _pending.get(request_id)
535+
if pending_entry == null or pending_entry.get("compiled", false):
536+
return
537+
if not pending_entry.get("acked", false):
538+
if _log_buffer:
539+
_log_buffer.log("[debug] eval grace: no ack yet, deferring to timeout (%s)" % request_id)
540+
return
541+
_clear_pending(request_id)
542+
var conn: McpConnection = pending_entry.connection
543+
if conn == null or not is_instance_valid(conn):
544+
return
545+
_send_error(conn, request_id, ErrorCodes.EVAL_COMPILE_ERROR,
546+
"Game eval failed to compile — likely a GDScript syntax/parse error. The parse error text is in the editor's Output/Debugger panel; it is not capturable from the running game. Check your eval code's syntax.")
547+
if _log_buffer:
548+
_log_buffer.log("[debug] !! eval compile error (%s)" % request_id)
549+
550+
551+
## #490: the game sends this the instant reload() of the eval source
552+
## succeeds. Flips the pending entry's `compiled` flag so the compile-grace
553+
## timer won't fire a false EVAL_COMPILE_ERROR.
554+
func _on_eval_compiled(data: Array) -> void:
555+
if data.is_empty():
556+
return
557+
var request_id: String = data[0]
558+
var pending_entry = _pending.get(request_id)
559+
if pending_entry == null:
560+
return
561+
pending_entry["compiled"] = true
562+
if _log_buffer:
563+
_log_buffer.log("[debug] <- mcp:eval_compiled (%s)" % request_id)
564+
## #490: compiled OK — start polling for a runtime error that may have
565+
## aborted execute(). A backgrounded game can't self-report it, so the
566+
## editor probes via mcp:eval_check until the eval resolves.
567+
_arm_eval_probe(request_id)
568+
569+
570+
## #490: the game reported a runtime error that aborted the eval — either
571+
## from its _process fast path (focused game) or in answer to an editor
572+
## eval_check probe (backgrounded game). Reply fast with the real error text
573+
## instead of waiting for the hang timeout.
574+
func _on_eval_runtime_error(data: Array) -> void:
575+
if data.size() < 2:
576+
return
577+
var request_id: String = data[0]
578+
var message: String = data[1]
579+
var pending_entry = _pending.get(request_id)
580+
if pending_entry == null:
581+
return
582+
_clear_pending(request_id)
583+
var connection: McpConnection = pending_entry.connection
584+
if connection == null or not is_instance_valid(connection):
585+
return
586+
var msg := "Game eval raised a runtime error: %s" % message if not message.is_empty() else "Game eval raised a runtime error (no message captured). Check logs_read(source='game')."
587+
_send_error(connection, request_id, ErrorCodes.EVAL_RUNTIME_ERROR, msg)
588+
if _log_buffer:
589+
_log_buffer.log("[debug] <- mcp:eval_runtime_error (%s): %s" % [request_id, message])
590+
591+
592+
## #490: arm one probe tick for an in-flight eval. Re-arms itself each tick
593+
## until the request resolves — eval_response / eval_runtime_error /
594+
## eval_compile_error / hang-timeout all call _clear_pending, which erases the
595+
## entry and stops the chain. Uses the editor's own SceneTreeTimer because the
596+
## editor loop keeps ticking even while a backgrounded game's loop is frozen.
597+
func _arm_eval_probe(request_id: String) -> void:
598+
var pending_entry = _pending.get(request_id)
599+
if pending_entry == null:
600+
return
601+
var tree := Engine.get_main_loop() as SceneTree
602+
if tree == null:
603+
return
604+
var probe_timer: SceneTreeTimer = tree.create_timer(EVAL_PROBE_INTERVAL_SEC)
605+
var probe_callable := func() -> void: _on_eval_probe_tick(request_id)
606+
pending_entry["probe_timer"] = probe_timer
607+
pending_entry["probe_callable"] = probe_callable
608+
probe_timer.timeout.connect(probe_callable)
609+
610+
611+
## #490: poke the game for a runtime-error verdict, then re-arm. The game's
612+
## _handle_eval_check answers with mcp:eval_runtime_error if a script error
613+
## aborted this eval, else stays silent and we poll again next interval.
614+
func _on_eval_probe_tick(request_id: String) -> void:
615+
if not _pending.has(request_id):
616+
return ## resolved — stop probing
617+
var session: EditorDebuggerSession = _first_active_session()
618+
if session != null and session.is_active():
619+
session.send_message("mcp:eval_check", [request_id])
620+
_arm_eval_probe(request_id)
621+
622+
465623
## --- game_command: curated runtime game operations ---
466624

467625
func request_game_command(

0 commit comments

Comments
 (0)