fix: Pause point timeout details carry the wait's timeout and the marker id, and busy vibe entries name the running tool and the resent requests

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

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

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 {

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) {

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)
 	}
 }
 

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".

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")
+		})
+	}
+}

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:<error data type>`, `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:<error data type>`, `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) |