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 4f3f6b490..154d59626 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 94b708051..c21fd4f1a 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/pause_point_errors.go b/cli/project-runner/internal/projectrunner/pause_point_errors.go index 5171eeb39..526239070 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 66497bc4f..826091bd6 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 707cd30bf..5517c31a5 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) } } diff --git a/cli/project-runner/internal/projectrunner/plain_tool_log.go b/cli/project-runner/internal/projectrunner/plain_tool_log.go index 761709238..42e434d51 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 6e951cb05..6424862e6 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 f9457370c..7dd248814 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) |