diff --git a/.agents/skills/uloop-compile/SKILL.md b/.agents/skills/uloop-compile/SKILL.md index 3febf89300..265987c4c7 100644 --- a/.agents/skills/uloop-compile/SKILL.md +++ b/.agents/skills/uloop-compile/SKILL.md @@ -11,7 +11,7 @@ Execute Unity project compilation. ## Usage ```bash -uloop compile [--force-recompile] [--no-wait-for-domain-reload] [--stop-on-external-scene-changes] +uloop compile [--force-recompile] [--no-wait-for-domain-reload] [--stop-on-external-scene-changes] [--compile-wait-timeout-seconds ] ``` ## Parameters @@ -21,6 +21,7 @@ uloop compile [--force-recompile] [--no-wait-for-domain-reload] [--stop-on-exter | `--force-recompile` | flag | - | Full recompile plus domain reload. Almost never needed: a plain compile already detects externally edited files, and the forced reload can freeze large projects and come back as `COMPILE_RESULT_UNKNOWN`. | | `--no-wait-for-domain-reload` | flag | - | Return before Domain Reload completion | | `--stop-on-external-scene-changes` | flag | - | Stop before compilation if open Scene files changed externally instead of auto-reloading them | +| `--compile-wait-timeout-seconds` | integer | 600 | Maximum seconds the CLI waits for the compile to finish before returning COMPILE_WAIT_TIMEOUT (default 600). Values above 1200 exceed the Unity-side result retention window (20 minutes) and weaken post-timeout recovery. | ## When to use --force-recompile diff --git a/.claude/skills/uloop-compile/SKILL.md b/.claude/skills/uloop-compile/SKILL.md index 3febf89300..265987c4c7 100644 --- a/.claude/skills/uloop-compile/SKILL.md +++ b/.claude/skills/uloop-compile/SKILL.md @@ -11,7 +11,7 @@ Execute Unity project compilation. ## Usage ```bash -uloop compile [--force-recompile] [--no-wait-for-domain-reload] [--stop-on-external-scene-changes] +uloop compile [--force-recompile] [--no-wait-for-domain-reload] [--stop-on-external-scene-changes] [--compile-wait-timeout-seconds ] ``` ## Parameters @@ -21,6 +21,7 @@ uloop compile [--force-recompile] [--no-wait-for-domain-reload] [--stop-on-exter | `--force-recompile` | flag | - | Full recompile plus domain reload. Almost never needed: a plain compile already detects externally edited files, and the forced reload can freeze large projects and come back as `COMPILE_RESULT_UNKNOWN`. | | `--no-wait-for-domain-reload` | flag | - | Return before Domain Reload completion | | `--stop-on-external-scene-changes` | flag | - | Stop before compilation if open Scene files changed externally instead of auto-reloading them | +| `--compile-wait-timeout-seconds` | integer | 600 | Maximum seconds the CLI waits for the compile to finish before returning COMPILE_WAIT_TIMEOUT (default 600). Values above 1200 exceed the Unity-side result retention window (20 minutes) and weaken post-timeout recovery. | ## When to use --force-recompile diff --git a/.github/workflows/dead-code.yml b/.github/workflows/dead-code.yml index 2595aea67f..723737ce3b 100644 --- a/.github/workflows/dead-code.yml +++ b/.github/workflows/dead-code.yml @@ -45,4 +45,4 @@ jobs: --include-kept false --format table --fail-on high-confidence - --max-public-candidates 22 + --max-public-candidates 23 diff --git a/Packages/src/Editor/FirstPartyTools/Compile/CompileSchema.cs b/Packages/src/Editor/FirstPartyTools/Compile/CompileSchema.cs index 4bc546da41..6f153a042b 100644 --- a/Packages/src/Editor/FirstPartyTools/Compile/CompileSchema.cs +++ b/Packages/src/Editor/FirstPartyTools/Compile/CompileSchema.cs @@ -25,6 +25,13 @@ public class CompileSchema : UnityCliLoopToolSchema /// public bool ReloadExternalSceneChanges { get; set; } = true; + /// + /// How long the CLI waits for compilation to complete, in seconds. + /// Unity ignores this value; it is consumed by the CLI. + /// + [Description("How long the CLI waits for compilation to complete, in seconds. Unity ignores this value; it is consumed by the CLI.")] + public int CompileWaitTimeoutSeconds { get; set; } = 600; + /// /// Internal request identifier used for delayed result recovery across domain reload. /// diff --git a/Packages/src/Editor/FirstPartyTools/Compile/Skill/SKILL.md b/Packages/src/Editor/FirstPartyTools/Compile/Skill/SKILL.md index 3febf89300..265987c4c7 100644 --- a/Packages/src/Editor/FirstPartyTools/Compile/Skill/SKILL.md +++ b/Packages/src/Editor/FirstPartyTools/Compile/Skill/SKILL.md @@ -11,7 +11,7 @@ Execute Unity project compilation. ## Usage ```bash -uloop compile [--force-recompile] [--no-wait-for-domain-reload] [--stop-on-external-scene-changes] +uloop compile [--force-recompile] [--no-wait-for-domain-reload] [--stop-on-external-scene-changes] [--compile-wait-timeout-seconds ] ``` ## Parameters @@ -21,6 +21,7 @@ uloop compile [--force-recompile] [--no-wait-for-domain-reload] [--stop-on-exter | `--force-recompile` | flag | - | Full recompile plus domain reload. Almost never needed: a plain compile already detects externally edited files, and the forced reload can freeze large projects and come back as `COMPILE_RESULT_UNKNOWN`. | | `--no-wait-for-domain-reload` | flag | - | Return before Domain Reload completion | | `--stop-on-external-scene-changes` | flag | - | Stop before compilation if open Scene files changed externally instead of auto-reloading them | +| `--compile-wait-timeout-seconds` | integer | 600 | Maximum seconds the CLI waits for the compile to finish before returning COMPILE_WAIT_TIMEOUT (default 600). Values above 1200 exceed the Unity-side result retention window (20 minutes) and weaken post-timeout recovery. | ## When to use --force-recompile diff --git a/cli/common/errors/busy_editor_state.go b/cli/common/errors/busy_editor_state.go index 1bbde241ef..8fc4ad66f1 100644 --- a/cli/common/errors/busy_editor_state.go +++ b/cli/common/errors/busy_editor_state.go @@ -18,6 +18,16 @@ func unityServerBusyNextActions(data map[string]any) []string { actions...) } + // Why only runningToolName == "compile": attach recovery requires a local pending + // record from this client's own COMPILE_WAIT_TIMEOUT. Editor-state "unity-compile" + // busy and other clients' compiles must not promise reattach. + if rpcStringData(data, "runningToolName") == "compile" { + actions = append( + actions, + "A compile can take several minutes on large projects. Wait for it to finish, then retry. If your own `uloop compile` previously failed with COMPILE_WAIT_TIMEOUT, re-running `uloop compile` reattaches to that compile instead of starting a new one.", + ) + } + if stallSeconds, ok := rpcFloatData(data, "secondsSinceLastMainThreadTick"); ok && stallSeconds >= unityServerBusyResponsivenessStallThresholdSeconds { actions = append( diff --git a/cli/common/errors/busy_editor_state_test.go b/cli/common/errors/busy_editor_state_test.go index 2f4eb48a49..0711a6b033 100644 --- a/cli/common/errors/busy_editor_state_test.go +++ b/cli/common/errors/busy_editor_state_test.go @@ -17,6 +17,42 @@ func TestUnityServerBusyNextActions_WhenCompiling_IncludesCompileGuidance(t *tes } } +// Verifies a busy compile tool adds reattach guidance that only applies after the +// caller's own COMPILE_WAIT_TIMEOUT (not for unrelated clients or unity-compile). +func TestUnityServerBusyNextActions_WhenRunningCompileTool_IncludesReattachGuidance(t *testing.T) { + data := map[string]any{ + "runningToolName": "compile", + } + + actions := unityServerBusyNextActions(data) + expected := "A compile can take several minutes on large projects. Wait for it to finish, then retry. If your own `uloop compile` previously failed with COMPILE_WAIT_TIMEOUT, re-running `uloop compile` reattaches to that compile instead of starting a new one." + found := false + for _, action := range actions { + if action == expected { + found = true + break + } + } + if !found { + t.Fatalf("compile reattach guidance missing: %#v", actions) + } +} + +// Verifies editor-state unity-compile busy does not promise uloop compile reattach. +func TestUnityServerBusyNextActions_WhenRunningUnityCompile_OmitsReattachGuidance(t *testing.T) { + data := map[string]any{ + "runningToolName": "unity-compile", + "isCompiling": true, + } + + actions := unityServerBusyNextActions(data) + for _, action := range actions { + if action == "A compile can take several minutes on large projects. Wait for it to finish, then retry. If your own `uloop compile` previously failed with COMPILE_WAIT_TIMEOUT, re-running `uloop compile` reattaches to that compile instead of starting a new one." { + t.Fatalf("unity-compile busy must not promise reattach: %#v", actions) + } + } +} + // Verifies stalled main-thread ticks add a lightweight responsiveness check action. func TestUnityServerBusyNextActions_WhenMainThreadStalled_IncludesResponsivenessCheck(t *testing.T) { data := map[string]any{ diff --git a/cli/common/tools/default-tools.json b/cli/common/tools/default-tools.json index df36cb6ffd..514c045bbe 100644 --- a/cli/common/tools/default-tools.json +++ b/cli/common/tools/default-tools.json @@ -19,6 +19,11 @@ "type": "boolean", "description": "Stop before compilation if open Scene files changed externally instead of auto-reloading them", "default": true + }, + "CompileWaitTimeoutSeconds": { + "type": "integer", + "description": "Maximum seconds the CLI waits for the compile to finish before returning COMPILE_WAIT_TIMEOUT (default 600). Values above 1200 exceed the Unity-side result retention window (20 minutes) and weaken post-timeout recovery.", + "default": 600 } } } diff --git a/cli/dispatcher/shared-inputs-stamp.json b/cli/dispatcher/shared-inputs-stamp.json index 603a54226f..60430f5310 100644 --- a/cli/dispatcher/shared-inputs-stamp.json +++ b/cli/dispatcher/shared-inputs-stamp.json @@ -1,4 +1,4 @@ { "schemaVersion": 1, - "sharedInputsHash": "8735819857e8be16e1a53dadd643bf92995ea65c" + "sharedInputsHash": "050e25b77113c7d2cb24bd904463acda2e7f0087" } diff --git a/cli/project-runner/internal/projectrunner/compile_attach.go b/cli/project-runner/internal/projectrunner/compile_attach.go new file mode 100644 index 0000000000..f92ea47356 --- /dev/null +++ b/cli/project-runner/internal/projectrunner/compile_attach.go @@ -0,0 +1,337 @@ +package projectrunner + +import ( + "context" + "encoding/json" + "fmt" + "io" + "time" + + clierrors "github.com/hatayama/unity-cli-loop/common/errors" + "github.com/hatayama/unity-cli-loop/common/ui" + "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 ( + compileAttachProbeTimeout = 10 * time.Second + compileAttachProbeInterval = 1 * time.Second + // Why 3: a single Ready&&!HasResult sample can race the completion→store window. + compileAttachMissingResultStreak = 3 +) + +type attachWaitOutcome int + +const ( + attachWaitCompleted attachWaitOutcome = iota + attachWaitTimedOut + attachWaitDisappeared + attachWaitFailed +) + +// tryAttachToPendingCompile reattaches to a previously timed-out compile when a +// pending record still exists. handled=true means the caller must return exitCode. +func tryAttachToPendingCompile( + ctx context.Context, + connection unityipc.Connection, + params map[string]any, + waitTimeout time.Duration, + stdout io.Writer, + stderr io.Writer, + deps compileWaitDeps, +) (bool, int) { + record, ok := readCompilePendingRecord(connection.ProjectRoot) + if !ok { + return false, 0 + } + + status, probed := probePendingCompileStatus(ctx, connection, record.RequestID, deps) + if !probed { + // Why keep the record: probe failures during domain reload are transient and + // do not prove the in-flight compile is gone. + return false, 0 + } + + // Why HasResult first: Ready is editor-wide (!compiling/!updating/!reload), not + // scoped to record.RequestID. Only HasResult is request-specific, and results are + // stored only after that request finishes — so a result is definitive even when + // the editor is busy with unrelated work. + if status.HasResult && len(status.Result) > 0 { + if compileForceRecompileEnabled(params) { + clearCompilePendingRecord(connection.ProjectRoot) + return false, 0 + } + return true, returnAttachedStoredCompileResult(ctx, connection, record, status.Result, stdout, stderr) + } + + if !status.Ready { + return attachWaitForPendingCompile(ctx, connection, record, params, waitTimeout, stdout, stderr, deps) + } + + clearCompilePendingRecord(connection.ProjectRoot) + return false, 0 +} + +func probePendingCompileStatus( + ctx context.Context, + connection unityipc.Connection, + requestID string, + deps compileWaitDeps, +) (compileStatusResponse, bool) { + timeout := deps.attachProbeTimeout + if timeout <= 0 { + timeout = compileAttachProbeTimeout + } + interval := deps.attachProbeInterval + if interval <= 0 { + interval = compileAttachProbeInterval + } + + deadline := time.Now().Add(timeout) + for { + status, err := deps.queryCompileStatus(ctx, connection, requestID) + if err == nil { + return status, true + } + if !time.Now().Before(deadline) { + return compileStatusResponse{}, false + } + + remaining := time.Until(deadline) + sleepFor := interval + if sleepFor > remaining { + sleepFor = remaining + } + timer := time.NewTimer(sleepFor) + select { + case <-ctx.Done(): + timer.Stop() + return compileStatusResponse{}, false + case <-timer.C: + } + } +} + +func attachWaitForPendingCompile( + ctx context.Context, + connection unityipc.Connection, + record compilePendingRecord, + params map[string]any, + waitTimeout time.Duration, + stdout io.Writer, + stderr io.Writer, + deps compileWaitDeps, +) (bool, int) { + if compileForceRecompileEnabled(params) { + _, _ = fmt.Fprintf( + stderr, + "warning: reattaching to an in-flight compile; --force-recompile is not applied. Re-run with --force-recompile after this compile finishes if you still need a forced recompile.\n", + ) + } + + startedAt := time.Now() + logCompileAttachStart(connection, record.RequestID, "waiting") + spinner := clicore.NewToolSpinner(stderr, clicore.CompileCommandName) + spinner.Update("Reattaching to in-flight compile...") + + pollInterval := deps.attachWaitPollInterval + if pollInterval <= 0 { + pollInterval = compileWaitPollInterval + } + waitStartedAt := time.Now() + result, outcome, lastStatus, waitErr := waitForAttachedCompileCompletion(ctx, compileCompletionOptions{ + connection: connection, + requestID: record.RequestID, + timeout: waitTimeout, + pollInterval: pollInterval, + }, deps) + if waitErr != nil { + spinner.Stop() + logCompileAttachResult(connection, record.RequestID, "error", false) + clierrors.WriteClassifiedError(stderr, waitErr, clierrors.ErrorContext{ + ProjectRoot: connection.ProjectRoot, + Command: clicore.CompileCommandName, + }) + return true, 1 + } + + switch outcome { + case attachWaitDisappeared: + spinner.Stop() + clearCompilePendingRecord(connection.ProjectRoot) + logCompileAttachResult(connection, record.RequestID, "disappeared", true) + return false, 0 + case attachWaitTimedOut: + spinner.Stop() + // Why not refresh TimedOutAtUtc: stale expiry must stay anchored to the first timeout. + logCompileAttachResult(connection, record.RequestID, "timeout", false) + // Why not (TTL - waitTimeout): attach keeps the first TimedOutAtUtc, so remaining + // retrieval time is wall-clock until that anchor plus compilePendingRecordLifetime. + retentionRemaining := time.Until(record.TimedOutAtUtc.Add(compilePendingRecordLifetime)) + clierrors.WriteErrorEnvelope(stderr, compileWaitTimeoutError( + connection.ProjectRoot, + waitTimeout, + lastStatus, + time.Since(waitStartedAt), + retentionRemaining, + )) + return true, 1 + case attachWaitCompleted: + clearCompilePendingRecord(connection.ProjectRoot) + logCompileAttachResult(connection, record.RequestID, "completed", true) + return true, completeCompileResultOutput(ctx, connection, result, stdout, stderr, spinner, startedAt, unityipc.UnitySendOutcome{}) + default: + spinner.Stop() + logCompileAttachResult(connection, record.RequestID, "error", false) + return true, 1 + } +} + +func waitForAttachedCompileCompletion( + ctx context.Context, + options compileCompletionOptions, + deps compileWaitDeps, +) (json.RawMessage, attachWaitOutcome, *compileStatusResponse, error) { + startedAt := time.Now() + deadline := startedAt.Add(options.timeout) + attempts := 0 + missingResultStreak := 0 + var lastStatus compileStatusResponse + observedStatus := false + var lastErr error + lastObservationKey := "" + + logCompileStatusPollStart(options, startedAt, deadline) + + ticker := time.NewTicker(options.pollInterval) + defer ticker.Stop() + for { + now := time.Now() + if !now.Before(deadline) { + break + } + + attempts++ + status, err := deps.queryCompileStatus(ctx, options.connection, options.requestID) + lastErr = err + if err == nil { + lastStatus = status + observedStatus = true + if status.HasResult && len(status.Result) > 0 { + logCompileStatusPollObservedIfChanged(options, startedAt, attempts, status, nil, &lastObservationKey) + logCompileStatusPollComplete(options, startedAt, attempts, status) + return status.Result, attachWaitCompleted, nil, nil + } + if status.Ready && !status.HasResult { + missingResultStreak++ + if missingResultStreak >= compileAttachMissingResultStreak { + logCompileStatusPollObservedIfChanged(options, startedAt, attempts, status, nil, &lastObservationKey) + return nil, attachWaitDisappeared, lastObservedCompileStatus(lastStatus, observedStatus), nil + } + } else { + missingResultStreak = 0 + } + } + logCompileStatusPollObservedIfChanged(options, startedAt, attempts, status, err, &lastObservationKey) + + select { + case <-ctx.Done(): + logCompileWaitCancelled(options, startedAt, attempts, lastStatus, lastErr, ctx.Err()) + return nil, attachWaitFailed, lastObservedCompileStatus(lastStatus, observedStatus), ctx.Err() + case <-ticker.C: + } + } + + logCompileWaitTimedOut(options, startedAt, attempts, lastStatus, lastErr) + return nil, attachWaitTimedOut, lastObservedCompileStatus(lastStatus, observedStatus), nil +} + +func returnAttachedStoredCompileResult( + ctx context.Context, + connection unityipc.Connection, + record compilePendingRecord, + result json.RawMessage, + stdout io.Writer, + stderr io.Writer, +) int { + startedAt := time.Now() + logCompileAttachStart(connection, record.RequestID, "stored_result") + spinner := clicore.NewToolSpinner(stderr, clicore.CompileCommandName) + clearCompilePendingRecord(connection.ProjectRoot) + logCompileAttachResult(connection, record.RequestID, "stored_result", true) + return completeCompileResultOutput(ctx, connection, result, stdout, stderr, spinner, startedAt, unityipc.UnitySendOutcome{}) +} + +func completeCompileResultOutput( + ctx context.Context, + connection unityipc.Connection, + result json.RawMessage, + stdout io.Writer, + stderr io.Writer, + spinner *ui.TerminalSpinner, + startedAt time.Time, + outcome unityipc.UnitySendOutcome, +) int { + switch compileResultReadinessWaitMode(result) { + case compileReadinessWaitWarmup: + spinner.Update("Warming execute-dynamic-code after compile...") + if err := clicore.WaitForToolReadiness(ctx, connection.ProjectRoot); err != nil { + spinner.Stop() + writePostCompileWarmupWarning(stderr, err) + } + } + spinner.Stop() + clicore.WriteJSON(stdout, result) + writeDebugTiming(stderr, clicore.CompileCommandName, time.Since(startedAt), outcome) + return toolEnvelopeExitCode(result) +} + +func persistCompilePendingRecordOrWarn(projectRoot string, requestID string, stderr io.Writer) { + err := writeCompilePendingRecord(projectRoot, compilePendingRecord{ + RequestID: requestID, + TimedOutAtUtc: time.Now().UTC(), + }) + if err == nil { + return + } + _, _ = fmt.Fprintf(stderr, "warning: failed to persist pending compile request for retry attach: %v\n", err) +} + +func logCompileAttachStart(connection unityipc.Connection, requestID string, mode string) { + writeCompileVibeLog(connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { + return vibelog.CLIVibeLogEntry{ + Level: "INFO", + Operation: "cli_compile_attach_start", + Message: "Reattaching to a previously timed-out compile request.", + Context: map[string]any{ + "command": clicore.CompileCommandName, + "request_id": requestID, + "attach_mode": mode, + "project_identity": vibelog.ProjectIdentity(connection.ProjectRoot), + "endpoint": connection.Endpoint.Address, + }, + CorrelationID: requestID, + } + }) +} + +func logCompileAttachResult(connection unityipc.Connection, requestID string, outcome string, clearedRecord bool) { + writeCompileVibeLog(connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { + return vibelog.CLIVibeLogEntry{ + Level: "INFO", + Operation: "cli_compile_attach_result", + Message: "Finished attach attempt for a previously timed-out compile request.", + Context: map[string]any{ + "command": clicore.CompileCommandName, + "request_id": requestID, + "attach_outcome": outcome, + "record_cleared": clearedRecord, + "project_identity": vibelog.ProjectIdentity(connection.ProjectRoot), + "endpoint": connection.Endpoint.Address, + }, + CorrelationID: requestID, + } + }) +} diff --git a/cli/project-runner/internal/projectrunner/compile_attach_test.go b/cli/project-runner/internal/projectrunner/compile_attach_test.go new file mode 100644 index 0000000000..7860c81f21 --- /dev/null +++ b/cli/project-runner/internal/projectrunner/compile_attach_test.go @@ -0,0 +1,609 @@ +package projectrunner + +import ( + "bytes" + "context" + "encoding/json" + "fmt" + "os" + "runtime" + "strings" + "testing" + "time" + + "github.com/hatayama/unity-cli-loop/common/unityipc" +) + +// Verifies that with no pending record, compile follows the normal request path. +func TestRunCompileAttachWithoutPendingRecordUsesNormalPath(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("TCP endpoint injection is only used by this non-Windows client test") + } + + enableCliVibeLog(t) + endpoint, serverErr := startCompileAcceptOnceServer(t) + projectRoot := t.TempDir() + connection := unityipc.Connection{Endpoint: endpoint, ProjectRoot: projectRoot} + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + return compileStatusResponse{ + Ready: true, + HasResult: true, + Result: json.RawMessage(`{"Success":false,"ErrorCount":1}`), + }, nil + }) + var stdout, stderr bytes.Buffer + + code := runCompileWithDomainReloadWaitWithDeps(context.Background(), connection, map[string]any{}, &stdout, &stderr, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr.String()) + } + logContent := readOnlyCliVibeLog(t, projectRoot) + if !strings.Contains(logContent, `"operation":"cli_compile_request_prepared"`) { + t.Fatalf("normal path should prepare a compile request:\n%s", logContent) + } + if strings.Contains(logContent, `"operation":"cli_compile_attach_start"`) { + t.Fatalf("attach must not run without a pending record:\n%s", logContent) + } + select { + case err := <-serverErr: + t.Fatalf("server failed: %v", err) + default: + } +} + +// Verifies HasResult is returned even when Ready is false (editor-wide busy is unrelated). +func TestRunCompileAttachReturnsStoredResultWhenEditorNotReady(t *testing.T) { + enableCliVibeLog(t) + projectRoot := t.TempDir() + if err := writeCompilePendingRecord(projectRoot, compilePendingRecord{ + RequestID: "compile_attach_busy_stored", + TimedOutAtUtc: time.Now().UTC(), + }); err != nil { + t.Fatalf("write pending record failed: %v", err) + } + + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + return compileStatusResponse{ + Ready: false, + IsCompiling: true, + HasResult: true, + Result: json.RawMessage(`{"Success":false,"ErrorCount":7}`), + }, nil + }) + connection := unityipc.Connection{ + Endpoint: unityipc.Endpoint{Network: "tcp", Address: "127.0.0.1:1"}, + ProjectRoot: projectRoot, + } + var stdout, stderr bytes.Buffer + + code := runCompileWithDomainReloadWaitWithDeps(context.Background(), connection, map[string]any{}, &stdout, &stderr, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr.String()) + } + if !strings.Contains(stdout.String(), `"ErrorCount"`) || !strings.Contains(stdout.String(), "7") { + t.Fatalf("stored result missing from stdout: %s", stdout.String()) + } + if _, err := os.Stat(compilePendingRecordPath(projectRoot)); !os.IsNotExist(err) { + t.Fatalf("pending record should be cleared: %v", err) + } + logContent := readOnlyCliVibeLog(t, projectRoot) + if !strings.Contains(logContent, `"attach_mode":"stored_result"`) { + t.Fatalf("stored-result attach mode missing:\n%s", logContent) + } + if strings.Contains(logContent, `"operation":"cli_compile_request_prepared"`) { + t.Fatalf("stored result must not send a new compile request:\n%s", logContent) + } +} + +// Verifies an in-flight pending compile is waited on without sending a new compile request. +func TestRunCompileAttachWaitsForInFlightCompileAndClearsRecord(t *testing.T) { + enableCliVibeLog(t) + projectRoot := t.TempDir() + requestID := "compile_attach_waiting" + timedOutAt := time.Now().UTC().Add(-time.Minute) + if err := writeCompilePendingRecord(projectRoot, compilePendingRecord{ + RequestID: requestID, + TimedOutAtUtc: timedOutAt, + }); err != nil { + t.Fatalf("write pending record failed: %v", err) + } + + callCount := 0 + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + callCount++ + if callCount == 1 { + return compileStatusResponse{Ready: false, IsCompiling: true}, nil + } + return compileStatusResponse{ + Ready: true, + HasResult: true, + Result: json.RawMessage(`{"Success":false,"ErrorCount":2,"WarningCount":0}`), + }, nil + }) + connection := unityipc.Connection{ + Endpoint: unityipc.Endpoint{Network: "tcp", Address: "127.0.0.1:1"}, + ProjectRoot: projectRoot, + } + var stdout, stderr bytes.Buffer + + code := runCompileWithDomainReloadWaitWithDeps(context.Background(), connection, map[string]any{}, &stdout, &stderr, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr.String()) + } + if !strings.Contains(stdout.String(), `"ErrorCount"`) || !strings.Contains(stdout.String(), "2") { + t.Fatalf("attached result missing from stdout: %s", stdout.String()) + } + if _, err := os.Stat(compilePendingRecordPath(projectRoot)); !os.IsNotExist(err) { + t.Fatalf("pending record should be cleared after attach success: %v", err) + } + logContent := readOnlyCliVibeLog(t, projectRoot) + for _, expected := range []string{ + `"operation":"cli_compile_attach_start"`, + `"operation":"cli_compile_attach_result"`, + `"attach_mode":"waiting"`, + `"attach_outcome":"completed"`, + } { + if !strings.Contains(logContent, expected) { + t.Fatalf("attach vibe log missing %q:\n%s", expected, logContent) + } + } + if strings.Contains(logContent, `"operation":"cli_compile_request_prepared"`) { + t.Fatalf("attach wait must not send a new compile request:\n%s", logContent) + } +} + +// Verifies a completed pending compile returns the stored result without a new request. +func TestRunCompileAttachReturnsStoredResultAndClearsRecord(t *testing.T) { + enableCliVibeLog(t) + projectRoot := t.TempDir() + requestID := "compile_attach_stored" + if err := writeCompilePendingRecord(projectRoot, compilePendingRecord{ + RequestID: requestID, + TimedOutAtUtc: time.Now().UTC(), + }); err != nil { + t.Fatalf("write pending record failed: %v", err) + } + + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + return compileStatusResponse{ + Ready: true, + HasResult: true, + Result: json.RawMessage(`{"Success":false,"ErrorCount":3}`), + }, nil + }) + connection := unityipc.Connection{ + Endpoint: unityipc.Endpoint{Network: "tcp", Address: "127.0.0.1:1"}, + ProjectRoot: projectRoot, + } + var stdout, stderr bytes.Buffer + + code := runCompileWithDomainReloadWaitWithDeps(context.Background(), connection, map[string]any{}, &stdout, &stderr, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr.String()) + } + if !strings.Contains(stdout.String(), `"ErrorCount"`) || !strings.Contains(stdout.String(), "3") { + t.Fatalf("stored result missing from stdout: %s", stdout.String()) + } + if _, err := os.Stat(compilePendingRecordPath(projectRoot)); !os.IsNotExist(err) { + t.Fatalf("pending record should be cleared: %v", err) + } + logContent := readOnlyCliVibeLog(t, projectRoot) + if !strings.Contains(logContent, `"attach_mode":"stored_result"`) { + t.Fatalf("stored-result attach mode missing:\n%s", logContent) + } + if strings.Contains(logContent, `"operation":"cli_compile_request_prepared"`) { + t.Fatalf("stored-result attach must not send a compile request:\n%s", logContent) + } +} + +// Verifies ForceRecompile clears the pending record and starts a new compile. +func TestRunCompileAttachForceRecompileClearsRecordAndStartsNewCompile(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("TCP endpoint injection is only used by this non-Windows client test") + } + + enableCliVibeLog(t) + endpoint, serverErr := startCompileAcceptOnceServer(t) + projectRoot := t.TempDir() + if err := writeCompilePendingRecord(projectRoot, compilePendingRecord{ + RequestID: "compile_attach_force", + TimedOutAtUtc: time.Now().UTC(), + }); err != nil { + t.Fatalf("write pending record failed: %v", err) + } + + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + return compileStatusResponse{ + Ready: true, + HasResult: true, + Result: json.RawMessage(`{"Success":false,"ErrorCount":9}`), + }, nil + }) + connection := unityipc.Connection{Endpoint: endpoint, ProjectRoot: projectRoot} + params := map[string]any{compileForceParam: true} + var stdout, stderr bytes.Buffer + + code := runCompileWithDomainReloadWaitWithDeps(context.Background(), connection, params, &stdout, &stderr, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr.String()) + } + if _, err := os.Stat(compilePendingRecordPath(projectRoot)); !os.IsNotExist(err) { + t.Fatalf("pending record should be cleared before forced recompile: %v", err) + } + logContent := readOnlyCliVibeLog(t, projectRoot) + if !strings.Contains(logContent, `"operation":"cli_compile_request_prepared"`) { + t.Fatalf("force recompile should send a new compile request:\n%s", logContent) + } + if strings.Contains(logContent, `"operation":"cli_compile_attach_start"`) { + t.Fatalf("force recompile should not return via attach:\n%s", logContent) + } + select { + case err := <-serverErr: + t.Fatalf("server failed: %v", err) + default: + } +} + +// Verifies Ready-without-result clears the pending record and starts a new compile. +func TestRunCompileAttachReadyWithoutResultClearsRecordAndStartsNewCompile(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("TCP endpoint injection is only used by this non-Windows client test") + } + + enableCliVibeLog(t) + endpoint, serverErr := startCompileAcceptOnceServer(t) + projectRoot := t.TempDir() + if err := writeCompilePendingRecord(projectRoot, compilePendingRecord{ + RequestID: "compile_attach_missing_result", + TimedOutAtUtc: time.Now().UTC(), + }); err != nil { + t.Fatalf("write pending record failed: %v", err) + } + + callCount := 0 + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + callCount++ + if callCount == 1 { + return compileStatusResponse{Ready: true, HasResult: false}, nil + } + return compileStatusResponse{ + Ready: true, + HasResult: true, + Result: json.RawMessage(`{"Success":false,"ErrorCount":4}`), + }, nil + }) + connection := unityipc.Connection{Endpoint: endpoint, ProjectRoot: projectRoot} + var stdout, stderr bytes.Buffer + + code := runCompileWithDomainReloadWaitWithDeps(context.Background(), connection, map[string]any{}, &stdout, &stderr, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr.String()) + } + if _, err := os.Stat(compilePendingRecordPath(projectRoot)); !os.IsNotExist(err) { + t.Fatalf("pending record should be cleared when stored result is gone: %v", err) + } + logContent := readOnlyCliVibeLog(t, projectRoot) + if !strings.Contains(logContent, `"operation":"cli_compile_request_prepared"`) { + t.Fatalf("missing stored result should fall through to a new compile:\n%s", logContent) + } + if strings.Contains(logContent, `"operation":"cli_compile_attach_start"`) { + t.Fatalf("missing stored result should not attach:\n%s", logContent) + } + select { + case err := <-serverErr: + t.Fatalf("server failed: %v", err) + default: + } +} + +// Verifies an attach wait that times out again keeps the original pending record untouched, +// and reports remaining retention from the first TimedOutAtUtc (not TTL minus this wait). +func TestRunCompileAttachRetimesOutPreservesPendingRecord(t *testing.T) { + enableCliVibeLog(t) + projectRoot := t.TempDir() + requestID := "compile_attach_retimeout" + // Why 15m ago: a 1s attach wait would overstate "roughly 19 more minutes" if NextActions + // used (TTL - waitTimeout). Wall-clock remaining is ~5 minutes (stable against minute floor). + timedOutAt := time.Now().UTC().Add(-15 * time.Minute) + if err := writeCompilePendingRecord(projectRoot, compilePendingRecord{ + RequestID: requestID, + TimedOutAtUtc: timedOutAt, + }); err != nil { + t.Fatalf("write pending record failed: %v", err) + } + + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + return compileStatusResponse{Ready: false, IsCompiling: true}, nil + }) + connection := unityipc.Connection{ + Endpoint: unityipc.Endpoint{Network: "tcp", Address: "127.0.0.1:1"}, + ProjectRoot: projectRoot, + } + params := map[string]any{compileWaitTimeoutParam: 1} + var stdout, stderr bytes.Buffer + + code := runCompileWithDomainReloadWaitWithDeps(context.Background(), connection, params, &stdout, &stderr, deps) + if code != 1 { + t.Fatalf("expected timeout exit 1: code=%d stderr=%s", code, stderr.String()) + } + if !strings.Contains(stderr.String(), "Compile status wait timed out after 1000ms") { + t.Fatalf("reattach timeout message mismatch: %s", stderr.String()) + } + assertCompileWaitTimeoutEnvelopeDetails(t, stderr.Bytes(), true) + if strings.Contains(stderr.String(), "roughly 19 more minutes") { + t.Fatalf("attach re-timeout must not overstate retention from this wait: %s", stderr.String()) + } + if !strings.Contains(stderr.String(), "roughly 5 more minutes") && + !strings.Contains(stderr.String(), "roughly 4 more minutes") { + t.Fatalf("attach re-timeout should report ~5 minutes left from first timeout: %s", stderr.String()) + } + + got, ok := readCompilePendingRecord(projectRoot) + if !ok { + t.Fatal("pending record must be preserved after attach timeout") + } + if got.RequestID != requestID || !got.TimedOutAtUtc.Equal(timedOutAt) { + t.Fatalf("pending record mutated on re-timeout: %#v", got) + } + logContent := readOnlyCliVibeLog(t, projectRoot) + if !strings.Contains(logContent, `"attach_outcome":"timeout"`) { + t.Fatalf("attach timeout outcome missing:\n%s", logContent) + } +} + +// Verifies probe failures keep the pending record and fall through to a new compile. +func TestRunCompileAttachProbeFailureKeepsRecordAndStartsNewCompile(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("TCP endpoint injection is only used by this non-Windows client test") + } + + enableCliVibeLog(t) + endpoint, serverErr := startCompileAcceptOnceServer(t) + projectRoot := t.TempDir() + requestID := "compile_attach_probe_fail" + timedOutAt := time.Now().UTC().Add(-time.Minute) + if err := writeCompilePendingRecord(projectRoot, compilePendingRecord{ + RequestID: requestID, + TimedOutAtUtc: timedOutAt, + }); err != nil { + t.Fatalf("write pending record failed: %v", err) + } + + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + return compileStatusResponse{}, fmt.Errorf("probe unavailable") + }) + connection := unityipc.Connection{Endpoint: endpoint, ProjectRoot: projectRoot} + var stdout, stderr bytes.Buffer + + // After probe failure, normal path queries status again with the new request id. + // Replace deps so probe fails, then normal wait succeeds via a second deps wrapper. + queryCalls := 0 + deps.queryCompileStatus = func(ctx context.Context, connection unityipc.Connection, id string) (compileStatusResponse, error) { + queryCalls++ + if id == requestID { + return compileStatusResponse{}, fmt.Errorf("probe unavailable") + } + return compileStatusResponse{ + Ready: true, + HasResult: true, + Result: json.RawMessage(`{"Success":false,"ErrorCount":5}`), + }, nil + } + + code := runCompileWithDomainReloadWaitWithDeps(context.Background(), connection, map[string]any{}, &stdout, &stderr, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr.String()) + } + got, ok := readCompilePendingRecord(projectRoot) + if !ok { + t.Fatal("pending record must remain after probe failure") + } + if got.RequestID != requestID || !got.TimedOutAtUtc.Equal(timedOutAt) { + t.Fatalf("pending record mutated after probe failure: %#v", got) + } + if queryCalls < 2 { + t.Fatalf("expected probe retries then normal status query, got %d calls", queryCalls) + } + logContent := readOnlyCliVibeLog(t, projectRoot) + if !strings.Contains(logContent, `"operation":"cli_compile_request_prepared"`) { + t.Fatalf("probe failure should fall through to a new compile:\n%s", logContent) + } + if strings.Contains(logContent, `"operation":"cli_compile_attach_start"`) { + t.Fatalf("failed probe must not attach:\n%s", logContent) + } + select { + case err := <-serverErr: + t.Fatalf("server failed: %v", err) + default: + } +} + +// Verifies three consecutive Ready&&!HasResult observations abandon attach without waiting out the deadline. +func TestRunCompileAttachDisappearedResultFallsThroughQuickly(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("TCP endpoint injection is only used by this non-Windows client test") + } + + enableCliVibeLog(t) + endpoint, serverErr := startCompileAcceptOnceServer(t) + projectRoot := t.TempDir() + if err := writeCompilePendingRecord(projectRoot, compilePendingRecord{ + RequestID: "compile_attach_disappeared", + TimedOutAtUtc: time.Now().UTC(), + }); err != nil { + t.Fatalf("write pending record failed: %v", err) + } + + callCount := 0 + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + callCount++ + if callCount == 1 { + // Probe: editor busy with unrelated work, no stored result for this RequestId. + return compileStatusResponse{Ready: false, IsCompiling: true, HasResult: false}, nil + } + if callCount <= 1+compileAttachMissingResultStreak { + return compileStatusResponse{Ready: true, HasResult: false}, nil + } + return compileStatusResponse{ + Ready: true, + HasResult: true, + Result: json.RawMessage(`{"Success":false,"ErrorCount":8}`), + }, nil + }) + connection := unityipc.Connection{Endpoint: endpoint, ProjectRoot: projectRoot} + params := map[string]any{compileWaitTimeoutParam: 600} + var stdout, stderr bytes.Buffer + + startedAt := time.Now() + code := runCompileWithDomainReloadWaitWithDeps(context.Background(), connection, params, &stdout, &stderr, deps) + elapsed := time.Since(startedAt) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr.String()) + } + if elapsed > 2*time.Second { + t.Fatalf("disappearance should not wait for the configured timeout: elapsed=%v", elapsed) + } + if _, err := os.Stat(compilePendingRecordPath(projectRoot)); !os.IsNotExist(err) { + t.Fatalf("disappeared attach should clear the pending record: %v", err) + } + logContent := readOnlyCliVibeLog(t, projectRoot) + if !strings.Contains(logContent, `"attach_outcome":"disappeared"`) { + t.Fatalf("disappeared attach outcome missing:\n%s", logContent) + } + if !strings.Contains(logContent, `"operation":"cli_compile_request_prepared"`) { + t.Fatalf("disappearance should fall through to a new compile:\n%s", logContent) + } + select { + case err := <-serverErr: + t.Fatalf("server failed: %v", err) + default: + } +} + +// Verifies a single Ready&&!HasResult sample does not abort attach (completion/store race). +func TestRunCompileAttachToleratesTransientReadyWithoutResult(t *testing.T) { + enableCliVibeLog(t) + projectRoot := t.TempDir() + if err := writeCompilePendingRecord(projectRoot, compilePendingRecord{ + RequestID: "compile_attach_transient_ready", + TimedOutAtUtc: time.Now().UTC(), + }); err != nil { + t.Fatalf("write pending record failed: %v", err) + } + + callCount := 0 + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + callCount++ + switch callCount { + case 1: + return compileStatusResponse{Ready: false, IsCompiling: true}, nil + case 2: + return compileStatusResponse{Ready: true, HasResult: false}, nil + default: + return compileStatusResponse{ + Ready: true, + HasResult: true, + Result: json.RawMessage(`{"Success":false,"ErrorCount":6}`), + }, nil + } + }) + connection := unityipc.Connection{ + Endpoint: unityipc.Endpoint{Network: "tcp", Address: "127.0.0.1:1"}, + ProjectRoot: projectRoot, + } + var stdout, stderr bytes.Buffer + + code := runCompileWithDomainReloadWaitWithDeps(context.Background(), connection, map[string]any{}, &stdout, &stderr, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr.String()) + } + if !strings.Contains(stdout.String(), `"ErrorCount"`) || !strings.Contains(stdout.String(), "6") { + t.Fatalf("attach should continue after one Ready&&!HasResult sample: %s", stdout.String()) + } + logContent := readOnlyCliVibeLog(t, projectRoot) + if strings.Contains(logContent, `"attach_outcome":"disappeared"`) { + t.Fatalf("one Ready&&!HasResult sample must not count as disappearance:\n%s", logContent) + } + if !strings.Contains(logContent, `"attach_outcome":"completed"`) { + t.Fatalf("attach should complete after the stored result appears:\n%s", logContent) + } +} + +// Verifies ForceRecompile during attach wait warns and does not start a forced recompile. +func TestRunCompileAttachWarnsWhenForceRecompileIgnoredDuringWait(t *testing.T) { + enableCliVibeLog(t) + projectRoot := t.TempDir() + if err := writeCompilePendingRecord(projectRoot, compilePendingRecord{ + RequestID: "compile_attach_force_warn", + TimedOutAtUtc: time.Now().UTC(), + }); err != nil { + t.Fatalf("write pending record failed: %v", err) + } + + callCount := 0 + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + callCount++ + if callCount == 1 { + return compileStatusResponse{Ready: false, IsCompiling: true}, nil + } + return compileStatusResponse{ + Ready: true, + HasResult: true, + Result: json.RawMessage(`{"Success":false,"ErrorCount":11}`), + }, nil + }) + connection := unityipc.Connection{ + Endpoint: unityipc.Endpoint{Network: "tcp", Address: "127.0.0.1:1"}, + ProjectRoot: projectRoot, + } + params := map[string]any{compileForceParam: true} + var stdout, stderr bytes.Buffer + + code := runCompileWithDomainReloadWaitWithDeps(context.Background(), connection, params, &stdout, &stderr, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr.String()) + } + if !strings.Contains(stderr.String(), "--force-recompile is not applied") { + t.Fatalf("expected force-recompile ignored warning: %s", stderr.String()) + } + if !strings.Contains(stdout.String(), `"ErrorCount"`) || !strings.Contains(stdout.String(), "11") { + t.Fatalf("attach should still return the in-flight result: %s", stdout.String()) + } + logContent := readOnlyCliVibeLog(t, projectRoot) + if strings.Contains(logContent, `"operation":"cli_compile_request_prepared"`) { + t.Fatalf("force during attach wait must not send a new compile request:\n%s", logContent) + } +} + +// Verifies COMPILE_WAIT_TIMEOUT persistence writes a pending record for later attach. +func TestRunCompileTimeoutWritesPendingRecord(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("TCP endpoint injection is only used by this non-Windows client test") + } + + endpoint, serverErr := startCompileAcceptOnceServer(t) + projectRoot := t.TempDir() + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + return compileStatusResponse{Ready: false, IsCompiling: true}, nil + }) + connection := unityipc.Connection{Endpoint: endpoint, ProjectRoot: projectRoot} + params := map[string]any{compileWaitTimeoutParam: 1} + var stdout, stderr bytes.Buffer + + code := runCompileWithDomainReloadWaitWithDeps(context.Background(), connection, params, &stdout, &stderr, deps) + if code != 1 { + t.Fatalf("expected timeout exit 1: code=%d stderr=%s", code, stderr.String()) + } + got, ok := readCompilePendingRecord(projectRoot) + if !ok { + t.Fatal("timeout should persist a pending compile record") + } + if got.RequestID == "" || got.TimedOutAtUtc.IsZero() { + t.Fatalf("pending record incomplete: %#v", got) + } + select { + case err := <-serverErr: + t.Fatalf("server failed: %v", err) + default: + } +} diff --git a/cli/project-runner/internal/projectrunner/compile_pending_record.go b/cli/project-runner/internal/projectrunner/compile_pending_record.go new file mode 100644 index 0000000000..49244bc869 --- /dev/null +++ b/cli/project-runner/internal/projectrunner/compile_pending_record.go @@ -0,0 +1,71 @@ +package projectrunner + +import ( + "encoding/json" + "os" + "path/filepath" + "time" + + "github.com/hatayama/unity-cli-loop/common/tools" +) + +const ( + compilePendingRecordFileName = "pending-compile-request.json" + // Why match C# CompileResultLifetime (20m): a timed-out CLI can only recover the + // Unity-stored result while that retention window still covers TimedOutAtUtc. + compilePendingRecordLifetime = 20 * time.Minute +) + +// compilePendingRecord remembers which compile a COMPILE_WAIT_TIMEOUT left in flight +// so a later uloop compile can reattach instead of starting a new request. +type compilePendingRecord struct { + RequestID string `json:"requestId"` + TimedOutAtUtc time.Time `json:"timedOutAtUtc"` +} + +func compilePendingRecordPath(projectRoot string) string { + return filepath.Join(projectRoot, tools.CacheDirectoryName, compilePendingRecordFileName) +} + +func writeCompilePendingRecord(projectRoot string, record compilePendingRecord) error { + if record.RequestID == "" || record.TimedOutAtUtc.IsZero() { + return os.ErrInvalid + } + + directory := filepath.Join(projectRoot, tools.CacheDirectoryName) + if err := os.MkdirAll(directory, 0o755); err != nil { + return err + } + + payload, err := json.Marshal(record) + if err != nil { + return err + } + // Why UTF-8 without BOM: Windows readers must see the same bytes as macOS/Linux. + return os.WriteFile(compilePendingRecordPath(projectRoot), payload, 0o644) +} + +func readCompilePendingRecord(projectRoot string) (compilePendingRecord, bool) { + path := compilePendingRecordPath(projectRoot) + content, err := os.ReadFile(path) + if err != nil { + return compilePendingRecord{}, false + } + + var record compilePendingRecord + if json.Unmarshal(content, &record) != nil || record.RequestID == "" || record.TimedOutAtUtc.IsZero() { + _ = os.Remove(path) + return compilePendingRecord{}, false + } + + if time.Since(record.TimedOutAtUtc) > compilePendingRecordLifetime { + _ = os.Remove(path) + return compilePendingRecord{}, false + } + + return record, true +} + +func clearCompilePendingRecord(projectRoot string) { + _ = os.Remove(compilePendingRecordPath(projectRoot)) +} diff --git a/cli/project-runner/internal/projectrunner/compile_pending_record_test.go b/cli/project-runner/internal/projectrunner/compile_pending_record_test.go new file mode 100644 index 0000000000..5fc3a58b3c --- /dev/null +++ b/cli/project-runner/internal/projectrunner/compile_pending_record_test.go @@ -0,0 +1,137 @@ +package projectrunner + +import ( + "os" + "path/filepath" + "runtime" + "testing" + "time" + + "github.com/hatayama/unity-cli-loop/common/tools" +) + +// Verifies a pending compile record round-trips through the project .uloop path. +func TestWriteReadCompilePendingRecordRoundTrip(t *testing.T) { + projectRoot := t.TempDir() + timedOutAt := time.Now().UTC().Truncate(time.Second) + record := compilePendingRecord{ + RequestID: "compile_test_record", + TimedOutAtUtc: timedOutAt, + } + + if err := writeCompilePendingRecord(projectRoot, record); err != nil { + t.Fatalf("writeCompilePendingRecord failed: %v", err) + } + + path := compilePendingRecordPath(projectRoot) + if filepath.Base(path) != compilePendingRecordFileName { + t.Fatalf("unexpected file name: %s", path) + } + if filepath.Base(filepath.Dir(path)) != tools.CacheDirectoryName { + t.Fatalf("record must live under %s: %s", tools.CacheDirectoryName, path) + } + + got, ok := readCompilePendingRecord(projectRoot) + if !ok { + t.Fatal("expected pending record") + } + if got.RequestID != record.RequestID { + t.Fatalf("request id mismatch: %#v", got) + } + if !got.TimedOutAtUtc.Equal(timedOutAt) { + t.Fatalf("timed out at mismatch: %#v", got.TimedOutAtUtc) + } +} + +// Verifies invalid JSON is treated as no record and the corrupt file is deleted. +func TestReadCompilePendingRecordRejectsInvalidJSON(t *testing.T) { + projectRoot := t.TempDir() + path := compilePendingRecordPath(projectRoot) + if err := os.MkdirAll(filepath.Dir(path), 0o755); err != nil { + t.Fatalf("mkdir failed: %v", err) + } + if err := os.WriteFile(path, []byte(`{"requestId":`), 0o644); err != nil { + t.Fatalf("write corrupt record failed: %v", err) + } + + if _, ok := readCompilePendingRecord(projectRoot); ok { + t.Fatal("invalid JSON must not yield a record") + } + if _, err := os.Stat(path); !os.IsNotExist(err) { + t.Fatalf("invalid JSON file should be deleted: %v", err) + } +} + +// Verifies missing required fields are treated as no record and the file is deleted. +func TestReadCompilePendingRecordRejectsMissingFields(t *testing.T) { + projectRoot := t.TempDir() + path := compilePendingRecordPath(projectRoot) + if err := os.MkdirAll(filepath.Dir(path), 0o755); err != nil { + t.Fatalf("mkdir failed: %v", err) + } + if err := os.WriteFile(path, []byte(`{"requestId":""}`), 0o644); err != nil { + t.Fatalf("write incomplete record failed: %v", err) + } + + if _, ok := readCompilePendingRecord(projectRoot); ok { + t.Fatal("missing fields must not yield a record") + } + if _, err := os.Stat(path); !os.IsNotExist(err) { + t.Fatalf("incomplete record file should be deleted: %v", err) + } +} + +// Verifies stale records older than CompileResultLifetime are deleted on read. +func TestReadCompilePendingRecordRejectsStaleRecord(t *testing.T) { + projectRoot := t.TempDir() + record := compilePendingRecord{ + RequestID: "compile_stale", + TimedOutAtUtc: time.Now().UTC().Add(-(compilePendingRecordLifetime + time.Minute)), + } + if err := writeCompilePendingRecord(projectRoot, record); err != nil { + t.Fatalf("writeCompilePendingRecord failed: %v", err) + } + + if _, ok := readCompilePendingRecord(projectRoot); ok { + t.Fatal("stale record must not be returned") + } + if _, err := os.Stat(compilePendingRecordPath(projectRoot)); !os.IsNotExist(err) { + t.Fatalf("stale record file should be deleted: %v", err) + } +} + +// Verifies clearCompilePendingRecord removes an existing file and tolerates absence. +func TestClearCompilePendingRecord(t *testing.T) { + projectRoot := t.TempDir() + record := compilePendingRecord{ + RequestID: "compile_clear", + TimedOutAtUtc: time.Now().UTC(), + } + if err := writeCompilePendingRecord(projectRoot, record); err != nil { + t.Fatalf("writeCompilePendingRecord failed: %v", err) + } + + clearCompilePendingRecord(projectRoot) + if _, err := os.Stat(compilePendingRecordPath(projectRoot)); !os.IsNotExist(err) { + t.Fatalf("record should be cleared: %v", err) + } + + clearCompilePendingRecord(projectRoot) +} + +// Verifies pending-record paths join .uloop and the file name with OS separators. +func TestCompilePendingRecordPathUsesOSSeparators(t *testing.T) { + projectRoot := filepath.FromSlash("/tmp/MyProject") + path := compilePendingRecordPath(projectRoot) + // Why literal FromSlash expected: building expected with the same Join helpers as the + // implementation would make this assertion tautological. + expected := filepath.FromSlash("/tmp/MyProject/.uloop/pending-compile-request.json") + if path != expected { + t.Fatalf("path mismatch: got %q want %q", path, expected) + } + if runtime.GOOS == "windows" { + if filepath.Separator != '\\' { + t.Fatal("expected Windows separator") + } + } +} diff --git a/cli/project-runner/internal/projectrunner/compile_wait.go b/cli/project-runner/internal/projectrunner/compile_wait.go index 515b9a0cfd..530acfb4b0 100644 --- a/cli/project-runner/internal/projectrunner/compile_wait.go +++ b/cli/project-runner/internal/projectrunner/compile_wait.go @@ -6,11 +6,11 @@ import ( "encoding/hex" "encoding/json" "fmt" + "math" "time" clierrors "github.com/hatayama/unity-cli-loop/common/errors" "github.com/hatayama/unity-cli-loop/common/tooldocs" - "github.com/hatayama/unity-cli-loop/common/vibelog" "github.com/hatayama/unity-cli-loop/common/clicontract" "github.com/hatayama/unity-cli-loop/common/clicore" @@ -22,13 +22,21 @@ const ( compileRequestIDParam = "RequestId" compileWaitParam = clicore.DomainReloadWaitParam compileForceParam = "ForceRecompile" + compileWaitTimeoutParam = "CompileWaitTimeoutSeconds" // Why separate from ToolReadinessTimeout (180s): launch readiness stays short. // Why 10m: worst-case blind block beats headroom. Why ≤ C# CompileResultLifetime (20m): // timed-out clients can still retrieve results by retrying uloop compile ~10m more. - compileWaitTimeout = 10 * time.Minute - compileWaitPollInterval = clicore.ToolReadinessPoll - compileStatusProbeTimeout = clicore.ToolReadinessProbeTimeout - compileResponseTimeout = 2 * time.Second + compileWaitTimeout = 10 * time.Minute + // Why warn at 20m: Unity stores compile results for CompileResultLifetime (20m). + // Waiting longer does not fail, but a timed-out retry may miss the retained result. + compileWaitTimeoutRetentionWarningSeconds = 1200 + // Why: time.Duration is int64 nanoseconds. Values above this overflow to a negative + // duration when multiplied by time.Second, which would look like an immediate timeout. + // This is an overflow guard, not a product-imposed maximum wait. + compileWaitTimeoutMaxSeconds = int64(math.MaxInt64 / int64(time.Second)) + compileWaitPollInterval = clicore.ToolReadinessPoll + compileStatusProbeTimeout = clicore.ToolReadinessProbeTimeout + compileResponseTimeout = 2 * time.Second ) type compileCompletionOptions struct { @@ -66,6 +74,59 @@ func prepareCompileWaitParams(params map[string]any) (string, error) { return requestID, nil } +// compileWaitTimeoutFromParams reads CompileWaitTimeoutSeconds from tool params. +// Missing values keep the default compileWaitTimeout (10m). Non-positive or non-integer +// values are rejected before a compile request is sent. +func compileWaitTimeoutFromParams(params map[string]any) (time.Duration, error) { + value, exists := params[compileWaitTimeoutParam] + if !exists || value == nil { + return compileWaitTimeout, nil + } + + seconds, ok := positiveInt64FromAny(value) + if !ok || seconds > compileWaitTimeoutMaxSeconds { + return 0, clierrors.InvalidValueArgumentError( + "--compile-wait-timeout-seconds", + fmt.Sprint(value), + "positive integer", + ) + } + return time.Duration(seconds) * time.Second, nil +} + +func positiveInt64FromAny(value any) (int64, bool) { + switch typed := value.(type) { + case int: + if typed <= 0 { + return 0, false + } + return int64(typed), true + case int32: + if typed <= 0 { + return 0, false + } + return int64(typed), true + case int64: + if typed <= 0 { + return 0, false + } + return typed, true + case float64: + if typed <= 0 || typed != math.Trunc(typed) || typed > float64(compileWaitTimeoutMaxSeconds) { + return 0, false + } + return int64(typed), true + case json.Number: + parsed, err := typed.Int64() + if err != nil || parsed <= 0 { + return 0, false + } + return parsed, true + default: + return 0, false + } +} + func ensureCompileRequestID(params map[string]any) (string, error) { if value, ok := params[compileRequestIDParam].(string); ok && value != "" { if isSafeCompileRequestID(value) { @@ -108,11 +169,16 @@ func isSafeCompileRequestID(requestID string) bool { return true } -func waitForCompileCompletionWithDeps(ctx context.Context, options compileCompletionOptions, deps compileWaitDeps) (json.RawMessage, bool, error) { +func waitForCompileCompletionWithDeps( + ctx context.Context, + options compileCompletionOptions, + deps compileWaitDeps, +) (json.RawMessage, bool, *compileStatusResponse, error) { startedAt := time.Now() deadline := startedAt.Add(options.timeout) attempts := 0 var lastStatus compileStatusResponse + observedStatus := false var lastErr error lastObservationKey := "" @@ -132,23 +198,32 @@ func waitForCompileCompletionWithDeps(ctx context.Context, options compileComple if err == nil && status.Ready && status.HasResult && len(status.Result) > 0 { logCompileStatusPollObservedIfChanged(options, startedAt, attempts, status, nil, &lastObservationKey) logCompileStatusPollComplete(options, startedAt, attempts, status) - return status.Result, true, nil + return status.Result, true, nil, nil } if err == nil { lastStatus = status + observedStatus = true } logCompileStatusPollObservedIfChanged(options, startedAt, attempts, status, err, &lastObservationKey) select { case <-ctx.Done(): logCompileWaitCancelled(options, startedAt, attempts, lastStatus, lastErr, ctx.Err()) - return nil, false, ctx.Err() + return nil, false, lastObservedCompileStatus(lastStatus, observedStatus), ctx.Err() case <-ticker.C: } } logCompileWaitTimedOut(options, startedAt, attempts, lastStatus, lastErr) - return nil, false, nil + return nil, false, lastObservedCompileStatus(lastStatus, observedStatus), nil +} + +func lastObservedCompileStatus(status compileStatusResponse, observed bool) *compileStatusResponse { + if !observed { + return nil + } + copied := status + return &copied } func compileForceRecompileEnabled(params map[string]any) bool { @@ -196,305 +271,3 @@ func shouldWaitForCompileStatus(err error, outcome unityipc.UnitySendOutcome) bo } return outcome.RequestAccepted && clierrors.IsFinalResponseTimeoutError(err) } - -func writeCompileVibeLog(projectRoot string, buildEntry func() vibelog.CLIVibeLogEntry) { - if !vibelog.IsCLIVibeLogEnabled() { - return - } - - writeCompileVibeLogEntry(projectRoot, buildEntry()) -} - -func writeCompileVibeLogEntry(projectRoot string, entry vibelog.CLIVibeLogEntry) { - _ = vibelog.WriteCLIVibeLog(projectRoot, entry) -} - -func logCliDebugModeResolved(connection unityipc.Connection, command string) { - writeCompileVibeLog(connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { - return vibelog.CLIVibeLogEntry{ - Level: "INFO", - Operation: "cli_debug_mode_resolved", - Message: "Resolved CLI debug mode for the command.", - Context: map[string]any{ - "command": command, - "debug_enabled": true, - "debug_source": "env", - "project_identity": vibelog.ProjectIdentity(connection.ProjectRoot), - "cli_version": clicontract.ProjectRunnerVersion(), - }, - } - }) -} - -func logCompileRequestPrepared( - connection unityipc.Connection, - params map[string]any, - requestID string, -) { - writeCompileVibeLog(connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { - reloadExternalSceneChanges := compileReloadExternalSceneChangesEnabled(params) - return vibelog.CLIVibeLogEntry{ - Level: "INFO", - Operation: "cli_compile_request_prepared", - Message: "Prepared compile request parameters before dispatch.", - Context: map[string]any{ - "command": clicore.CompileCommandName, - "request_id": requestID, - "wait_for_domain_reload": true, - "force_recompile": compileForceRecompileEnabled(params), - "reload_external_scene_changes": reloadExternalSceneChanges, - "stop_on_external_scene_changes": !reloadExternalSceneChanges, - "project_identity": vibelog.ProjectIdentity(connection.ProjectRoot), - "endpoint": connection.Endpoint.Address, - "timeout_ms": compileWaitTimeout.Milliseconds(), - "poll_interval_ms": compileWaitPollInterval.Milliseconds(), - "response_timeout_ms": compileResponseTimeout.Milliseconds(), - }, - CorrelationID: requestID, - } - }) -} - -func logCompileRequestSendResult( - connection unityipc.Connection, - requestID string, - outcome unityipc.UnitySendOutcome, - err error, - startedAt time.Time, -) { - writeCompileVibeLog(connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { - return vibelog.CLIVibeLogEntry{ - Level: compileRequestSendResultLogLevel(err), - Operation: "cli_compile_request_send_result", - Message: "Recorded compile request dispatch outcome before status polling.", - Context: map[string]any{ - "command": clicore.CompileCommandName, - "request_id": requestID, - "request_dispatched": outcome.RequestDispatched, - "request_accepted": outcome.RequestAccepted, - "response_received": err == nil && len(outcome.Result) > 0, - "response_timeout": err != nil && clierrors.IsFinalResponseTimeoutError(err), - "transport_error": clicore.ErrorMessage(err), - "elapsed_ms": time.Since(startedAt).Milliseconds(), - "endpoint": connection.Endpoint.Address, - "project_identity": vibelog.ProjectIdentity(connection.ProjectRoot), - "outcome_total_ms": outcome.Timing.Total.Milliseconds(), - "outcome_dial_ms": outcome.Timing.Dial.Milliseconds(), - "outcome_write_ms": outcome.Timing.Write.Milliseconds(), - "outcome_read_ms": outcome.Timing.Read.Milliseconds(), - "outcome_decode_ms": outcome.Timing.Decode.Milliseconds(), - }, - CorrelationID: requestID, - } - }) -} - -func compileRequestSendResultLogLevel(err error) string { - if err == nil { - return "INFO" - } - return "WARNING" -} - -func logCompileStatusPollStart( - options compileCompletionOptions, - startedAt time.Time, - deadline time.Time, -) { - writeCompileVibeLog(options.connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { - return vibelog.CLIVibeLogEntry{ - Level: "INFO", - Operation: "cli_compile_status_poll_start", - Message: "Started polling Unity compile status.", - Context: compileWaitLogContext(options, startedAt, map[string]any{ - "started_at": startedAt.UTC().Format(time.RFC3339Nano), - "deadline_at": deadline.UTC().Format(time.RFC3339Nano), - "project_identity": vibelog.ProjectIdentity(options.connection.ProjectRoot), - }), - CorrelationID: options.requestID, - } - }) -} - -func logCompileStatusPollObservedIfChanged( - options compileCompletionOptions, - startedAt time.Time, - attempt int, - status compileStatusResponse, - err error, - lastObservationKey *string, -) { - if !vibelog.IsCLIVibeLogEnabled() { - return - } - - observationKey := compileStatusObservationKey(status, err) - if observationKey == *lastObservationKey { - return - } - - *lastObservationKey = observationKey - writeCompileVibeLogEntry(options.connection.ProjectRoot, vibelog.CLIVibeLogEntry{ - Level: compileStatusPollObservedLogLevel(err), - Operation: "cli_compile_status_poll_observed", - Message: "Observed Unity compile status while polling.", - Context: compileWaitLogContext(options, startedAt, map[string]any{ - "attempt": attempt, - "ready": status.Ready, - "has_result": status.HasResult, - "is_compiling": status.IsCompiling, - "is_updating": status.IsUpdating, - "is_domain_reload_in_progress": status.IsDomainReloadInProgress, - "message": status.Message, - "transport_error": clicore.ErrorMessage(err), - }), - CorrelationID: options.requestID, - }) -} - -func compileStatusPollObservedLogLevel(err error) string { - if err == nil { - return "INFO" - } - return "WARNING" -} - -func compileStatusObservationKey(status compileStatusResponse, err error) string { - return fmt.Sprintf( - "%t|%t|%t|%t|%t|%s|%s", - status.Ready, - status.HasResult, - status.IsCompiling, - status.IsUpdating, - status.IsDomainReloadInProgress, - status.Message, - clicore.ErrorMessage(err), - ) -} - -func logCompileStatusPollComplete( - options compileCompletionOptions, - startedAt time.Time, - attempts int, - status compileStatusResponse, -) { - writeCompileVibeLog(options.connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { - summary := compileResultLogSummary(status.Result) - return vibelog.CLIVibeLogEntry{ - Level: "INFO", - Operation: "cli_compile_status_poll_complete", - Message: "Unity compile status polling returned the stored result.", - Context: compileWaitLogContext(options, startedAt, map[string]any{ - "poll_attempts": attempts, - "success": summary.success, - "error_count": summary.errorCount, - "warning_count": summary.warningCount, - }), - CorrelationID: options.requestID, - } - }) -} - -func logCompileWaitTimedOut( - options compileCompletionOptions, - startedAt time.Time, - attempts int, - lastStatus compileStatusResponse, - lastErr error, -) { - writeCompileVibeLog(options.connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { - return vibelog.CLIVibeLogEntry{ - Level: "WARNING", - Operation: "cli_compile_status_poll_timeout", - Message: "Timed out while polling Unity compile status.", - Context: compileWaitLogContext(options, startedAt, map[string]any{ - "poll_attempts": attempts, - "last_status": compileStatusLogContext(lastStatus), - "last_transport_error": clicore.ErrorMessage(lastErr), - "project_identity": vibelog.ProjectIdentity(options.connection.ProjectRoot), - }), - CorrelationID: options.requestID, - } - }) -} - -func logCompileWaitCancelled( - options compileCompletionOptions, - startedAt time.Time, - attempts int, - lastStatus compileStatusResponse, - lastErr error, - cancelErr error, -) { - writeCompileVibeLog(options.connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { - return vibelog.CLIVibeLogEntry{ - Level: "WARNING", - Operation: "cli_compile_status_poll_cancelled", - Message: "Compile status polling was cancelled.", - Context: compileWaitLogContext(options, startedAt, map[string]any{ - "poll_attempts": attempts, - "last_status": compileStatusLogContext(lastStatus), - "last_transport_error": clicore.ErrorMessage(lastErr), - "cancel_error": clicore.ErrorMessage(cancelErr), - }), - CorrelationID: options.requestID, - } - }) -} - -func compileWaitLogContext( - options compileCompletionOptions, - startedAt time.Time, - extra map[string]any, -) map[string]any { - context := map[string]any{ - "command": clicore.CompileCommandName, - "request_id": options.requestID, - "force_recompile": options.forceRecompile, - "endpoint": options.connection.Endpoint.Address, - "timeout_ms": options.timeout.Milliseconds(), - "poll_interval_ms": options.pollInterval.Milliseconds(), - "elapsed_ms": time.Since(startedAt).Milliseconds(), - } - for key, value := range extra { - context[key] = value - } - return context -} - -type compileResultSummary struct { - success any - errorCount any - warningCount any -} - -func compileResultLogSummary(result json.RawMessage) compileResultSummary { - var payload map[string]any - if err := json.Unmarshal(result, &payload); err != nil { - return compileResultSummary{} - } - return compileResultSummary{ - success: firstPresentJSONValue(payload, "Success", "success"), - errorCount: firstPresentJSONValue(payload, "ErrorCount", "errorCount"), - warningCount: firstPresentJSONValue(payload, "WarningCount", "warningCount"), - } -} - -func firstPresentJSONValue(payload map[string]any, primaryKey string, legacyKey string) any { - value, ok := payload[primaryKey] - if ok { - return value - } - return payload[legacyKey] -} - -func compileStatusLogContext(status compileStatusResponse) map[string]any { - return map[string]any{ - "ready": status.Ready, - "has_result": status.HasResult, - "is_compiling": status.IsCompiling, - "is_updating": status.IsUpdating, - "is_domain_reload_in_progress": status.IsDomainReloadInProgress, - "message": status.Message, - } -} diff --git a/cli/project-runner/internal/projectrunner/compile_wait_deps.go b/cli/project-runner/internal/projectrunner/compile_wait_deps.go index 2448503d14..e7d1cb1f04 100644 --- a/cli/project-runner/internal/projectrunner/compile_wait_deps.go +++ b/cli/project-runner/internal/projectrunner/compile_wait_deps.go @@ -2,16 +2,23 @@ package projectrunner import ( "context" + "time" "github.com/hatayama/unity-cli-loop/common/unityipc" ) type compileWaitDeps struct { - queryCompileStatus func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) + queryCompileStatus func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) + attachProbeTimeout time.Duration + attachProbeInterval time.Duration + attachWaitPollInterval time.Duration } func defaultCompileWaitDeps() compileWaitDeps { return compileWaitDeps{ - queryCompileStatus: queryCompileStatusFromUnity, + queryCompileStatus: queryCompileStatusFromUnity, + attachProbeTimeout: compileAttachProbeTimeout, + attachProbeInterval: compileAttachProbeInterval, + attachWaitPollInterval: compileWaitPollInterval, } } diff --git a/cli/project-runner/internal/projectrunner/compile_wait_log.go b/cli/project-runner/internal/projectrunner/compile_wait_log.go new file mode 100644 index 0000000000..2d3db34f10 --- /dev/null +++ b/cli/project-runner/internal/projectrunner/compile_wait_log.go @@ -0,0 +1,317 @@ +package projectrunner + +import ( + "encoding/json" + "fmt" + "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/clicontract" + "github.com/hatayama/unity-cli-loop/common/clicore" + "github.com/hatayama/unity-cli-loop/common/unityipc" +) + +func writeCompileVibeLog(projectRoot string, buildEntry func() vibelog.CLIVibeLogEntry) { + if !vibelog.IsCLIVibeLogEnabled() { + return + } + + writeCompileVibeLogEntry(projectRoot, buildEntry()) +} + +func writeCompileVibeLogEntry(projectRoot string, entry vibelog.CLIVibeLogEntry) { + _ = vibelog.WriteCLIVibeLog(projectRoot, entry) +} + +func logCliDebugModeResolved(connection unityipc.Connection, command string) { + writeCompileVibeLog(connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { + return vibelog.CLIVibeLogEntry{ + Level: "INFO", + Operation: "cli_debug_mode_resolved", + Message: "Resolved CLI debug mode for the command.", + Context: map[string]any{ + "command": command, + "debug_enabled": true, + "debug_source": "env", + "project_identity": vibelog.ProjectIdentity(connection.ProjectRoot), + "cli_version": clicontract.ProjectRunnerVersion(), + }, + } + }) +} + +func logCompileRequestPrepared( + connection unityipc.Connection, + params map[string]any, + requestID string, + waitTimeout time.Duration, +) { + writeCompileVibeLog(connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { + reloadExternalSceneChanges := compileReloadExternalSceneChangesEnabled(params) + return vibelog.CLIVibeLogEntry{ + Level: "INFO", + Operation: "cli_compile_request_prepared", + Message: "Prepared compile request parameters before dispatch.", + Context: map[string]any{ + "command": clicore.CompileCommandName, + "request_id": requestID, + "wait_for_domain_reload": true, + "force_recompile": compileForceRecompileEnabled(params), + "reload_external_scene_changes": reloadExternalSceneChanges, + "stop_on_external_scene_changes": !reloadExternalSceneChanges, + "project_identity": vibelog.ProjectIdentity(connection.ProjectRoot), + "endpoint": connection.Endpoint.Address, + "timeout_ms": waitTimeout.Milliseconds(), + "poll_interval_ms": compileWaitPollInterval.Milliseconds(), + "response_timeout_ms": compileResponseTimeout.Milliseconds(), + }, + CorrelationID: requestID, + } + }) +} + +func logCompileRequestSendResult( + connection unityipc.Connection, + requestID string, + outcome unityipc.UnitySendOutcome, + err error, + startedAt time.Time, +) { + writeCompileVibeLog(connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { + return vibelog.CLIVibeLogEntry{ + Level: compileRequestSendResultLogLevel(err), + Operation: "cli_compile_request_send_result", + Message: "Recorded compile request dispatch outcome before status polling.", + Context: map[string]any{ + "command": clicore.CompileCommandName, + "request_id": requestID, + "request_dispatched": outcome.RequestDispatched, + "request_accepted": outcome.RequestAccepted, + "response_received": err == nil && len(outcome.Result) > 0, + "response_timeout": err != nil && clierrors.IsFinalResponseTimeoutError(err), + "transport_error": clicore.ErrorMessage(err), + "elapsed_ms": time.Since(startedAt).Milliseconds(), + "endpoint": connection.Endpoint.Address, + "project_identity": vibelog.ProjectIdentity(connection.ProjectRoot), + "outcome_total_ms": outcome.Timing.Total.Milliseconds(), + "outcome_dial_ms": outcome.Timing.Dial.Milliseconds(), + "outcome_write_ms": outcome.Timing.Write.Milliseconds(), + "outcome_read_ms": outcome.Timing.Read.Milliseconds(), + "outcome_decode_ms": outcome.Timing.Decode.Milliseconds(), + }, + CorrelationID: requestID, + } + }) +} + +func compileRequestSendResultLogLevel(err error) string { + if err == nil { + return "INFO" + } + return "WARNING" +} + +func logCompileStatusPollStart( + options compileCompletionOptions, + startedAt time.Time, + deadline time.Time, +) { + writeCompileVibeLog(options.connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { + return vibelog.CLIVibeLogEntry{ + Level: "INFO", + Operation: "cli_compile_status_poll_start", + Message: "Started polling Unity compile status.", + Context: compileWaitLogContext(options, startedAt, map[string]any{ + "started_at": startedAt.UTC().Format(time.RFC3339Nano), + "deadline_at": deadline.UTC().Format(time.RFC3339Nano), + "project_identity": vibelog.ProjectIdentity(options.connection.ProjectRoot), + }), + CorrelationID: options.requestID, + } + }) +} + +func logCompileStatusPollObservedIfChanged( + options compileCompletionOptions, + startedAt time.Time, + attempt int, + status compileStatusResponse, + err error, + lastObservationKey *string, +) { + if !vibelog.IsCLIVibeLogEnabled() { + return + } + + observationKey := compileStatusObservationKey(status, err) + if observationKey == *lastObservationKey { + return + } + + *lastObservationKey = observationKey + writeCompileVibeLogEntry(options.connection.ProjectRoot, vibelog.CLIVibeLogEntry{ + Level: compileStatusPollObservedLogLevel(err), + Operation: "cli_compile_status_poll_observed", + Message: "Observed Unity compile status while polling.", + Context: compileWaitLogContext(options, startedAt, map[string]any{ + "attempt": attempt, + "ready": status.Ready, + "has_result": status.HasResult, + "is_compiling": status.IsCompiling, + "is_updating": status.IsUpdating, + "is_domain_reload_in_progress": status.IsDomainReloadInProgress, + "message": status.Message, + "transport_error": clicore.ErrorMessage(err), + }), + CorrelationID: options.requestID, + }) +} + +func compileStatusPollObservedLogLevel(err error) string { + if err == nil { + return "INFO" + } + return "WARNING" +} + +func compileStatusObservationKey(status compileStatusResponse, err error) string { + return fmt.Sprintf( + "%t|%t|%t|%t|%t|%s|%s", + status.Ready, + status.HasResult, + status.IsCompiling, + status.IsUpdating, + status.IsDomainReloadInProgress, + status.Message, + clicore.ErrorMessage(err), + ) +} + +func logCompileStatusPollComplete( + options compileCompletionOptions, + startedAt time.Time, + attempts int, + status compileStatusResponse, +) { + writeCompileVibeLog(options.connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { + summary := compileResultLogSummary(status.Result) + return vibelog.CLIVibeLogEntry{ + Level: "INFO", + Operation: "cli_compile_status_poll_complete", + Message: "Unity compile status polling returned the stored result.", + Context: compileWaitLogContext(options, startedAt, map[string]any{ + "poll_attempts": attempts, + "success": summary.success, + "error_count": summary.errorCount, + "warning_count": summary.warningCount, + }), + CorrelationID: options.requestID, + } + }) +} + +func logCompileWaitTimedOut( + options compileCompletionOptions, + startedAt time.Time, + attempts int, + lastStatus compileStatusResponse, + lastErr error, +) { + writeCompileVibeLog(options.connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { + return vibelog.CLIVibeLogEntry{ + Level: "WARNING", + Operation: "cli_compile_status_poll_timeout", + Message: "Timed out while polling Unity compile status.", + Context: compileWaitLogContext(options, startedAt, map[string]any{ + "poll_attempts": attempts, + "last_status": compileStatusLogContext(lastStatus), + "last_transport_error": clicore.ErrorMessage(lastErr), + "project_identity": vibelog.ProjectIdentity(options.connection.ProjectRoot), + }), + CorrelationID: options.requestID, + } + }) +} + +func logCompileWaitCancelled( + options compileCompletionOptions, + startedAt time.Time, + attempts int, + lastStatus compileStatusResponse, + lastErr error, + cancelErr error, +) { + writeCompileVibeLog(options.connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { + return vibelog.CLIVibeLogEntry{ + Level: "WARNING", + Operation: "cli_compile_status_poll_cancelled", + Message: "Compile status polling was cancelled.", + Context: compileWaitLogContext(options, startedAt, map[string]any{ + "poll_attempts": attempts, + "last_status": compileStatusLogContext(lastStatus), + "last_transport_error": clicore.ErrorMessage(lastErr), + "cancel_error": clicore.ErrorMessage(cancelErr), + }), + CorrelationID: options.requestID, + } + }) +} + +func compileWaitLogContext( + options compileCompletionOptions, + startedAt time.Time, + extra map[string]any, +) map[string]any { + context := map[string]any{ + "command": clicore.CompileCommandName, + "request_id": options.requestID, + "force_recompile": options.forceRecompile, + "endpoint": options.connection.Endpoint.Address, + "timeout_ms": options.timeout.Milliseconds(), + "poll_interval_ms": options.pollInterval.Milliseconds(), + "elapsed_ms": time.Since(startedAt).Milliseconds(), + } + for key, value := range extra { + context[key] = value + } + return context +} + +type compileResultSummary struct { + success any + errorCount any + warningCount any +} + +func compileResultLogSummary(result json.RawMessage) compileResultSummary { + var payload map[string]any + if err := json.Unmarshal(result, &payload); err != nil { + return compileResultSummary{} + } + return compileResultSummary{ + success: firstPresentJSONValue(payload, "Success", "success"), + errorCount: firstPresentJSONValue(payload, "ErrorCount", "errorCount"), + warningCount: firstPresentJSONValue(payload, "WarningCount", "warningCount"), + } +} + +func firstPresentJSONValue(payload map[string]any, primaryKey string, legacyKey string) any { + value, ok := payload[primaryKey] + if ok { + return value + } + return payload[legacyKey] +} + +func compileStatusLogContext(status compileStatusResponse) map[string]any { + return map[string]any{ + "ready": status.Ready, + "has_result": status.HasResult, + "is_compiling": status.IsCompiling, + "is_updating": status.IsUpdating, + "is_domain_reload_in_progress": status.IsDomainReloadInProgress, + "message": status.Message, + } +} diff --git a/cli/project-runner/internal/projectrunner/compile_wait_test.go b/cli/project-runner/internal/projectrunner/compile_wait_test.go index 7c80852b3c..934e919ea2 100644 --- a/cli/project-runner/internal/projectrunner/compile_wait_test.go +++ b/cli/project-runner/internal/projectrunner/compile_wait_test.go @@ -7,6 +7,7 @@ import ( "encoding/json" "fmt" "net" + "path/filepath" "runtime" "strings" "testing" @@ -14,6 +15,7 @@ import ( clierrors "github.com/hatayama/unity-cli-loop/common/errors" "github.com/hatayama/unity-cli-loop/common/tooldocs" + "github.com/hatayama/unity-cli-loop/common/vibelog" "github.com/hatayama/unity-cli-loop/common/clicore" "github.com/hatayama/unity-cli-loop/common/unityipc" @@ -183,7 +185,7 @@ func TestWaitForCompileCompletionReturnsReadyStatusResult(t *testing.T) { return compileStatusResponse{Ready: true, HasResult: true, Result: json.RawMessage(`{"Success":true}`)}, nil }) - result, completed, err := waitForCompileCompletionWithDeps(context.Background(), compileCompletionOptions{ + result, completed, _, err := waitForCompileCompletionWithDeps(context.Background(), compileCompletionOptions{ connection: connection, requestID: requestID, timeout: time.Second, @@ -224,7 +226,7 @@ func TestWaitForCompileCompletionWritesPollLifecycleVibeLogs(t *testing.T) { }, nil }) - result, completed, err := waitForCompileCompletionWithDeps(context.Background(), compileCompletionOptions{ + result, completed, _, err := waitForCompileCompletionWithDeps(context.Background(), compileCompletionOptions{ connection: connection, requestID: requestID, timeout: time.Second, @@ -274,7 +276,7 @@ func TestWaitForCompileCompletionForceCompileWaitsForStoredResult(t *testing.T) }, nil }) - result, completed, err := waitForCompileCompletionWithDeps(context.Background(), compileCompletionOptions{ + result, completed, _, err := waitForCompileCompletionWithDeps(context.Background(), compileCompletionOptions{ connection: connection, requestID: requestID, forceRecompile: true, @@ -315,7 +317,7 @@ func TestWaitForCompileCompletionForceCompileTimesOutWithoutStoredResult(t *test return compileStatusResponse{Ready: true, HasResult: false}, nil }) - _, completed, err := waitForCompileCompletionWithDeps(context.Background(), compileCompletionOptions{ + _, completed, _, err := waitForCompileCompletionWithDeps(context.Background(), compileCompletionOptions{ connection: connection, requestID: requestID, forceRecompile: true, @@ -339,7 +341,7 @@ func TestWaitForCompileCompletionWritesTimeoutVibeLog(t *testing.T) { return compileStatusResponse{Ready: false, IsCompiling: true, Message: "Compiling"}, nil }) - _, completed, err := waitForCompileCompletionWithDeps(context.Background(), compileCompletionOptions{ + _, completed, _, err := waitForCompileCompletionWithDeps(context.Background(), compileCompletionOptions{ connection: connection, requestID: requestID, timeout: 20 * time.Millisecond, @@ -378,7 +380,7 @@ func TestWaitForCompileCompletionWritesCancellationVibeLog(t *testing.T) { return compileStatusResponse{Ready: false, IsDomainReloadInProgress: true}, nil }) - _, completed, err := waitForCompileCompletionWithDeps(ctx, compileCompletionOptions{ + _, completed, _, err := waitForCompileCompletionWithDeps(ctx, compileCompletionOptions{ connection: connection, requestID: requestID, timeout: time.Second, @@ -411,42 +413,7 @@ func TestRunCompileWithDomainReloadWaitWritesRequestLifecycleVibeLogs(t *testing } enableCliVibeLog(t) - listener, err := net.Listen("tcp", "127.0.0.1:0") - if err != nil { - t.Fatalf("failed to listen: %v", err) - } - defer func() { - _ = listener.Close() - }() - - serverErr := make(chan error, 1) - go func() { - conn, err := listener.Accept() - if err != nil { - serverErr <- err - return - } - defer func() { - _ = conn.Close() - }() - - if _, err := unityipc.Read(bufio.NewReader(conn)); err != nil { - serverErr <- err - return - } - - accepted := []byte(`{"jsonrpc":"2.0","result":{"accepted":true},"uloop":{"phase":"accepted"},"id":1}`) - if err := unityipc.Write(conn, accepted); err != nil { - serverErr <- err - return - } - - final := []byte(`{"jsonrpc":"2.0","result":{"Accepted":true},"id":1}`) - if err := unityipc.Write(conn, final); err != nil { - serverErr <- err - return - } - }() + endpoint, serverErr := startCompileAcceptOnceServer(t) deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { return compileStatusResponse{ @@ -458,10 +425,7 @@ func TestRunCompileWithDomainReloadWaitWritesRequestLifecycleVibeLogs(t *testing projectRoot := t.TempDir() connection := unityipc.Connection{ - Endpoint: unityipc.Endpoint{ - Network: "tcp", - Address: listener.Addr().String(), - }, + Endpoint: endpoint, ProjectRoot: projectRoot, } params := map[string]any{ @@ -487,6 +451,7 @@ func TestRunCompileWithDomainReloadWaitWritesRequestLifecycleVibeLogs(t *testing `"response_received":true`, `"force_recompile":true`, `"reload_external_scene_changes":false`, + `"timeout_ms":600000`, } { if !strings.Contains(logContent, expected) { t.Fatalf("CLI Vibe log missing %q:\n%s", expected, logContent) @@ -500,6 +465,184 @@ func TestRunCompileWithDomainReloadWaitWritesRequestLifecycleVibeLogs(t *testing } } +// Verifies runCompileWithDomainReloadWaitWithDeps wires CompileWaitTimeoutSeconds into +// the wait deadline and COMPILE_WAIT_TIMEOUT message (not only the wait helper itself). +func TestRunCompileWithDomainReloadWaitUsesConfiguredTimeout(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("TCP endpoint injection is only used by this non-Windows client test") + } + + enableCliVibeLog(t) + endpoint, serverErr := startCompileAcceptOnceServer(t) + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + return compileStatusResponse{Ready: false, IsCompiling: true, Message: "Compiling"}, nil + }) + + projectRoot := t.TempDir() + connection := unityipc.Connection{ + Endpoint: endpoint, + ProjectRoot: projectRoot, + } + params := map[string]any{ + compileWaitTimeoutParam: 1, + } + var stdout bytes.Buffer + var stderr bytes.Buffer + + code := runCompileWithDomainReloadWaitWithDeps(context.Background(), connection, params, &stdout, &stderr, deps) + if code != 1 { + t.Fatalf("expected timeout exit 1: code=%d stdout=%s stderr=%s", code, stdout.String(), stderr.String()) + } + if !strings.Contains(stderr.String(), "Compile status wait timed out after 1000ms") { + t.Fatalf("timeout message missing configured duration: %s", stderr.String()) + } + if !strings.Contains(stderr.String(), `"ErrorCode": "COMPILE_WAIT_TIMEOUT"`) && + !strings.Contains(stderr.String(), `"ErrorCode":"COMPILE_WAIT_TIMEOUT"`) { + t.Fatalf("expected COMPILE_WAIT_TIMEOUT envelope: %s", stderr.String()) + } + assertCompileWaitTimeoutEnvelopeDetails(t, stderr.Bytes(), true) + + logContent := readOnlyCliVibeLog(t, projectRoot) + if !strings.Contains(logContent, `"timeout_ms":1000`) { + t.Fatalf("prepared vibe log should record configured timeout_ms=1000:\n%s", logContent) + } + + select { + case err := <-serverErr: + t.Fatalf("server failed: %v", err) + default: + } +} + +// Verifies invalid CompileWaitTimeoutSeconds fails before a compile request is dispatched. +func TestRunCompileWithDomainReloadWaitRejectsNonPositiveTimeout(t *testing.T) { + enableCliVibeLog(t) + projectRoot := t.TempDir() + connection := unityipc.Connection{ + Endpoint: unityipc.Endpoint{ + Network: "tcp", + Address: "127.0.0.1:1", + }, + ProjectRoot: projectRoot, + } + params := map[string]any{ + compileWaitTimeoutParam: 0, + } + var stdout bytes.Buffer + var stderr bytes.Buffer + queryCalls := 0 + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + queryCalls++ + return compileStatusResponse{}, nil + }) + + code := runCompileWithDomainReloadWaitWithDeps(context.Background(), connection, params, &stdout, &stderr, deps) + if code != 1 { + t.Fatalf("expected invalid timeout exit 1: code=%d stderr=%s", code, stderr.String()) + } + if queryCalls != 0 { + t.Fatalf("compile status must not be queried for invalid timeout: calls=%d", queryCalls) + } + logFiles, err := filepath.Glob(filepath.Join(projectRoot, vibelog.CLIVibeLogDirectory, vibelog.CLIVibeLogPrefix+"_*.json")) + if err != nil { + t.Fatalf("failed to glob CLI Vibe logs: %v", err) + } + if len(logFiles) != 0 { + t.Fatalf("compile request must not write vibe logs for invalid timeout: %#v", logFiles) + } + if !strings.Contains(stderr.String(), "positive integer") { + t.Fatalf("expected positive integer validation error: %s", stderr.String()) + } +} + +// Verifies timeouts above the Unity result retention window warn on stderr before compile proceeds. +func TestRunCompileWithDomainReloadWaitWarnsWhenTimeoutExceedsRetention(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("TCP endpoint injection is only used by this non-Windows client test") + } + + endpoint, serverErr := startCompileAcceptOnceServer(t) + // Why Success:false: Success:true triggers post-compile warmup against a live Editor + // and would hang this unit test. The warning is emitted before send/wait. + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + return compileStatusResponse{ + Ready: true, + HasResult: true, + Result: json.RawMessage(`{"Success":false,"ErrorCount":1,"WarningCount":0}`), + }, nil + }) + + connection := unityipc.Connection{ + Endpoint: endpoint, + ProjectRoot: t.TempDir(), + } + params := map[string]any{ + compileWaitTimeoutParam: compileWaitTimeoutRetentionWarningSeconds + 1, + } + var stdout bytes.Buffer + var stderr bytes.Buffer + + code := runCompileWithDomainReloadWaitWithDeps(context.Background(), connection, params, &stdout, &stderr, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope exit 1: code=%d stdout=%s stderr=%s", code, stdout.String(), stderr.String()) + } + if !strings.Contains(stderr.String(), "exceeds the Unity-side compile result retention window (20 minutes)") { + t.Fatalf("expected retention warning on stderr: %s", stderr.String()) + } + + select { + case err := <-serverErr: + t.Fatalf("server failed: %v", err) + default: + } +} + +// startCompileAcceptOnceServer accepts one compile IPC session and returns accepted + final responses. +func startCompileAcceptOnceServer(t *testing.T) (unityipc.Endpoint, <-chan error) { + t.Helper() + listener, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatalf("failed to listen: %v", err) + } + t.Cleanup(func() { + _ = listener.Close() + }) + + serverErr := make(chan error, 1) + go func() { + conn, acceptErr := listener.Accept() + if acceptErr != nil { + serverErr <- acceptErr + return + } + defer func() { + _ = conn.Close() + }() + + if _, readErr := unityipc.Read(bufio.NewReader(conn)); readErr != nil { + serverErr <- readErr + return + } + + accepted := []byte(`{"jsonrpc":"2.0","result":{"accepted":true},"uloop":{"phase":"accepted"},"id":1}`) + if writeErr := unityipc.Write(conn, accepted); writeErr != nil { + serverErr <- writeErr + return + } + + final := []byte(`{"jsonrpc":"2.0","result":{"Accepted":true},"id":1}`) + if writeErr := unityipc.Write(conn, final); writeErr != nil { + serverErr <- writeErr + return + } + }() + + return unityipc.Endpoint{ + Network: "tcp", + Address: listener.Addr().String(), + }, serverErr +} + func TestShouldWaitForCompileStatusRequiresDispatchedTransportError(t *testing.T) { if shouldWaitForCompileStatus(fmt.Errorf("missing"), unityipc.UnitySendOutcome{}) { t.Fatal("undispatched error should not wait") @@ -552,11 +695,127 @@ func TestWritePostCompileWarmupWarningReportsNonFatalFailure(t *testing.T) { } } +// Verifies CompileWaitTimeoutSeconds is parsed from tool params with the default +// kept when absent and non-positive or non-integer values rejected. +func TestCompileWaitTimeoutFromParams(t *testing.T) { + cases := []struct { + name string + params map[string]any + want time.Duration + wantErr bool + }{ + { + name: "missing uses default", + params: map[string]any{}, + want: compileWaitTimeout, + }, + { + name: "nil value uses default", + params: map[string]any{compileWaitTimeoutParam: nil}, + want: compileWaitTimeout, + }, + { + name: "int value", + params: map[string]any{compileWaitTimeoutParam: 90}, + want: 90 * time.Second, + }, + { + name: "float64 whole number", + params: map[string]any{compileWaitTimeoutParam: float64(120)}, + want: 120 * time.Second, + }, + { + name: "json.Number", + params: map[string]any{compileWaitTimeoutParam: json.Number("45")}, + want: 45 * time.Second, + }, + { + name: "zero is rejected", + params: map[string]any{compileWaitTimeoutParam: 0}, + wantErr: true, + }, + { + name: "negative is rejected", + params: map[string]any{compileWaitTimeoutParam: -1}, + wantErr: true, + }, + { + name: "non-integer float is rejected", + params: map[string]any{compileWaitTimeoutParam: 1.5}, + wantErr: true, + }, + { + name: "max representable duration is accepted", + params: map[string]any{compileWaitTimeoutParam: compileWaitTimeoutMaxSeconds}, + want: time.Duration(compileWaitTimeoutMaxSeconds) * time.Second, + }, + { + name: "overflowing duration is rejected", + params: map[string]any{compileWaitTimeoutParam: compileWaitTimeoutMaxSeconds + 1}, + wantErr: true, + }, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + got, err := compileWaitTimeoutFromParams(tc.params) + if tc.wantErr { + if err == nil { + t.Fatal("expected error") + } + return + } + if err != nil { + t.Fatalf("unexpected error: %v", err) + } + if got != tc.want { + t.Fatalf("timeout mismatch: got %v want %v", got, tc.want) + } + }) + } +} + +// Verifies waitForCompileCompletionWithDeps stops when the configured timeout elapses +// instead of waiting for the default compileWaitTimeout. +func TestWaitForCompileCompletionRespectsConfiguredTimeout(t *testing.T) { + connection := compileWaitTestConnection(t) + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + return compileStatusResponse{Ready: false, IsCompiling: true}, nil + }) + + startedAt := time.Now() + _, completed, _, err := waitForCompileCompletionWithDeps(context.Background(), compileCompletionOptions{ + connection: connection, + requestID: "compile_configured_timeout", + timeout: 40 * time.Millisecond, + pollInterval: 5 * time.Millisecond, + }, deps) + elapsed := time.Since(startedAt) + if err != nil { + t.Fatalf("waitForCompileCompletion failed: %v", err) + } + if completed { + t.Fatal("compile wait should time out while still compiling") + } + if elapsed < 40*time.Millisecond { + t.Fatalf("timed out too early: %v", elapsed) + } + if elapsed > 500*time.Millisecond { + t.Fatalf("timed out too late for a 40ms deadline: %v", elapsed) + } +} + // Tests that compile wait timeout guidance teaches the caller to verify Editor // responsiveness instead of assuming a freeze, because agents have terminated // whole sessions after misreading this timeout as a frozen Editor. func TestCompileWaitTimeoutError(t *testing.T) { - cliErr := compileWaitTimeoutError("/tmp/MyProject") + cliErr := compileWaitTimeoutError( + "/tmp/MyProject", + 90*time.Second, + nil, + 90*time.Second, + compilePendingRecordLifetime-90*time.Second, + ) if cliErr.ErrorCode != clierrors.ErrorCodeCompileWaitTimeout { t.Fatalf("error code mismatch: %#v", cliErr) @@ -567,13 +826,13 @@ func TestCompileWaitTimeoutError(t *testing.T) { if cliErr.ProjectRoot != "/tmp/MyProject" { t.Fatalf("project root mismatch: %#v", cliErr) } - expectedMessage := "Compile status wait timed out after 600000ms. This does not mean the Unity Editor is frozen; the compile may simply still be running." + expectedMessage := "Compile status wait timed out after 90000ms. This does not mean the Unity Editor is frozen; the compile may simply still be running." if cliErr.Message != expectedMessage { t.Fatalf("message mismatch: %#v", cliErr.Message) } expectedActions := []string{ "Run a light command such as `uloop get-logs --max-count 1` to check whether Unity is responsive before treating this as a freeze.", - "Unity-side compile continues after this timeout; retry `uloop compile` — the result remains retrievable for about 10 more minutes without `uloop launch -r`.", + "Unity keeps compiling and refuses other commands with UNITY_SERVER_BUSY until it finishes. Re-run `uloop compile`: it will reattach to the in-flight compile and wait for its result instead of starting a new one. The result stays retrievable for roughly 18 more minutes.", clierrors.ApiUpdateConsentModalNextAction, "Only if Unity does not respond to any command, restart it with `uloop launch -r`.", } @@ -582,11 +841,154 @@ func TestCompileWaitTimeoutError(t *testing.T) { } for i, expected := range expectedActions { if cliErr.NextActions[i] != expected { - t.Fatalf("next action %d mismatch: %#v", i, cliErr.NextActions) + t.Fatalf("next action %d mismatch:\n got: %#v\nwant: %#v", i, cliErr.NextActions[i], expected) } } } +// Verifies a wait that consumes the full retention window omits the remaining-minutes sentence. +func TestCompileWaitTimeoutErrorOmitsRemainingMinutesWhenNoneLeft(t *testing.T) { + cliErr := compileWaitTimeoutError( + "/tmp/MyProject", + compilePendingRecordLifetime, + nil, + compilePendingRecordLifetime, + 0, + ) + reattach := cliErr.NextActions[1] + if strings.Contains(reattach, "retrievable for roughly") { + t.Fatalf("remaining-minutes sentence should be omitted: %#v", reattach) + } + if !strings.Contains(reattach, "reattach to the in-flight compile") { + t.Fatalf("reattach guidance missing: %#v", reattach) + } +} + +// Verifies NextActions use the caller-supplied retentionRemaining instead of (TTL - timeout). +func TestCompileWaitTimeoutErrorUsesCallerRetentionRemaining(t *testing.T) { + cliErr := compileWaitTimeoutError( + "/tmp/MyProject", + 10*time.Minute, + nil, + 10*time.Minute, + time.Minute, + ) + reattach := cliErr.NextActions[1] + if strings.Contains(reattach, "roughly 10 more minutes") { + t.Fatalf("must not derive remaining from wait timeout: %#v", reattach) + } + if !strings.Contains(reattach, "roughly 1 more minutes") { + t.Fatalf("must use caller retentionRemaining: %#v", reattach) + } +} + +// Verifies COMPILE_WAIT_TIMEOUT Details include the last observed status flags and WaitedMs. +func TestCompileWaitTimeoutErrorIncludesLastObservedStatusDetails(t *testing.T) { + lastStatus := &compileStatusResponse{ + IsCompiling: true, + IsUpdating: false, + IsDomainReloadInProgress: true, + } + cliErr := compileWaitTimeoutError( + "/tmp/MyProject", + time.Second, + lastStatus, + 1234*time.Millisecond, + compilePendingRecordLifetime-time.Second, + ) + if cliErr.Details["WaitedMs"] != int64(1234) { + t.Fatalf("WaitedMs mismatch: %#v", cliErr.Details["WaitedMs"]) + } + if cliErr.Details["IsCompiling"] != true { + t.Fatalf("IsCompiling mismatch: %#v", cliErr.Details) + } + if cliErr.Details["IsUpdating"] != false { + t.Fatalf("IsUpdating mismatch: %#v", cliErr.Details) + } + if cliErr.Details["IsDomainReloadInProgress"] != true { + t.Fatalf("IsDomainReloadInProgress mismatch: %#v", cliErr.Details) + } +} + +// Verifies timeout Details omit status flags when no compile status was observed. +func TestCompileWaitTimeoutErrorOmitsStatusDetailsWhenUnobserved(t *testing.T) { + cliErr := compileWaitTimeoutError( + "/tmp/MyProject", + time.Second, + nil, + time.Second, + compilePendingRecordLifetime-time.Second, + ) + if _, ok := cliErr.Details["IsCompiling"]; ok { + t.Fatalf("IsCompiling should be omitted without an observation: %#v", cliErr.Details) + } + if cliErr.Details["WaitedMs"] != int64(1000) { + t.Fatalf("WaitedMs mismatch: %#v", cliErr.Details["WaitedMs"]) + } +} + +// Verifies the wait helper returns the last successful status observation on timeout. +func TestWaitForCompileCompletionReturnsLastStatusOnTimeout(t *testing.T) { + connection := compileWaitTestConnection(t) + deps := compileWaitTestDeps(func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + return compileStatusResponse{ + Ready: false, + IsCompiling: true, + IsDomainReloadInProgress: true, + }, nil + }) + + _, completed, lastStatus, err := waitForCompileCompletionWithDeps(context.Background(), compileCompletionOptions{ + connection: connection, + requestID: "compile_last_status", + timeout: 30 * time.Millisecond, + pollInterval: 5 * time.Millisecond, + }, deps) + if err != nil { + t.Fatalf("waitForCompileCompletion failed: %v", err) + } + if completed { + t.Fatal("expected timeout") + } + if lastStatus == nil { + t.Fatal("expected last observed status") + } + if !lastStatus.IsCompiling || !lastStatus.IsDomainReloadInProgress { + t.Fatalf("last status mismatch: %#v", lastStatus) + } +} + +// assertCompileWaitTimeoutEnvelopeDetails checks the run/attach wiring that passes +// lastStatus and WaitedMs into the COMPILE_WAIT_TIMEOUT stderr envelope. +func assertCompileWaitTimeoutEnvelopeDetails(t *testing.T, stderr []byte, wantCompiling bool) { + t.Helper() + jsonStart := bytes.IndexByte(stderr, '{') + if jsonStart < 0 { + t.Fatalf("stderr has no JSON envelope: %s", string(stderr)) + } + var envelope clierrors.CLIErrorEnvelope + if err := json.Unmarshal(stderr[jsonStart:], &envelope); err != nil { + t.Fatalf("stderr is not a JSON error envelope: %v\n%s", err, string(stderr)) + } + if envelope.Error.ErrorCode != clierrors.ErrorCodeCompileWaitTimeout { + t.Fatalf("error code mismatch: %#v", envelope.Error.ErrorCode) + } + details := envelope.Error.Details + if details == nil { + t.Fatal("COMPILE_WAIT_TIMEOUT Details missing") + } + if details["IsCompiling"] != wantCompiling { + t.Fatalf("IsCompiling mismatch: %#v", details["IsCompiling"]) + } + waitedMs, ok := details["WaitedMs"].(float64) + if !ok { + t.Fatalf("WaitedMs missing or wrong type: %#v", details["WaitedMs"]) + } + if waitedMs < 1000 { + t.Fatalf("WaitedMs should cover the configured 1s wait: %#v", waitedMs) + } +} + func compileWaitTestConnection(t *testing.T) unityipc.Connection { t.Helper() return unityipc.Connection{ @@ -602,6 +1004,9 @@ func compileWaitTestDeps( replacement func(context.Context, unityipc.Connection, string) (compileStatusResponse, error), ) compileWaitDeps { return compileWaitDeps{ - queryCompileStatus: replacement, + queryCompileStatus: replacement, + attachProbeTimeout: 40 * time.Millisecond, + attachProbeInterval: 5 * time.Millisecond, + attachWaitPollInterval: 5 * time.Millisecond, } } diff --git a/cli/project-runner/internal/projectrunner/execution_errors.go b/cli/project-runner/internal/projectrunner/execution_errors.go index a1bf1261d1..e00b72b6f8 100644 --- a/cli/project-runner/internal/projectrunner/execution_errors.go +++ b/cli/project-runner/internal/projectrunner/execution_errors.go @@ -2,31 +2,72 @@ package projectrunner import ( "fmt" + "time" clierrors "github.com/hatayama/unity-cli-loop/common/errors" "github.com/hatayama/unity-cli-loop/common/clicore" ) -func compileWaitTimeoutError(projectRoot string) clierrors.CLIError { +func compileWaitTimeoutError( + projectRoot string, + timeout time.Duration, + lastStatus *compileStatusResponse, + waited time.Duration, + retentionRemaining time.Duration, +) clierrors.CLIError { return clierrors.CLIError{ ErrorCode: clierrors.ErrorCodeCompileWaitTimeout, Phase: clierrors.ErrorPhaseCompileWaiting, Message: fmt.Sprintf( "Compile status wait timed out after %dms. This does not mean the Unity Editor is frozen; the compile may simply still be running.", - compileWaitTimeout.Milliseconds()), + timeout.Milliseconds()), Retryable: true, SafeToRetry: true, ProjectRoot: projectRoot, Command: clicore.CompileCommandName, // Why: agents historically treated this timeout as a frozen Editor and ran - // launch -r. The real recovery path is retrying compile while C# still holds - // the result (CompileResultLifetime 20m = wait 10m + ~10m retrievable window). - NextActions: []string{ - "Run a light command such as `uloop get-logs --max-count 1` to check whether Unity is responsive before treating this as a freeze.", - "Unity-side compile continues after this timeout; retry `uloop compile` — the result remains retrievable for about 10 more minutes without `uloop launch -r`.", - clierrors.ApiUpdateConsentModalNextAction, - "Only if Unity does not respond to any command, restart it with `uloop launch -r`.", - }, + // launch -r. Recovery is reattach via a later uloop compile while Unity still + // holds the result (CompileResultLifetime / compilePendingRecordLifetime). + NextActions: compileWaitTimeoutNextActions(retentionRemaining), + Details: compileWaitTimeoutDetails(lastStatus, waited), + } +} + +func compileWaitTimeoutDetails(lastStatus *compileStatusResponse, waited time.Duration) map[string]any { + details := map[string]any{ + "WaitedMs": waited.Milliseconds(), + } + if lastStatus == nil { + return details + } + details["IsCompiling"] = lastStatus.IsCompiling + details["IsUpdating"] = lastStatus.IsUpdating + details["IsDomainReloadInProgress"] = lastStatus.IsDomainReloadInProgress + return details +} + +func compileWaitTimeoutNextActions(retentionRemaining time.Duration) []string { + reattachAction := "Unity keeps compiling and refuses other commands with UNITY_SERVER_BUSY until it finishes. Re-run `uloop compile`: it will reattach to the in-flight compile and wait for its result instead of starting a new one." + // Why the caller passes remaining: attach re-timeouts keep the original TimedOutAtUtc, + // so remaining retention is wall-clock from that first timeout, not (TTL - this wait). + remaining := retentionRemaining + if remaining < 0 { + remaining = 0 + } + remainingMinutes := int(remaining / time.Minute) + if remainingMinutes > 0 { + reattachAction = fmt.Sprintf( + "%s The result stays retrievable for roughly %d more minutes.", + reattachAction, + remainingMinutes, + ) + } + + return []string{ + "Run a light command such as `uloop get-logs --max-count 1` to check whether Unity is responsive before treating this as a freeze.", + reattachAction, + clierrors.ApiUpdateConsentModalNextAction, + "Only if Unity does not respond to any command, restart it with `uloop launch -r`.", } } diff --git a/cli/project-runner/internal/projectrunner/run.go b/cli/project-runner/internal/projectrunner/run.go index 39b86ede22..d4caeac7d0 100644 --- a/cli/project-runner/internal/projectrunner/run.go +++ b/cli/project-runner/internal/projectrunner/run.go @@ -165,6 +165,25 @@ func runCompileWithDomainReloadWaitWithDeps( stderr io.Writer, compileWait compileWaitDeps, ) int { + waitTimeout, timeoutErr := compileWaitTimeoutFromParams(params) + if timeoutErr != nil { + clierrors.WriteClassifiedError(stderr, timeoutErr, clierrors.ErrorContext{ + ProjectRoot: connection.ProjectRoot, + Command: clicore.CompileCommandName, + }) + return 1 + } + if waitTimeout > time.Duration(compileWaitTimeoutRetentionWarningSeconds)*time.Second { + _, _ = fmt.Fprintf( + stderr, + "warning: --compile-wait-timeout-seconds exceeds the Unity-side compile result retention window (20 minutes); if the wait times out, the result may expire before a retry can recover it.\n", + ) + } + + if handled, code := tryAttachToPendingCompile(ctx, connection, params, waitTimeout, stdout, stderr, compileWait); handled { + return code + } + requestID, err := prepareCompileWaitParams(params) if err != nil { clierrors.WriteClassifiedError(stderr, err, clierrors.ErrorContext{ @@ -175,7 +194,7 @@ func runCompileWithDomainReloadWaitWithDeps( } logCliDebugModeResolved(connection, clicore.CompileCommandName) - logCompileRequestPrepared(connection, params, requestID) + logCompileRequestPrepared(connection, params, requestID, waitTimeout) startedAt := time.Now() spinner := clicore.NewToolSpinner(stderr, clicore.CompileCommandName) @@ -201,11 +220,12 @@ func runCompileWithDomainReloadWaitWithDeps( } spinner.Update("Waiting for domain reload to complete...") - result, completed, waitErr := waitForCompileCompletionWithDeps(ctx, compileCompletionOptions{ + waitStartedAt := time.Now() + result, completed, lastStatus, waitErr := waitForCompileCompletionWithDeps(ctx, compileCompletionOptions{ connection: connection, requestID: requestID, forceRecompile: compileForceRecompileEnabled(params), - timeout: compileWaitTimeout, + timeout: waitTimeout, pollInterval: compileWaitPollInterval, }, compileWait) if waitErr != nil { @@ -218,21 +238,17 @@ func runCompileWithDomainReloadWaitWithDeps( } if !completed { spinner.Stop() - clierrors.WriteErrorEnvelope(stderr, compileWaitTimeoutError(connection.ProjectRoot)) + persistCompilePendingRecordOrWarn(connection.ProjectRoot, requestID, stderr) + clierrors.WriteErrorEnvelope(stderr, compileWaitTimeoutError( + connection.ProjectRoot, + waitTimeout, + lastStatus, + time.Since(waitStartedAt), + compilePendingRecordLifetime-waitTimeout, + )) return 1 } - switch compileResultReadinessWaitMode(result) { - case compileReadinessWaitWarmup: - spinner.Update("Warming execute-dynamic-code after compile...") - if err := clicore.WaitForToolReadiness(ctx, connection.ProjectRoot); err != nil { - spinner.Stop() - writePostCompileWarmupWarning(stderr, err) - } - } - spinner.Stop() - clicore.WriteJSON(stdout, result) - writeDebugTiming(stderr, clicore.CompileCommandName, time.Since(startedAt), outcome) - return toolEnvelopeExitCode(result) + return completeCompileResultOutput(ctx, connection, result, stdout, stderr, spinner, startedAt, outcome) } func writePostCompileWarmupWarning(stderr io.Writer, err error) { diff --git a/cli/project-runner/shared-inputs-stamp.json b/cli/project-runner/shared-inputs-stamp.json index b542791c75..d536489edc 100644 --- a/cli/project-runner/shared-inputs-stamp.json +++ b/cli/project-runner/shared-inputs-stamp.json @@ -1,4 +1,4 @@ { "schemaVersion": 1, - "sharedInputsHash": "d6266127571e15b8979a320e29d659c5f246d4c3" + "sharedInputsHash": "620c09181440d0c45707c8507839b5dab37c73cc" }