diff --git a/.agents/skills/uloop-compile/SKILL.md b/.agents/skills/uloop-compile/SKILL.md index 7263aadc28..537db387f7 100644 --- a/.agents/skills/uloop-compile/SKILL.md +++ b/.agents/skills/uloop-compile/SKILL.md @@ -57,7 +57,7 @@ Returns JSON: - `WarningCount`: number or null - `Warning` (string, optional): set when the compile was requested during Play Mode (the Play session is discarded), while pause points were armed in either Play Mode or Edit Mode (the domain reload drops every pause point patch; those enabled with `--persist` are counted separately and re-armed from their saved enable request after the reload), or while hot-reload changes were active (a successful compile drops every patch; the edited sources are compiled in). - `Message`: string -- `ErrorCode`: string or null. `COMPILE_ALREADY_IN_PROGRESS` when Unity is already compiling, `COMPILE_EDITOR_UPDATING` when the editor is updating, `COMPILE_RESULT_UNKNOWN` after a forced recompile that did not return a definitive result. +- `ErrorCode`: string or null. `COMPILE_ALREADY_IN_PROGRESS` / `COMPILE_EDITOR_UPDATING` when Unity was still compiling or updating after the CLI waited for it and sent the compile again (it does so twice before giving up; run `uloop compile` again), `COMPILE_RESULT_UNKNOWN` after a forced recompile that did not return a definitive result. - `NextActions`: string array or null. Corrective steps derived from the errors, e.g. the assembly that declares an unresolved namespace (CS0234), or, for CS0246 in a script under an asmdef, a reminder to check that asmdef's references (the type may instead be a typo — decide from the error). When Unity stops compiling before the finish callback (`Success: null`, indeterminate), `Message` keeps the get-logs pointer and appends `Recent Console errors:` with the last few Console errors (typically the asmdef or compiler error that aborted the compile), so fix from that list before reaching for `uloop get-logs`. diff --git a/.claude/skills/uloop-compile/SKILL.md b/.claude/skills/uloop-compile/SKILL.md index 7263aadc28..537db387f7 100644 --- a/.claude/skills/uloop-compile/SKILL.md +++ b/.claude/skills/uloop-compile/SKILL.md @@ -57,7 +57,7 @@ Returns JSON: - `WarningCount`: number or null - `Warning` (string, optional): set when the compile was requested during Play Mode (the Play session is discarded), while pause points were armed in either Play Mode or Edit Mode (the domain reload drops every pause point patch; those enabled with `--persist` are counted separately and re-armed from their saved enable request after the reload), or while hot-reload changes were active (a successful compile drops every patch; the edited sources are compiled in). - `Message`: string -- `ErrorCode`: string or null. `COMPILE_ALREADY_IN_PROGRESS` when Unity is already compiling, `COMPILE_EDITOR_UPDATING` when the editor is updating, `COMPILE_RESULT_UNKNOWN` after a forced recompile that did not return a definitive result. +- `ErrorCode`: string or null. `COMPILE_ALREADY_IN_PROGRESS` / `COMPILE_EDITOR_UPDATING` when Unity was still compiling or updating after the CLI waited for it and sent the compile again (it does so twice before giving up; run `uloop compile` again), `COMPILE_RESULT_UNKNOWN` after a forced recompile that did not return a definitive result. - `NextActions`: string array or null. Corrective steps derived from the errors, e.g. the assembly that declares an unresolved namespace (CS0234), or, for CS0246 in a script under an asmdef, a reminder to check that asmdef's references (the type may instead be a typo — decide from the error). When Unity stops compiling before the finish callback (`Success: null`, indeterminate), `Message` keeps the get-logs pointer and appends `Recent Console errors:` with the last few Console errors (typically the asmdef or compiler error that aborted the compile), so fix from that list before reaching for `uloop get-logs`. diff --git a/Packages/src/Editor/FirstPartyTools/Compile/Skill/SKILL.md b/Packages/src/Editor/FirstPartyTools/Compile/Skill/SKILL.md index 7263aadc28..537db387f7 100644 --- a/Packages/src/Editor/FirstPartyTools/Compile/Skill/SKILL.md +++ b/Packages/src/Editor/FirstPartyTools/Compile/Skill/SKILL.md @@ -57,7 +57,7 @@ Returns JSON: - `WarningCount`: number or null - `Warning` (string, optional): set when the compile was requested during Play Mode (the Play session is discarded), while pause points were armed in either Play Mode or Edit Mode (the domain reload drops every pause point patch; those enabled with `--persist` are counted separately and re-armed from their saved enable request after the reload), or while hot-reload changes were active (a successful compile drops every patch; the edited sources are compiled in). - `Message`: string -- `ErrorCode`: string or null. `COMPILE_ALREADY_IN_PROGRESS` when Unity is already compiling, `COMPILE_EDITOR_UPDATING` when the editor is updating, `COMPILE_RESULT_UNKNOWN` after a forced recompile that did not return a definitive result. +- `ErrorCode`: string or null. `COMPILE_ALREADY_IN_PROGRESS` / `COMPILE_EDITOR_UPDATING` when Unity was still compiling or updating after the CLI waited for it and sent the compile again (it does so twice before giving up; run `uloop compile` again), `COMPILE_RESULT_UNKNOWN` after a forced recompile that did not return a definitive result. - `NextActions`: string array or null. Corrective steps derived from the errors, e.g. the assembly that declares an unresolved namespace (CS0234), or, for CS0246 in a script under an asmdef, a reminder to check that asmdef's references (the type may instead be a typo — decide from the error). When Unity stops compiling before the finish callback (`Success: null`, indeterminate), `Message` keeps the get-logs pointer and appends `Recent Console errors:` with the last few Console errors (typically the asmdef or compiler error that aborted the compile), so fix from that list before reaching for `uloop get-logs`. diff --git a/cli/project-runner/internal/projectrunner/compile_fresh_recovery.go b/cli/project-runner/internal/projectrunner/compile_fresh_recovery.go new file mode 100644 index 0000000000..359e48de3b --- /dev/null +++ b/cli/project-runner/internal/projectrunner/compile_fresh_recovery.go @@ -0,0 +1,188 @@ +package projectrunner + +import ( + "context" + "encoding/json" + "errors" + "io" + "time" + + clierrors "github.com/hatayama/unity-cli-loop/common/errors" + "github.com/hatayama/unity-cli-loop/common/vibelog" + + "github.com/hatayama/unity-cli-loop/common/clicore" + "github.com/hatayama/unity-cli-loop/common/unityipc" +) + +const ( + // The first send and two resends. + freshCompileMaxAttempts = 3 + // Why: with less wait time left, a resent compile would start in Unity just as the command + // times out, which adds a compile and turns a rejection into a timeout. + compileResendMinimumBudget = 10 * time.Second +) + +var errCompileRequestMissing = errors.New("the compile request has no record in Unity") + +// freshCompileAttemptOutcome says how one fresh compile attempt ended, so the caller can decide +// whether to send the compile again. +type freshCompileAttemptOutcome int + +const ( + // The returned result is the command's result. + freshCompileAttemptFinal freshCompileAttemptOutcome = iota + // Unity lost the request, so sending it again is safe. + freshCompileAttemptRequestMissing + // Unity rejected the compile because it was compiling or updating, and the wait has seen it + // Ready since. + freshCompileAttemptEditorBusy +) + +// freshCompileAttemptOptions configures one fresh compile attempt. +type freshCompileAttemptOptions struct { + // Zero never reports RequestMissing or EditorBusy, which keeps the behavior of a compile that + // is never sent again. Otherwise they are reported only while at least + // compileResendMinimumBudget is left before this moment. + resendBefore time.Time + // Zero waits as long as --timeout-seconds says, for the first attempt and for entries that + // never send again. A positive value is this attempt's wait limit. + timeoutOverride time.Duration +} + +// runFreshCompileRecoveringWithDeps sends a fresh compile and sends it again when Unity lost the +// request or rejected it because it was still compiling or updating, at most +// freshCompileMaxAttempts sends in all within the one wait the caller asked for. +func runFreshCompileRecoveringWithDeps( + ctx context.Context, + connection unityipc.Connection, + params map[string]any, + stderr io.Writer, + compileWait compileWaitDeps, +) compileExecutionResult { + waitTimeout, err := compileWaitTimeoutFromParams(params) + if err != nil { + // The entry that never resends reports an invalid --timeout-seconds the way it always has. + return runFreshCompileWithDomainReloadWaitResultWithDeps(ctx, connection, params, stderr, compileWait) + } + resendBefore := time.Now().Add(waitTimeout) + options := freshCompileAttemptOptions{resendBefore: resendBefore} + for attempt := 1; ; attempt++ { + if attempt >= freshCompileMaxAttempts { + // Why: the last attempt behaves exactly like a compile that is never resent, so reaching + // the limit never makes a new kind of failure. + options.resendBefore = time.Time{} + } + result, outcome := runFreshCompileAttempt(ctx, connection, params, stderr, compileWait, options) + if outcome == freshCompileAttemptFinal { + return result + } + logCompileRequestResend(connection, params, outcome, attempt) + // Why a new request ID: Unity keeps the rejection it stored under the old one, and a status + // query with that ID would return it at once. + delete(params, compileRequestIDParam) + // Why positive: an attempt reports a resend only while canResendCompile holds. + options.timeoutOverride = time.Until(resendBefore) + } +} + +// compileRequestMissingTracker recognizes a request that Unity lost: Ready answers without a result +// that keep coming after Unity's server was recreated by a domain reload or a restart. +type compileRequestMissingTracker struct { + serverRestartSeen bool + missingStreak int +} + +// observe records one status query and reports whether the request is now known to be lost. +// Why a restart must be seen first: a request that reached Unity's main thread has a result by the +// first Ready answer after a domain reload, because Unity builds one from the pending request it +// registered there. So Ready answers without a result after the server was recreated come only +// from a request that never got there. Without a restart, a live request answers the same way for +// the seconds before its compile starts, and a resend then would be rejected by the single-flight +// slot the first request still holds. +func (tracker *compileRequestMissingTracker) observe(status compileStatusResponse, err error) bool { + if err != nil { + if isServerGoneError(err) { + tracker.serverRestartSeen = true + } + tracker.missingStreak = 0 + return false + } + if status.IsDomainReloadInProgress { + tracker.serverRestartSeen = true + } + if !status.Ready || status.HasResult { + tracker.missingStreak = 0 + return false + } + tracker.missingStreak++ + return tracker.serverRestartSeen && tracker.missingStreak >= compileAttachMissingResultStreak +} + +// isServerGoneError reports whether a failed status query shows that Unity's server went away: the +// connection dropped mid-query, or nobody was listening. +func isServerGoneError(err error) bool { + if clierrors.IsTransportDisconnectError(err) { + return true + } + var connectionErr *unityipc.ConnectionAttemptError + if !errors.As(err, &connectionErr) { + return false + } + // Why not a connect timeout or a denied connect: a Windows named pipe times out while all of its + // instances are busy, and a sandbox can deny the connect, both while the server is alive. + return !clierrors.IsFinalResponseTimeoutError(err) && !clierrors.IsPermanentConnectError(err) +} + +// canResendCompile reports whether at least compileResendMinimumBudget is left before resendBefore. +// A zero resendBefore never allows a resend. +func canResendCompile(resendBefore time.Time) bool { + return !resendBefore.IsZero() && time.Until(resendBefore) >= compileResendMinimumBudget +} + +type compileErrorCodeProbe struct { + ErrorCode string `json:"ErrorCode"` +} + +// isCompileEditorBusyRejection reports whether a compile result only says that Unity was still +// compiling or updating when the request arrived. +// Why ErrorCode only: the collision is a structured compile result, not a message string. +func isCompileEditorBusyRejection(raw []byte) bool { + var probe compileErrorCodeProbe + if json.Unmarshal(raw, &probe) != nil { + return false + } + return probe.ErrorCode == compileAlreadyInProgressErrorCode || + probe.ErrorCode == compileEditorUpdatingErrorCode +} + +func logCompileRequestResend( + connection unityipc.Connection, + params map[string]any, + outcome freshCompileAttemptOutcome, + attempt int, +) { + requestID, _ := params[compileRequestIDParam].(string) + writeCompileVibeLog(connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { + return vibelog.CLIVibeLogEntry{ + Level: "INFO", + Operation: "cli_compile_request_resend", + Message: "Sending the compile request again.", + Context: map[string]any{ + "command": clicore.CompileCommandName, + "request_id": requestID, + "reason": compileResendReason(outcome), + "attempt": attempt, + "project_identity": vibelog.ProjectIdentity(connection.ProjectRoot), + "endpoint": connection.Endpoint.Address, + }, + CorrelationID: requestID, + } + }) +} + +func compileResendReason(outcome freshCompileAttemptOutcome) string { + if outcome == freshCompileAttemptEditorBusy { + return "editor_busy" + } + return "request_missing" +} diff --git a/cli/project-runner/internal/projectrunner/compile_fresh_recovery_test.go b/cli/project-runner/internal/projectrunner/compile_fresh_recovery_test.go new file mode 100644 index 0000000000..937ee396ef --- /dev/null +++ b/cli/project-runner/internal/projectrunner/compile_fresh_recovery_test.go @@ -0,0 +1,648 @@ +package projectrunner + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "io" + "os" + "strings" + "testing" + "time" + + clierrors "github.com/hatayama/unity-cli-loop/common/errors" + + "github.com/hatayama/unity-cli-loop/common/unityipc" +) + +const ( + // Stops a wait that never ends instead of letting it poll through the whole default wait. + compileRecoveryQueryLimit = 200 + // A compile error: definitive, and it does not start the post-compile warmup. + compileRecoveryDefinitiveResult = `{"Success":false,"ErrorCount":1,"WarningCount":0,"ErrorCode":null}` + compileRecoveryAlreadyInProgressResult = `{"Success":false,"ErrorCode":"COMPILE_ALREADY_IN_PROGRESS","ErrorCount":1}` +) + +// compileRecoverySend is one scripted end of a compile send. +type compileRecoverySend struct { + outcome unityipc.UnitySendOutcome + err error +} + +// compileRecoveryAnswer is one scripted answer to a compile status query. +type compileRecoveryAnswer struct { + status compileStatusResponse + err error +} + +// compileRecoveryScenario scripts the compile sends in order and, for the request each send +// carried, the status answers in order. A request's last answer repeats once its script runs out. +type compileRecoveryScenario struct { + t *testing.T + sends []compileRecoverySend + answers [][]compileRecoveryAnswer + sentIDs []string + attemptOf map[string]int + nextAnswer map[string]int + queries map[string]int + totalQueries int + cancel context.CancelFunc + cancelAttempt int + cancelAtQuery int +} + +func newCompileRecoveryScenario( + t *testing.T, + sends []compileRecoverySend, + answers ...[]compileRecoveryAnswer, +) *compileRecoveryScenario { + t.Helper() + return &compileRecoveryScenario{ + t: t, + sends: sends, + answers: answers, + attemptOf: map[string]int{}, + nextAnswer: map[string]int{}, + queries: map[string]int{}, + } +} + +// cancelWhen cancels the command once the request of the given send (zero-based) has been queried +// queryCount times. +func (scenario *compileRecoveryScenario) cancelWhen(cancel context.CancelFunc, attempt int, queryCount int) { + scenario.cancel = cancel + scenario.cancelAttempt = attempt + scenario.cancelAtQuery = queryCount +} + +func (scenario *compileRecoveryScenario) deps() compileWaitDeps { + deps := compileWaitTestDeps(scenario.query) + deps.sendCompile = scenario.send + deps.freshWaitPollInterval = time.Millisecond + deps.startStallFocusThreshold = time.Hour + return deps +} + +func (scenario *compileRecoveryScenario) send( + _ context.Context, + _ unityipc.Connection, + _ string, + params map[string]any, + _ unityipc.ProgressFunc, + _ time.Duration, +) (unityipc.UnitySendOutcome, error) { + attempt := len(scenario.sentIDs) + if attempt >= len(scenario.sends) { + scenario.t.Fatalf("unexpected compile send #%d: the scenario allows %d", attempt+1, len(scenario.sends)) + } + requestID, _ := params[compileRequestIDParam].(string) + scenario.sentIDs = append(scenario.sentIDs, requestID) + scenario.attemptOf[requestID] = attempt + scenario.nextAnswer[requestID] = 0 + step := scenario.sends[attempt] + return step.outcome, step.err +} + +func (scenario *compileRecoveryScenario) query( + ctx context.Context, + _ unityipc.Connection, + requestID string, +) (compileStatusResponse, error) { + scenario.totalQueries++ + if scenario.totalQueries > compileRecoveryQueryLimit { + scenario.t.Fatalf("compile status was queried more than %d times: the wait never ended", compileRecoveryQueryLimit) + } + attempt, ok := scenario.attemptOf[requestID] + if !ok || attempt >= len(scenario.answers) { + scenario.t.Fatalf("compile status was queried for a request with no scripted answers: %q", requestID) + } + answers := scenario.answers[attempt] + index := scenario.nextAnswer[requestID] + if index < len(answers)-1 { + scenario.nextAnswer[requestID] = index + 1 + } + // Why count only before the cancellation: the wait may poll once more after it, because its + // select picks at random when the poll tick and the cancellation are both ready. + if ctx.Err() == nil { + scenario.queries[requestID]++ + if scenario.cancel != nil && attempt == scenario.cancelAttempt && scenario.queries[requestID] == scenario.cancelAtQuery { + scenario.cancel() + } + } + answer := answers[index] + return answer.status, answer.err +} + +func (scenario *compileRecoveryScenario) sendCount() int { + return len(scenario.sentIDs) +} + +// queriesOf returns how often the request of the given send was queried before any cancellation. +func (scenario *compileRecoveryScenario) queriesOf(attempt int) int { + return scenario.queries[scenario.sentIDs[attempt]] +} + +func compileRecoveryAcceptedOutcome() unityipc.UnitySendOutcome { + return unityipc.UnitySendOutcome{RequestDispatched: true, RequestAccepted: true} +} + +// recoverySendDisconnected is a send that Unity accepted before the connection dropped. +func recoverySendDisconnected() compileRecoverySend { + return compileRecoverySend{outcome: compileRecoveryAcceptedOutcome(), err: io.EOF} +} + +// recoverySendTimedOut is a send that Unity accepted without a final response in time. +func recoverySendTimedOut(t *testing.T) compileRecoverySend { + t.Helper() + if !clierrors.IsFinalResponseTimeoutError(os.ErrDeadlineExceeded) { + t.Fatal("os.ErrDeadlineExceeded must classify as a final response timeout") + } + return compileRecoverySend{outcome: compileRecoveryAcceptedOutcome(), err: os.ErrDeadlineExceeded} +} + +// recoverySendAnswered is a send that received Unity's final response. +func recoverySendAnswered() compileRecoverySend { + return compileRecoverySend{outcome: compileRecoveryAcceptedOutcome()} +} + +// recoveryMissing is Unity Ready with no result for the request. +func recoveryMissing() compileRecoveryAnswer { + return compileRecoveryAnswer{status: compileStatusResponse{Ready: true}} +} + +func recoveryMissingTimes(count int) []compileRecoveryAnswer { + answers := make([]compileRecoveryAnswer, 0, count) + for range count { + answers = append(answers, recoveryMissing()) + } + return answers +} + +func recoveryDone(result string) compileRecoveryAnswer { + return compileRecoveryAnswer{status: compileStatusResponse{Ready: true, HasResult: true, Result: json.RawMessage(result)}} +} + +func recoveryCompiling() compileRecoveryAnswer { + return compileRecoveryAnswer{status: compileStatusResponse{IsCompiling: true}} +} + +func recoveryQueryFailure(err error) compileRecoveryAnswer { + return compileRecoveryAnswer{err: err} +} + +func compileRecoveryRejection(errorCode string) string { + return `{"Success":false,"ErrorCode":"` + errorCode + `","ErrorCount":1}` +} + +// compileRecoveryBusyRejectionAnswers is Unity storing a busy rejection while it still compiles, +// then turning Ready. +func compileRecoveryBusyRejectionAnswers(errorCode string) []compileRecoveryAnswer { + return []compileRecoveryAnswer{ + {status: compileStatusResponse{HasResult: true, IsCompiling: true, Result: json.RawMessage(compileRecoveryRejection(errorCode))}}, + recoveryDone(compileRecoveryRejection(errorCode)), + } +} + +// runCompileRecovery runs the resending entry against the scenario. +func runCompileRecovery( + t *testing.T, + ctx context.Context, + scenario *compileRecoveryScenario, + params map[string]any, +) (compileExecutionResult, string) { + t.Helper() + var stderr bytes.Buffer + result := runFreshCompileRecoveringWithDeps(ctx, unreachableConnection(t.TempDir()), params, &stderr, scenario.deps()) + return result, stderr.String() +} + +func vibeLogContextNumber(t *testing.T, entry map[string]any, key string) float64 { + t.Helper() + contextMap, ok := entry["context"].(map[string]any) + if !ok { + t.Fatalf("vibe log context missing: %#v", entry) + } + value, ok := contextMap[key].(float64) + if !ok { + t.Fatalf("vibe log context %s is not a number: %#v", key, contextMap[key]) + } + return value +} + +// compileResendLogEntry returns the only resend entry in the project's CLI vibe log. +func compileResendLogEntry(t *testing.T, projectRoot string) map[string]any { + t.Helper() + entries := cliVibeEntriesForOperation(t, readOnlyCliVibeLog(t, projectRoot), "cli_compile_request_resend") + if len(entries) != 1 { + t.Fatalf("compile resend log entries = %d, want 1", len(entries)) + } + return entries[0] +} + +// Verifies a request Unity lost across a server restart is sent again with a new request ID after +// three Ready answers without a result, instead of waiting out the whole timeout, and that the +// resend is logged as a lost request under the first request's ID. +func TestFreshCompileRecoveryResendsWhenUnityLostTheRequest(t *testing.T) { + enableCliVibeLog(t) + scenario := newCompileRecoveryScenario(t, + []compileRecoverySend{recoverySendDisconnected(), recoverySendAnswered()}, + []compileRecoveryAnswer{recoveryMissing()}, + []compileRecoveryAnswer{recoveryDone(compileRecoveryDefinitiveResult)}, + ) + projectRoot := t.TempDir() + var stderrBuffer bytes.Buffer + + result := runFreshCompileRecoveringWithDeps(context.Background(), unreachableConnection(projectRoot), map[string]any{}, &stderrBuffer, scenario.deps()) + stderr := stderrBuffer.String() + + if scenario.sendCount() != 2 { + t.Fatalf("compile sends = %d, want 2", scenario.sendCount()) + } + if scenario.sentIDs[0] == scenario.sentIDs[1] { + t.Fatalf("the resent compile must carry a new request ID: %q", scenario.sentIDs[0]) + } + if string(result.result) != compileRecoveryDefinitiveResult { + t.Fatalf("result = %s, want the resent compile's result", result.result) + } + if strings.Contains(stderr, "COMPILE_WAIT_TIMEOUT") { + t.Fatalf("a resent compile must not report a wait timeout:\n%s", stderr) + } + if queries := scenario.queriesOf(0); queries != 3 { + t.Fatalf("queries for the lost request = %d, want 3", queries) + } + resend := compileResendLogEntry(t, projectRoot) + if reason := vibeLogContextString(t, resend, "reason"); reason != "request_missing" { + t.Fatalf("resend reason = %q, want request_missing", reason) + } + if attempt := vibeLogContextNumber(t, resend, "attempt"); attempt != 1 { + t.Fatalf("resend attempt = %v, want 1", attempt) + } + if requestID := vibeLogContextString(t, resend, "request_id"); requestID != scenario.sentIDs[0] { + t.Fatalf("resend request_id = %q, want the lost request's ID %q", requestID, scenario.sentIDs[0]) + } +} + +// Verifies a status query that finds the server gone, dropped mid-query or with nobody listening, +// counts as a server restart, so a request still missing afterwards is sent again. +func TestFreshCompileRecoveryResendsWhenAStatusQueryLosesTheServer(t *testing.T) { + cases := []struct { + name string + queryErr error + }{ + {name: "dropped mid-query", queryErr: io.EOF}, + {name: "nobody listening", queryErr: &unityipc.ConnectionAttemptError{Cause: errors.New("connect: connection refused")}}, + } + for _, testCase := range cases { + t.Run(testCase.name, func(t *testing.T) { + scenario := newCompileRecoveryScenario(t, + []compileRecoverySend{recoverySendTimedOut(t), recoverySendAnswered()}, + append([]compileRecoveryAnswer{recoveryQueryFailure(testCase.queryErr)}, recoveryMissingTimes(3)...), + []compileRecoveryAnswer{recoveryDone(compileRecoveryDefinitiveResult)}, + ) + + result, _ := runCompileRecovery(t, context.Background(), scenario, map[string]any{}) + + if scenario.sendCount() != 2 { + t.Fatalf("compile sends = %d, want 2", scenario.sendCount()) + } + if string(result.result) != compileRecoveryDefinitiveResult { + t.Fatalf("result = %s, want the resent compile's result", result.result) + } + }) + } +} + +// Verifies an answer that reports a domain reload in progress counts as a server restart, so a +// request still missing afterwards is sent again. +func TestFreshCompileRecoveryResendsAfterSeeingTheDomainReloadFlag(t *testing.T) { + scenario := newCompileRecoveryScenario(t, + []compileRecoverySend{recoverySendTimedOut(t), recoverySendAnswered()}, + append( + []compileRecoveryAnswer{{status: compileStatusResponse{IsDomainReloadInProgress: true}}}, + recoveryMissingTimes(3)..., + ), + []compileRecoveryAnswer{recoveryDone(compileRecoveryDefinitiveResult)}, + ) + + result, _ := runCompileRecovery(t, context.Background(), scenario, map[string]any{}) + + if scenario.sendCount() != 2 { + t.Fatalf("compile sends = %d, want 2", scenario.sendCount()) + } + if string(result.result) != compileRecoveryDefinitiveResult { + t.Fatalf("result = %s, want the resent compile's result", result.result) + } +} + +// Verifies Ready answers without a result never lead to a resend when nothing showed the server +// went away: a live request answers that way until its compile starts, and a resend then would be +// rejected as busy. +func TestFreshCompileRecoveryKeepsWaitingWhenTheServerWasNeverLost(t *testing.T) { + cases := []struct { + name string + firstAnswers []compileRecoveryAnswer + }{ + {name: "no failed query"}, + { + name: "query acknowledged but unanswered", + firstAnswers: []compileRecoveryAnswer{recoveryQueryFailure(&compileStatusUnansweredError{cause: os.ErrDeadlineExceeded})}, + }, + { + name: "other query error", + firstAnswers: []compileRecoveryAnswer{recoveryQueryFailure(errors.New("unity error: boom"))}, + }, + { + name: "connect timed out", + firstAnswers: []compileRecoveryAnswer{recoveryQueryFailure(&unityipc.ConnectionAttemptError{Cause: context.DeadlineExceeded})}, + }, + { + name: "connect denied", + firstAnswers: []compileRecoveryAnswer{recoveryQueryFailure(&unityipc.ConnectionAttemptError{Cause: os.ErrPermission})}, + }, + } + for _, testCase := range cases { + t.Run(testCase.name, func(t *testing.T) { + script := append([]compileRecoveryAnswer{}, testCase.firstAnswers...) + script = append(script, recoveryMissingTimes(6)...) + script = append(script, recoveryDone(compileRecoveryDefinitiveResult)) + scenario := newCompileRecoveryScenario(t, []compileRecoverySend{recoverySendTimedOut(t)}, script) + + result, _ := runCompileRecovery(t, context.Background(), scenario, map[string]any{}) + + if scenario.sendCount() != 1 { + t.Fatalf("compile sends = %d, want 1", scenario.sendCount()) + } + if string(result.result) != compileRecoveryDefinitiveResult { + t.Fatalf("result = %s, want the compile's result", result.result) + } + }) + } +} + +// Verifies two Ready answers without a result are not enough for a resend: a single such answer +// can race Unity storing the result. +func TestFreshCompileRecoveryDoesNotResendBeforeThreeMissingAnswers(t *testing.T) { + scenario := newCompileRecoveryScenario(t, + []compileRecoverySend{recoverySendDisconnected()}, + append(recoveryMissingTimes(2), recoveryDone(compileRecoveryDefinitiveResult)), + ) + + result, _ := runCompileRecovery(t, context.Background(), scenario, map[string]any{}) + + if scenario.sendCount() != 1 { + t.Fatalf("compile sends = %d, want 1", scenario.sendCount()) + } + if string(result.result) != compileRecoveryDefinitiveResult { + t.Fatalf("result = %s, want the compile's result", result.result) + } +} + +// Verifies a compiling answer between Ready answers without a result restarts their count. +func TestFreshCompileRecoveryMissingStreakRestartsAfterABusyAnswer(t *testing.T) { + script := recoveryMissingTimes(2) + script = append(script, recoveryCompiling()) + script = append(script, recoveryMissingTimes(2)...) + script = append(script, recoveryDone(compileRecoveryDefinitiveResult)) + scenario := newCompileRecoveryScenario(t, []compileRecoverySend{recoverySendDisconnected()}, script) + + result, _ := runCompileRecovery(t, context.Background(), scenario, map[string]any{}) + + if scenario.sendCount() != 1 { + t.Fatalf("compile sends = %d, want 1", scenario.sendCount()) + } + if string(result.result) != compileRecoveryDefinitiveResult { + t.Fatalf("result = %s, want the compile's result", result.result) + } +} + +// Verifies a compile Unity rejected because it was compiling or updating is sent again with a new +// request ID once the wait has seen the Editor Ready. +func TestFreshCompileRecoveryResendsAfterUnityRejectedTheCompileAsBusy(t *testing.T) { + for _, errorCode := range []string{"COMPILE_ALREADY_IN_PROGRESS", "COMPILE_EDITOR_UPDATING"} { + t.Run(errorCode, func(t *testing.T) { + scenario := newCompileRecoveryScenario(t, + []compileRecoverySend{recoverySendAnswered(), recoverySendAnswered()}, + compileRecoveryBusyRejectionAnswers(errorCode), + []compileRecoveryAnswer{recoveryDone(compileRecoveryDefinitiveResult)}, + ) + + result, _ := runCompileRecovery(t, context.Background(), scenario, map[string]any{}) + + if scenario.sendCount() != 2 { + t.Fatalf("compile sends = %d, want 2", scenario.sendCount()) + } + if scenario.sentIDs[0] == scenario.sentIDs[1] { + t.Fatalf("the resent compile must carry a new request ID: %q", scenario.sentIDs[0]) + } + if string(result.result) != compileRecoveryDefinitiveResult { + t.Fatalf("result = %s, want the resent compile's result", result.result) + } + }) + } +} + +// Verifies a definitive compile failure is returned as it is, without a resend. +func TestFreshCompileRecoveryReturnsADefinitiveFailureWithoutResending(t *testing.T) { + scenario := newCompileRecoveryScenario(t, + []compileRecoverySend{recoverySendAnswered()}, + []compileRecoveryAnswer{recoveryDone(compileRecoveryDefinitiveResult)}, + ) + + result, _ := runCompileRecovery(t, context.Background(), scenario, map[string]any{}) + + if scenario.sendCount() != 1 { + t.Fatalf("compile sends = %d, want 1", scenario.sendCount()) + } + if string(result.result) != compileRecoveryDefinitiveResult { + t.Fatalf("result = %s, want the compile's result", result.result) + } +} + +// Verifies a compile rejected as busy on every attempt is sent three times in all, and the last +// rejection is returned the way a rejection is returned without resending. +func TestFreshCompileRecoveryReturnsTheRejectionAfterTheAttemptLimit(t *testing.T) { + rejected := []compileRecoveryAnswer{recoveryDone(compileRecoveryAlreadyInProgressResult)} + scenario := newCompileRecoveryScenario(t, + []compileRecoverySend{recoverySendAnswered(), recoverySendAnswered(), recoverySendAnswered()}, + rejected, rejected, rejected, + ) + + result, _ := runCompileRecovery(t, context.Background(), scenario, map[string]any{}) + + if scenario.sendCount() != 3 { + t.Fatalf("compile sends = %d, want 3", scenario.sendCount()) + } + if string(result.result) != compileRecoveryAlreadyInProgressResult { + t.Fatalf("result = %s, want the last rejection", result.result) + } + if result.exitCode != 1 { + t.Fatalf("exit code = %d, want 1", result.exitCode) + } +} + +// Verifies the last attempt neither detects a lost request nor sends it again: it keeps waiting the +// way a compile that is never resent does, until the command ends. +func TestFreshCompileRecoveryStopsDetectingOnTheLastAttempt(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + missing := []compileRecoveryAnswer{recoveryMissing()} + scenario := newCompileRecoveryScenario(t, + []compileRecoverySend{recoverySendDisconnected(), recoverySendDisconnected(), recoverySendDisconnected()}, + missing, missing, missing, + ) + scenario.cancelWhen(cancel, 2, 6) + + result, stderr := runCompileRecovery(t, ctx, scenario, map[string]any{}) + + if scenario.sendCount() != 3 { + t.Fatalf("compile sends = %d, want 3", scenario.sendCount()) + } + if result.exitCode != 1 || len(result.result) != 0 { + t.Fatalf("unexpected result: %#v", result) + } + if !strings.Contains(stderr, context.Canceled.Error()) { + t.Fatalf("stderr must report the cancellation:\n%s", stderr) + } +} + +// Verifies the entry that never resends, used by pause-point recovery, keeps waiting for a lost +// request until the command ends instead of resending it or returning without a result. +func TestFreshCompileWithoutRecoveryDoesNotResend(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + scenario := newCompileRecoveryScenario(t, + []compileRecoverySend{recoverySendDisconnected()}, + []compileRecoveryAnswer{recoveryMissing()}, + ) + scenario.cancelWhen(cancel, 0, 6) + var stderr bytes.Buffer + + result := runFreshCompileWithDomainReloadWaitResultWithDeps( + ctx, unreachableConnection(t.TempDir()), map[string]any{}, &stderr, scenario.deps()) + + if scenario.sendCount() != 1 { + t.Fatalf("compile sends = %d, want 1", scenario.sendCount()) + } + if result.exitCode != 1 || len(result.result) != 0 { + t.Fatalf("unexpected result: %#v", result) + } + if !strings.Contains(stderr.String(), context.Canceled.Error()) { + t.Fatalf("stderr must report the cancellation:\n%s", stderr.String()) + } + if queries := scenario.queriesOf(0); queries != 6 { + t.Fatalf("queries for the lost request = %d, want 6", queries) + } +} + +// Verifies the hot-reload compile fallback also sends a compile rejected as busy again. +func TestHotReloadFallbackCompileResendsAfterABusyRejection(t *testing.T) { + scenario := newCompileRecoveryScenario(t, + []compileRecoverySend{recoverySendAnswered(), recoverySendAnswered()}, + compileRecoveryBusyRejectionAnswers("COMPILE_ALREADY_IN_PROGRESS"), + []compileRecoveryAnswer{recoveryDone(compileRecoveryDefinitiveResult)}, + ) + var stderr bytes.Buffer + + result := hotReloadFallbackCompileWithDeps(context.Background(), unreachableConnection(t.TempDir()), &stderr, scenario.deps()) + + if scenario.sendCount() != 2 { + t.Fatalf("compile sends = %d, want 2", scenario.sendCount()) + } + if string(result.result) != compileRecoveryDefinitiveResult { + t.Fatalf("result = %s, want the resent compile's result", result.result) + } +} + +// Verifies a busy rejection is returned as it is when too little wait time is left for another +// attempt: a resent compile would start in Unity just as the command times out. +func TestFreshCompileRecoveryDoesNotResendARejectionWhenLittleWaitTimeIsLeft(t *testing.T) { + scenario := newCompileRecoveryScenario(t, + []compileRecoverySend{recoverySendAnswered()}, + []compileRecoveryAnswer{recoveryDone(compileRecoveryAlreadyInProgressResult)}, + ) + + result, _ := runCompileRecovery(t, context.Background(), scenario, map[string]any{compileWaitTimeoutParam: 5}) + + if scenario.sendCount() != 1 { + t.Fatalf("compile sends = %d, want 1", scenario.sendCount()) + } + if string(result.result) != compileRecoveryAlreadyInProgressResult { + t.Fatalf("result = %s, want the rejection", result.result) + } + if result.exitCode != 1 { + t.Fatalf("exit code = %d, want 1", result.exitCode) + } +} + +// Verifies a lost request is not sent again when too little wait time is left for another attempt; +// the wait goes on the way it does without resending. +func TestFreshCompileRecoveryKeepsWaitingForALostRequestWhenLittleWaitTimeIsLeft(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + scenario := newCompileRecoveryScenario(t, + []compileRecoverySend{recoverySendDisconnected()}, + []compileRecoveryAnswer{recoveryMissing()}, + ) + scenario.cancelWhen(cancel, 0, 6) + + result, stderr := runCompileRecovery(t, ctx, scenario, map[string]any{compileWaitTimeoutParam: 5}) + + if scenario.sendCount() != 1 { + t.Fatalf("compile sends = %d, want 1", scenario.sendCount()) + } + if result.exitCode != 1 { + t.Fatalf("exit code = %d, want 1", result.exitCode) + } + if !strings.Contains(stderr, context.Canceled.Error()) { + t.Fatalf("stderr must report the cancellation:\n%s", stderr) + } +} + +// Verifies the first attempt waits exactly as long as --timeout-seconds says, while a resent +// compile waits only for the time that is left, and that the resend after a busy rejection is +// logged as one. +func TestFreshCompileRecoveryGivesAResendOnlyTheTimeThatIsLeft(t *testing.T) { + enableCliVibeLog(t) + scenario := newCompileRecoveryScenario(t, + []compileRecoverySend{recoverySendAnswered(), recoverySendAnswered()}, + compileRecoveryBusyRejectionAnswers("COMPILE_ALREADY_IN_PROGRESS"), + []compileRecoveryAnswer{recoveryDone(compileRecoveryDefinitiveResult)}, + ) + projectRoot := t.TempDir() + var stderr bytes.Buffer + + runFreshCompileRecoveringWithDeps(context.Background(), unreachableConnection(projectRoot), map[string]any{}, &stderr, scenario.deps()) + + prepared := cliVibeEntriesForOperation(t, readOnlyCliVibeLog(t, projectRoot), "cli_compile_request_prepared") + if len(prepared) != 2 { + t.Fatalf("prepared compile requests = %d, want 2", len(prepared)) + } + if first := vibeLogContextNumber(t, prepared[0], "timeout_ms"); first != 600000 { + t.Fatalf("first attempt timeout_ms = %v, want 600000", first) + } + if second := vibeLogContextNumber(t, prepared[1], "timeout_ms"); second >= 600000 { + t.Fatalf("resent attempt timeout_ms = %v, want less than 600000", second) + } + resend := compileResendLogEntry(t, projectRoot) + if reason := vibeLogContextString(t, resend, "reason"); reason != "editor_busy" { + t.Fatalf("resend reason = %q, want editor_busy", reason) + } +} + +// Verifies a status query against an endpoint nobody listens on fails with an error that counts as +// the server being gone, so the scripted connection failure above matches what the real query +// returns. +func TestStatusQueryAgainstNoListenerCountsAsTheServerBeingGone(t *testing.T) { + _, err := queryCompileStatusFromUnity(context.Background(), unreachableConnection(t.TempDir()), "request") + + if err == nil { + t.Fatal("a status query against an endpoint nobody listens on must fail") + } + if errors.Is(err, os.ErrPermission) { + t.Skipf("the environment denied the connection itself, so it cannot show a missing listener: %v", err) + } + if !isServerGoneError(err) { + t.Fatalf("a status query with no listener must count as the server being gone: %v", err) + } +} diff --git a/cli/project-runner/internal/projectrunner/compile_wait.go b/cli/project-runner/internal/projectrunner/compile_wait.go index 55f44fa197..5a587909c4 100644 --- a/cli/project-runner/internal/projectrunner/compile_wait.go +++ b/cli/project-runner/internal/projectrunner/compile_wait.go @@ -54,6 +54,11 @@ type compileCompletionOptions struct { untilEditorReady bool timeout time.Duration pollInterval time.Duration + // resendBefore, when not zero, lets a fresh compile's wait end with errCompileRequestMissing + // once the request is known to be lost and enough time is left to send it again. + resendBefore time.Time + // serverRestartSeen says the compile send already ended with the connection dropping. + serverRestartSeen bool } type compileStatusResponse struct { @@ -204,6 +209,7 @@ func waitForCompileCompletionWithDeps( logCompileStatusPollStart(options, startedAt, deadline) interim := newCompileWaitInterimState(compileWaitNow(deps)) + missing := compileRequestMissingTracker{serverRestartSeen: options.serverRestartSeen} ticker := time.NewTicker(options.pollInterval) defer ticker.Stop() @@ -226,6 +232,10 @@ func waitForCompileCompletionWithDeps( lastStatus = status observedStatus = true } + if missing.observe(status, err) && canResendCompile(options.resendBefore) { + logCompileStatusPollObservedIfChanged(options, startedAt, attempts, status, err, &lastObservationKey) + return nil, false, lastObservedCompileStatus(lastStatus, observedStatus), errCompileRequestMissing + } logCompileStatusPollObservedIfChanged(options, startedAt, attempts, status, err, &lastObservationKey) observeCompileWaitInterim(&interim, deps, status, err) // Why: queryCompileStatus can return after the wait deadline. Focusing then diff --git a/cli/project-runner/internal/projectrunner/compile_wait_deps.go b/cli/project-runner/internal/projectrunner/compile_wait_deps.go index 8882e19919..b63f259aa6 100644 --- a/cli/project-runner/internal/projectrunner/compile_wait_deps.go +++ b/cli/project-runner/internal/projectrunner/compile_wait_deps.go @@ -27,7 +27,10 @@ type compileWaitDeps struct { reportInterim compileWaitInterimReporter // Zero keeps compileStartStallFocusThreshold. Tests shorten it so they do not wait 10s. startStallFocusThreshold time.Duration - focus connectionRetryDeps + // Zero keeps compileWaitPollInterval for a fresh compile's status wait. Tests shorten it so + // they do not wait 1s between status queries. + freshWaitPollInterval time.Duration + focus connectionRetryDeps } func compileStartStallFocusThresholdFor(deps compileWaitDeps) time.Duration { @@ -37,6 +40,13 @@ func compileStartStallFocusThresholdFor(deps compileWaitDeps) time.Duration { return compileStartStallFocusThreshold } +func freshWaitPollIntervalFor(deps compileWaitDeps) time.Duration { + if deps.freshWaitPollInterval > 0 { + return deps.freshWaitPollInterval + } + return compileWaitPollInterval +} + func compileWaitFocusDeps(deps compileWaitDeps) connectionRetryDeps { merged := defaultConnectionRetryDeps() if deps.focus.findRunningUnityProcess != nil { diff --git a/cli/project-runner/internal/projectrunner/pause_point_release_recovery.go b/cli/project-runner/internal/projectrunner/pause_point_release_recovery.go index 0d74735fce..31195146c9 100644 --- a/cli/project-runner/internal/projectrunner/pause_point_release_recovery.go +++ b/cli/project-runner/internal/projectrunner/pause_point_release_recovery.go @@ -189,20 +189,6 @@ func sendCompileWithBusyRetry( } } -type compileErrorCodeProbe struct { - ErrorCode string `json:"ErrorCode"` -} - -// Why ErrorCode only: the collision is a structured compile result, not a message string. -func isRetryablePausePointRecoveryCompileResult(raw []byte) bool { - var probe compileErrorCodeProbe - if json.Unmarshal(raw, &probe) != nil { - return false - } - return probe.ErrorCode == compileAlreadyInProgressErrorCode || - probe.ErrorCode == compileEditorUpdatingErrorCode -} - func runOneFreshCompileForPausePointRecoveryDefault( ctx context.Context, connection unityipc.Connection, @@ -256,7 +242,7 @@ func runFreshCompileWithBusyRetryForPausePointRecovery( if code == 0 { return 0 } - if !isRetryablePausePointRecoveryCompileResult(attemptOut.Bytes()) { + if !isCompileEditorBusyRejection(attemptOut.Bytes()) { _, _ = stdout.Write(attemptOut.Bytes()) return code } diff --git a/cli/project-runner/internal/projectrunner/run.go b/cli/project-runner/internal/projectrunner/run.go index caff9d7d91..f01f09d601 100644 --- a/cli/project-runner/internal/projectrunner/run.go +++ b/cli/project-runner/internal/projectrunner/run.go @@ -3,6 +3,7 @@ package projectrunner import ( "context" "encoding/json" + "errors" "fmt" "io" "os" @@ -263,7 +264,7 @@ func runCompileWithReattachPolicy( return result } - return runFreshCompileWithDomainReloadWaitResultWithDeps(ctx, connection, params, stderr, compileWait) + return runFreshCompileRecoveringWithDeps(ctx, connection, params, stderr, compileWait) } func runFreshCompileWithDomainReloadWaitWithDeps( @@ -285,13 +286,31 @@ func runFreshCompileWithDomainReloadWaitResultWithDeps( stderr io.Writer, compileWait compileWaitDeps, ) compileExecutionResult { + result, _ := runFreshCompileAttempt(ctx, connection, params, stderr, compileWait, freshCompileAttemptOptions{}) + return result +} + +// runFreshCompileAttempt sends one compile request and waits for Unity to report its result. +func runFreshCompileAttempt( + ctx context.Context, + connection unityipc.Connection, + params map[string]any, + stderr io.Writer, + compileWait compileWaitDeps, + options freshCompileAttemptOptions, +) (compileExecutionResult, freshCompileAttemptOutcome) { waitTimeout, timeoutErr := compileWaitTimeoutFromParams(params) if timeoutErr != nil { clierrors.WriteClassifiedError(stderr, timeoutErr, clierrors.ErrorContext{ ProjectRoot: connection.ProjectRoot, Command: clicore.CompileCommandName, }) - return compileExecutionResult{exitCode: 1} + return compileExecutionResult{exitCode: 1}, freshCompileAttemptFinal + } + // Why only a resent attempt: the first one keeps the exact --timeout-seconds wait, which its log + // entry and its timeout message report. + if options.timeoutOverride > 0 { + waitTimeout = options.timeoutOverride } requestID, err := prepareCompileWaitParams(params) @@ -300,7 +319,7 @@ func runFreshCompileWithDomainReloadWaitResultWithDeps( ProjectRoot: connection.ProjectRoot, Command: clicore.CompileCommandName, }) - return compileExecutionResult{exitCode: 1} + return compileExecutionResult{exitCode: 1}, freshCompileAttemptFinal } logCliDebugModeResolved(connection, clicore.CompileCommandName) @@ -326,7 +345,7 @@ func runFreshCompileWithDomainReloadWaitResultWithDeps( ProjectRoot: connection.ProjectRoot, Command: clicore.CompileCommandName, }) - return compileExecutionResult{exitCode: 1} + return compileExecutionResult{exitCode: 1}, freshCompileAttemptFinal } spinner.Update("Waiting for domain reload to complete...") @@ -337,15 +356,23 @@ func runFreshCompileWithDomainReloadWaitResultWithDeps( requestID: requestID, forceRecompile: compileForceRecompileEnabled(params), timeout: waitTimeout, - pollInterval: compileWaitPollInterval, + pollInterval: freshWaitPollIntervalFor(compileWait), + resendBefore: options.resendBefore, + // Only a dispatched send reaches this wait, so a dropped connection here came after the + // request was sent. + serverRestartSeen: err != nil && clierrors.IsTransportDisconnectError(err), }, compileWait) + if errors.Is(waitErr, errCompileRequestMissing) { + spinner.Stop() + return compileExecutionResult{}, freshCompileAttemptRequestMissing + } if waitErr != nil { spinner.Stop() clierrors.WriteClassifiedError(stderr, waitErr, clierrors.ErrorContext{ ProjectRoot: connection.ProjectRoot, Command: clicore.CompileCommandName, }) - return compileExecutionResult{exitCode: 1} + return compileExecutionResult{exitCode: 1}, freshCompileAttemptFinal } if !completed { spinner.Stop() @@ -357,9 +384,13 @@ func runFreshCompileWithDomainReloadWaitResultWithDeps( time.Since(waitStartedAt), compilePendingRecordLifetime-waitTimeout, )) - return compileExecutionResult{exitCode: 1} + return compileExecutionResult{exitCode: 1}, freshCompileAttemptFinal + } + if canResendCompile(options.resendBefore) && isCompileEditorBusyRejection(result) { + spinner.Stop() + return compileExecutionResult{}, freshCompileAttemptEditorBusy } - return completeCompileResult(ctx, connection, result, stderr, spinner, startedAt, outcome) + return completeCompileResult(ctx, connection, result, stderr, spinner, startedAt, outcome), freshCompileAttemptFinal } func writePostCompileWarmupWarning(stderr io.Writer, err error) {