From 654aca97100ab6f5002a1f29dc1d00ef30ce8468 Mon Sep 17 00:00:00 2001 From: hatayama Date: Thu, 8 Oct 2026 00:01:56 +0900 Subject: [PATCH 1/2] Report the wait's timeout and the marker id in pause point wait failures Details.TimeoutSeconds showed the marker's window while the Message quoted the await's own --timeout-seconds, so a 5-second wait reported 30. TimeoutSeconds now carries the wait's value and the marker's window moves to MarkerTimeoutSeconds, present only when the status answer gave one. Details.Id now prefers the Editor's normalized marker id so it matches the status command, and falls back to the typed id without a status answer. --- .../projectrunner/pause_point_errors.go | 32 ++++++----- .../projectrunner/pause_point_errors_test.go | 53 +++++++++++++++++++ .../projectrunner/pause_point_wait_test.go | 10 ++-- 3 files changed, 79 insertions(+), 16 deletions(-) diff --git a/cli/project-runner/internal/projectrunner/pause_point_errors.go b/cli/project-runner/internal/projectrunner/pause_point_errors.go index 5171eeb39b..526239070b 100644 --- a/cli/project-runner/internal/projectrunner/pause_point_errors.go +++ b/cli/project-runner/internal/projectrunner/pause_point_errors.go @@ -405,15 +405,16 @@ func pausePointStateErrorDetails( response pausePointStatusResponse, ) map[string]any { details := map[string]any{ - "Id": options.id, - "Status": response.Status, - "Expired": response.Expired, - "HitCount": response.HitCount, - "MethodEntryCount": response.MethodEntryCount, - "HitWhen": response.HitWhen, - "HitWhenSkippedCount": response.HitWhenSkippedCount, - "HitWhenErrorNote": response.HitWhenErrorNote, - "TimeoutSeconds": pausePointMarkerTimeoutSeconds(options, response), + "Id": pausePointDetailsID(options, response), + "Status": response.Status, + "Expired": response.Expired, + "HitCount": response.HitCount, + "MethodEntryCount": response.MethodEntryCount, + "HitWhen": response.HitWhen, + "HitWhenSkippedCount": response.HitWhenSkippedCount, + "HitWhenErrorNote": response.HitWhenErrorNote, + // Why the wait's value: it is what the Message quotes ("not hit within Ns"). + "TimeoutSeconds": options.timeoutSeconds, "EnabledAtUtc": response.EnabledAtUtc, "ElapsedSinceEnabledMilliseconds": response.ElapsedSinceEnabledMilliseconds, "Generation": response.Generation, @@ -423,6 +424,9 @@ func pausePointStateErrorDetails( "RecommendedNextAction": response.RecommendedNextAction, "SuppressedByHotReload": response.SuppressedByHotReload, } + if response.TimeoutSeconds > 0 { + details["MarkerTimeoutSeconds"] = response.TimeoutSeconds + } if response.ClearedReason != "" { details["ClearedReason"] = response.ClearedReason } @@ -435,11 +439,13 @@ func pausePointStateErrorDetails( return details } -func pausePointMarkerTimeoutSeconds(options waitForPausePointOptions, response pausePointStatusResponse) int { - if response.TimeoutSeconds > 0 { - return response.TimeoutSeconds +// pausePointDetailsID prefers the status answer's marker id, because the Editor +// normalizes it and it then matches the Id that the status command reports. +func pausePointDetailsID(options waitForPausePointOptions, response pausePointStatusResponse) string { + if response.Id != "" { + return response.Id } - return options.timeoutSeconds + return options.id } func pausePointRemainingMilliseconds(options waitForPausePointOptions, response pausePointStatusResponse) int64 { diff --git a/cli/project-runner/internal/projectrunner/pause_point_errors_test.go b/cli/project-runner/internal/projectrunner/pause_point_errors_test.go index 66497bc4f6..826091bd6c 100644 --- a/cli/project-runner/internal/projectrunner/pause_point_errors_test.go +++ b/cli/project-runner/internal/projectrunner/pause_point_errors_test.go @@ -169,6 +169,59 @@ func TestPausePointStateError_DetailsIncludeSuppressedByHotReload(t *testing.T) } } +// Verifies a failed await reports its own --timeout-seconds as TimeoutSeconds, the +// marker's window as MarkerTimeoutSeconds, and the Editor's normalized marker id. +func TestPausePointStateErrorDetailsCarryTheWaitTimeoutAndTheMarkerId(t *testing.T) { + options := waitForPausePointOptions{id: "./Assets/Foo.cs:42", timeoutSeconds: 5} + response := pausePointStatusResponse{ + Id: "Assets/Foo.cs:42", + Status: pausePointStatusEnabled, + TimeoutSeconds: 30, + } + + err := pausePointStateError( + "PAUSE_POINT_WAIT_TIMEOUT", + "Pause point was not hit within 5s.", + "/tmp/project", + options, + response, + true) + + if got := err.Details["TimeoutSeconds"]; got != 5 { + t.Fatalf("TimeoutSeconds = %v, want 5", got) + } + if got := err.Details["MarkerTimeoutSeconds"]; got != 30 { + t.Fatalf("MarkerTimeoutSeconds = %v, want 30", got) + } + if got := err.Details["Id"]; got != "Assets/Foo.cs:42" { + t.Fatalf("Id = %v, want Assets/Foo.cs:42", got) + } +} + +// Verifies a failed await with no status answer keeps the typed id and omits the +// marker window instead of reporting 0. +func TestPausePointStateErrorDetailsFallBackToTheTypedIdWithoutAStatus(t *testing.T) { + options := waitForPausePointOptions{id: "./Assets/Foo.cs:42", timeoutSeconds: 5} + + err := pausePointStateError( + "PAUSE_POINT_WAIT_TIMEOUT", + "Pause point was not hit within 5s.", + "/tmp/project", + options, + pausePointStatusResponse{}, + true) + + if got := err.Details["Id"]; got != "./Assets/Foo.cs:42" { + t.Fatalf("Id = %v, want ./Assets/Foo.cs:42", got) + } + if got := err.Details["TimeoutSeconds"]; got != 5 { + t.Fatalf("TimeoutSeconds = %v, want 5", got) + } + if got, ok := err.Details["MarkerTimeoutSeconds"]; ok { + t.Fatalf("MarkerTimeoutSeconds = %v, want the key omitted", got) + } +} + // Verifies await failures expose the hit-when state that distinguishes skipped // conditional captures from a line that never ran. func TestPausePointStateErrorDetailsIncludeHitWhenDiagnostics(t *testing.T) { diff --git a/cli/project-runner/internal/projectrunner/pause_point_wait_test.go b/cli/project-runner/internal/projectrunner/pause_point_wait_test.go index 707cd30bf3..5517c31a5b 100644 --- a/cli/project-runner/internal/projectrunner/pause_point_wait_test.go +++ b/cli/project-runner/internal/projectrunner/pause_point_wait_test.go @@ -685,7 +685,8 @@ func TestPausePointExpiredErrorUsesFileLineNextActions(t *testing.T) { } } -// Verifies recovery details use the marker lifetime instead of the wait deadline. +// Verifies recovery details carry the marker lifetime as MarkerTimeoutSeconds while +// TimeoutSeconds stays the wait's own --timeout-seconds. func TestPausePointExpiredErrorReportsMarkerTimeoutSeconds(t *testing.T) { response := pausePointStatusResponse{ Id: "jump", @@ -700,8 +701,11 @@ func TestPausePointExpiredErrorReportsMarkerTimeoutSeconds(t *testing.T) { timeoutSeconds: 5, }, response, pausePointWaitStateExpired, false, false, nil) - if cliErr.Details["TimeoutSeconds"] != 30 { - t.Fatalf("timeoutSeconds detail mismatch: %#v", cliErr.Details) + if cliErr.Details["MarkerTimeoutSeconds"] != 30 { + t.Fatalf("MarkerTimeoutSeconds detail mismatch: %#v", cliErr.Details) + } + if cliErr.Details["TimeoutSeconds"] != 5 { + t.Fatalf("TimeoutSeconds detail mismatch: %#v", cliErr.Details) } } From ff1e1e66984165ce6a22e4be749002ad646cf65f Mon Sep 17 00:00:00 2001 From: hatayama Date: Thu, 8 Oct 2026 00:02:59 +0900 Subject: [PATCH 2/2] Name the busy tool and the resent requests in the CLI vibe log A busy cli_tool_request_failed entry only said rpc:server_busy, so the log could not tell which command held the Editor; it now carries running_tool_name when Unity named one. The busy-wait complete entry counted resends but could not point at them, which left resent requests orphaned in an investigation; it now lists their correlation ids in order as resend_correlation_ids. The hot-reload busy note reuses the same busy-data reader instead of declaring its own. --- .../projectrunner/hot_reload_busy_wait.go | 36 +++++++++++-------- .../hot_reload_busy_wait_test.go | 15 +++++++- .../internal/projectrunner/plain_tool_log.go | 23 +++++++++++- .../projectrunner/plain_tool_log_test.go | 32 +++++++++++++++++ docs/vibe-logs.md | 4 +-- 5 files changed, 91 insertions(+), 19 deletions(-) diff --git a/cli/project-runner/internal/projectrunner/hot_reload_busy_wait.go b/cli/project-runner/internal/projectrunner/hot_reload_busy_wait.go index 4f3f6b490d..154d59626a 100644 --- a/cli/project-runner/internal/projectrunner/hot_reload_busy_wait.go +++ b/cli/project-runner/internal/projectrunner/hot_reload_busy_wait.go @@ -113,6 +113,8 @@ type hotReloadBusyWait struct { outcome unityipc.UnitySendOutcome sendErr error resends int + // resendCorrelationIDs holds the correlation id of every resent request, in order. + resendCorrelationIDs []string } // waitForBusyEditor polls the Editor status until it is ready, the budget runs out, or ctx is @@ -143,6 +145,7 @@ func waitForBusyEditor( answer, outcome, err := sendPlainTool(ctx, connection, hotReloadCommandName, params, stderr, deps) lastResend = time.Now() wait.resends++ + wait.resendCorrelationIDs = append(wait.resendCorrelationIDs, answer.correlationID) if !isUnityServerBusyRPCError(err) { wait.waited, wait.ready, wait.answered = time.Since(startedAt), err == nil, true wait.answer, wait.outcome, wait.sendErr = answer, outcome, err @@ -171,17 +174,11 @@ func isHeldByExecuteDynamicCode(status editorStatusResponse) bool { // hotReloadBusyRunningToolName names the command that held the Editor, from the busy answer's data. func hotReloadBusyRunningToolName(err error) string { - var rpcErr *unityipc.RPCError - if !errors.As(err, &rpcErr) { + name, ok := serverBusyRunningToolName(err) + if !ok { return hotReloadBusyUnknownToolName } - data := struct { - RunningToolName string `json:"runningToolName"` - }{} - if json.Unmarshal(rpcErr.Data, &data) != nil || data.RunningToolName == "" { - return hotReloadBusyUnknownToolName - } - return data.RunningToolName + return name } func hotReloadBusyWaitNote(runningToolName string, waited time.Duration, ready bool) string { @@ -242,6 +239,14 @@ func logHotReloadBusyWaitDecided(connection unityipc.Connection, correlationID s }) } +// Why never nil: a nil slice is written as null, and an empty wait should read as []. +func resendCorrelationIDsOrEmpty(wait hotReloadBusyWait) []string { + if wait.resendCorrelationIDs == nil { + return []string{} + } + return wait.resendCorrelationIDs +} + // Written once on every way out of a wait that started. second is nil when no request was sent // after the wait. func logHotReloadBusyWaitComplete( @@ -252,12 +257,13 @@ func logHotReloadBusyWaitComplete( ) { writePlainToolVibeLog(connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { entryContext := map[string]any{ - "correlation_id": correlationID, - "second_correlation_id": "", - "waited_ms": wait.waited.Milliseconds(), - "ready": wait.ready, - "resends": wait.resends, - "second_result": false, + "correlation_id": correlationID, + "second_correlation_id": "", + "waited_ms": wait.waited.Milliseconds(), + "ready": wait.ready, + "resends": wait.resends, + "resend_correlation_ids": resendCorrelationIDsOrEmpty(wait), + "second_result": false, } if second != nil { entryContext["second_correlation_id"] = second.correlationID diff --git a/cli/project-runner/internal/projectrunner/hot_reload_busy_wait_test.go b/cli/project-runner/internal/projectrunner/hot_reload_busy_wait_test.go index 94b7080513..c21fd4f1a6 100644 --- a/cli/project-runner/internal/projectrunner/hot_reload_busy_wait_test.go +++ b/cli/project-runner/internal/projectrunner/hot_reload_busy_wait_test.go @@ -332,7 +332,10 @@ func TestRunHotReloadWritesBusyWaitVibeLogs(t *testing.T) { if len(failed) == 0 { t.Fatalf("cli_tool_request_failed entries = 0, want the busy answer\n%s", logContent) } - assertCliVibeContextValues(t, cliVibeEntryContext(t, failed[0]), map[string]any{"error_kind": "rpc:server_busy"}) + assertCliVibeContextValues(t, cliVibeEntryContext(t, failed[0]), map[string]any{ + "error_kind": "rpc:server_busy", + "running_tool_name": "compile", + }) decided := singleCliVibeEntry(t, logContent, hotReloadBusyWaitDecidedOperation) assertSharedCliVibeCorrelationID(t, sent[0], decided) @@ -357,6 +360,9 @@ func TestRunHotReloadWritesBusyWaitVibeLogs(t *testing.T) { "second_success": true, "second_outcome": "Applied", }) + if resent := completeContext["resend_correlation_ids"]; !reflect.DeepEqual(resent, []any{}) { + t.Fatalf("resend_correlation_ids = %#v, want an empty array", resent) + } if _, isNumber := completeContext["waited_ms"].(float64); !isNumber { t.Fatalf("waited_ms = %#v, want a number", completeContext["waited_ms"]) } @@ -562,6 +568,13 @@ func TestRunHotReloadSendsAgainWhileACancelledExecuteDynamicCodeHoldsTheEditor(t "ready": true, "second_correlation_id": vibeLogContextString(t, sent[2], "correlation_id"), }) + wantResent := []any{ + vibeLogContextString(t, sent[1], "correlation_id"), + vibeLogContextString(t, sent[2], "correlation_id"), + } + if resent := complete["resend_correlation_ids"]; !reflect.DeepEqual(resent, wantResent) { + t.Fatalf("resend_correlation_ids = %#v, want %#v", resent, wantResent) + } } // Verifies no request is sent again before the resend interval has passed, even while diff --git a/cli/project-runner/internal/projectrunner/plain_tool_log.go b/cli/project-runner/internal/projectrunner/plain_tool_log.go index 7617092383..42e434d51e 100644 --- a/cli/project-runner/internal/projectrunner/plain_tool_log.go +++ b/cli/project-runner/internal/projectrunner/plain_tool_log.go @@ -5,6 +5,7 @@ package projectrunner // never a parameter value or a response body, which can name files of the project or carry code. import ( + "encoding/json" "errors" "sort" "time" @@ -90,7 +91,7 @@ func logPlainToolRequestFailed( writePlainToolVibeLog(connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { // Why no err.Error(): a Unity parameter-validation RPC error quotes the raw parameter values // in its message, and this log must never carry parameter values. - return vibelog.CLIVibeLogEntry{ + entry := vibelog.CLIVibeLogEntry{ Level: "ERROR", Operation: plainToolRequestFailedOperation, Message: "The tool request to Unity failed.", @@ -103,9 +104,29 @@ func logPlainToolRequestFailed( }, CorrelationID: correlationID, } + if name, ok := serverBusyRunningToolName(err); ok { + entry.Context["running_tool_name"] = name + } + return entry }) } +// serverBusyRunningToolName reads the name of the tool that held the Editor from a busy answer's +// data. It reports false for any other error, and for a busy answer that names no tool. +func serverBusyRunningToolName(err error) (string, bool) { + var rpcErr *unityipc.RPCError + if !errors.As(err, &rpcErr) || clierrors.RPCDataType(rpcErr.Data) != "server_busy" { + return "", false + } + data := struct { + RunningToolName string `json:"runningToolName"` + }{} + if json.Unmarshal(rpcErr.Data, &data) != nil || data.RunningToolName == "" { + return "", false + } + return data.RunningToolName, true +} + // classifyPlainToolError names what failed without any of the error's text: "rpc:" followed by the // type Unity attached to its error (empty when it attached none), "final_response_timeout", or // "other". diff --git a/cli/project-runner/internal/projectrunner/plain_tool_log_test.go b/cli/project-runner/internal/projectrunner/plain_tool_log_test.go index 6e951cb051..6424862e6c 100644 --- a/cli/project-runner/internal/projectrunner/plain_tool_log_test.go +++ b/cli/project-runner/internal/projectrunner/plain_tool_log_test.go @@ -281,3 +281,35 @@ func assertCliVibeLogOmitsTheSentinel(t *testing.T, logContent string) { t.Fatalf("the vibe log must not contain a parameter value or an error message:\n%s", logContent) } } + +// Verifies the failure entry names the tool that held the Editor only for a busy answer that +// carries the name. +func TestLogPlainToolRequestFailedNamesTheRunningToolOnlyForABusyAnswer(t *testing.T) { + cases := []struct { + name string + data string + wantName bool + }{ + {name: "busy with a name", data: `{"type":"server_busy","runningToolName":"compile"}`, wantName: true}, + {name: "busy without a name", data: `{"type":"server_busy"}`}, + {name: "not busy", data: `{"type":"invalid_params","runningToolName":"compile"}`}, + } + for _, testCase := range cases { + t.Run(testCase.name, func(t *testing.T) { + enableCliVibeLog(t) + projectRoot := t.TempDir() + err := &unityipc.RPCError{Code: -32603, Message: "failed", Data: []byte(testCase.data)} + + logPlainToolRequestFailed(unityipc.Connection{ProjectRoot: projectRoot}, "get-logs", "corr-1", 0, + unityipc.UnitySendOutcome{}, err) + + failedContext := cliVibeEntryContext(t, + singleCliVibeEntry(t, readOnlyCliVibeLog(t, projectRoot), "cli_tool_request_failed")) + if testCase.wantName { + assertCliVibeContextValues(t, failedContext, map[string]any{"running_tool_name": "compile"}) + return + } + assertCliVibeContextOmits(t, failedContext, "running_tool_name") + }) + } +} diff --git a/docs/vibe-logs.md b/docs/vibe-logs.md index f9457370c6..7dd2488142 100644 --- a/docs/vibe-logs.md +++ b/docs/vibe-logs.md @@ -67,9 +67,9 @@ or `control-play-mode` that waits for a domain reload or a Play Mode change, and |---|---|---| | `cli_tool_request_sent` | before the request is sent | `command`, `correlation_id`, `project_identity`, `cli_version`, `param_keys` (sorted), `array_lengths` (element count of each array parameter) | | `cli_tool_response_received` | when Unity answered | `command`, `correlation_id`, `elapsed_ms`, `request_accepted`, `result_bytes`, `exit_code` | -| `cli_tool_request_failed` (`ERROR`) | when no answer came, or Unity answered with an error | `command`, `correlation_id`, `elapsed_ms`, `request_accepted`, `error_kind` (`rpc:`, `final_response_timeout`, or `other`) | +| `cli_tool_request_failed` (`ERROR`) | when no answer came, or Unity answered with an error | `command`, `correlation_id`, `elapsed_ms`, `request_accepted`, `error_kind` (`rpc:`, `final_response_timeout`, or `other`), `running_tool_name` (only when `error_kind` is `rpc:server_busy` and Unity named the tool that held the Editor) | | `cli_hot_reload_busy_wait_decided` | when the first `hot-reload` answer is `server_busy` (another uloop command holds the Editor; the preceding `cli_tool_request_failed` has `error_kind` `rpc:server_busy`) | `correlation_id` (the first request's), `running_tool_name`, `running_tool_phase`, `running_tool_elapsed_seconds`, `budget_ms`, `resend_interval_ms` | -| `cli_hot_reload_busy_wait_complete` (`WARN` unless the Editor became ready and the request sent after the wait answered) | after the wait and the one request sent after it, on every way out of a wait that started (a cancel, a failed send, and a bad answer included) | `correlation_id` (the first request's), `second_correlation_id` (the request sent after the wait, or empty when none was sent), `waited_ms`, `ready`, `resends` (requests sent again during the wait while a cancelled `execute-dynamic-code` held the Editor; each also has its own `cli_tool_request_sent`), `second_result`, and that answer's `second_success` and `second_outcome` | +| `cli_hot_reload_busy_wait_complete` (`WARN` unless the Editor became ready and the request sent after the wait answered) | after the wait and the one request sent after it, on every way out of a wait that started (a cancel, a failed send, and a bad answer included) | `correlation_id` (the first request's), `second_correlation_id` (the request sent after the wait, or empty when none was sent), `waited_ms`, `ready`, `resends` (requests sent again during the wait while a cancelled `execute-dynamic-code` held the Editor; each also has its own `cli_tool_request_sent`), `resend_correlation_ids` (the `correlation_id` of every request sent again during the wait, in order; its length is `resends`, and its last entry equals `second_correlation_id` when a resent request got in), `second_result`, and that answer's `second_success` and `second_outcome` | | `cli_hot_reload_editor_ready_retry_decided` | after every `hot-reload` answer (the one after a busy wait, when one ran), before the fallback decision | `correlation_id` (the request's), `requested`, `parse_error` | | `cli_hot_reload_editor_ready_retry_complete` (`WARN` unless the Editor settled and the second apply answered) | after the wait and the second apply, when a retry was requested | `correlation_id` (the first request's), `second_correlation_id` (the second request's, or empty when none was sent), `waited_ms`, `ready`, `second_result`, and the second answer's `second_success` and `second_outcome` | | `cli_hot_reload_compile_fallback_decided` | after every `hot-reload` answer the fallback decision sees: the second one after an editor-ready retry, and none when that retry ended the command (see `cli_hot_reload_editor_ready_retry_complete`) | `correlation_id` (the request's), `requested`, `parse_error`, and the answer's `success`, `outcome`, `warnings_count`, and `timing` (numbers only) |