From 2c08f5a631cb86d8787dc1edd54a3cd0fb241b67 Mon Sep 17 00:00:00 2001 From: hatayama Date: Wed, 30 Sep 2026 03:34:46 +0900 Subject: [PATCH 1/2] Keep waiting on a compile whose status probe goes unanswered After COMPILE_WAIT_TIMEOUT, rerunning uloop compile is supposed to reattach to the in-flight compile, as the COMPILE_WAIT_TIMEOUT and UNITY_SERVER_BUSY next actions promise. While that compile blocked the Editor's main thread, the get-compile-status probe timed out, the command sent a new compile instead, and single-flight rejected it as UNITY_SERVER_BUSY (#3032). Unity writes the dispatch ack from its IPC thread before it switches to the main thread, so a probe that runs out of time after the ack shows the server is alive and only the main thread is blocked. That case now enters the existing attach wait. A timeout before the ack, a failed connection, any other error, and the caller's own deadline keep the old path: a new compile, with the pending record kept. - The status query keeps the send outcome and marks an acknowledged timeout, the same rule shouldWaitForCompileStatus applies to a new compile. - The probe decides on its last query's error, the Editor's latest state. - Each failed probe is logged with the path taken as cli_compile_attach_probe_failed, since #3032 could not be traced from the CLI Vibe log. The same path also serves the run-tests implicit compile and the hot-reload compile fallback. --- .../internal/projectrunner/compile_attach.go | 48 +- .../compile_attach_probe_test.go | 423 ++++++++++++++++++ .../compile_status_query_test.go | 95 ++++ .../internal/projectrunner/compile_wait.go | 40 +- 4 files changed, 597 insertions(+), 9 deletions(-) create mode 100644 cli/project-runner/internal/projectrunner/compile_attach_probe_test.go create mode 100644 cli/project-runner/internal/projectrunner/compile_status_query_test.go diff --git a/cli/project-runner/internal/projectrunner/compile_attach.go b/cli/project-runner/internal/projectrunner/compile_attach.go index b6a8afe674..29c1d29909 100644 --- a/cli/project-runner/internal/projectrunner/compile_attach.go +++ b/cli/project-runner/internal/projectrunner/compile_attach.go @@ -46,10 +46,20 @@ func tryAttachToPendingCompile( return false, compileExecutionResult{} } - status, probed := probePendingCompileStatus(ctx, connection, record.RequestID, deps) - if !probed { + status, probeErr := probePendingCompileStatus(ctx, connection, record.RequestID, deps) + if probeErr != nil { + // Why wait: Unity acknowledged the query, so its server is alive and only the main thread + // that answers status queries stayed blocked. While the pending compile holds the + // single-flight slot a new compile request is rejected as busy, so polling its status is the + // only way to reach its result. Why check ctx: the caller's own deadline passing after the + // ack ends the query the same way, and then there is no time left to wait. + if ctx.Err() == nil && isUnansweredStatusProbe(probeErr) { + logCompileAttachProbeFailed(connection, record.RequestID, probeErr, "waiting") + return attachWaitForPendingCompile(ctx, connection, record, params, waitTimeout, stderr, deps) + } // Why keep the record: probe failures during domain reload are transient and // do not prove the in-flight compile is gone. + logCompileAttachProbeFailed(connection, record.RequestID, probeErr, "new_compile") return false, compileExecutionResult{} } @@ -73,12 +83,15 @@ func tryAttachToPendingCompile( return false, compileExecutionResult{} } +// probePendingCompileStatus queries the pending compile's status until one query succeeds or the +// probe deadline passes. A failed probe returns the last query's error, or ctx.Err() when ctx ends +// between queries. func probePendingCompileStatus( ctx context.Context, connection unityipc.Connection, requestID string, deps compileWaitDeps, -) (compileStatusResponse, bool) { +) (compileStatusResponse, error) { timeout := deps.attachProbeTimeout if timeout <= 0 { timeout = compileAttachProbeTimeout @@ -92,10 +105,12 @@ func probePendingCompileStatus( for { status, err := deps.queryCompileStatus(ctx, connection, requestID) if err == nil { - return status, true + return status, nil } if !time.Now().Before(deadline) { - return compileStatusResponse{}, false + // Why the last error, not the first: it is the Editor's latest state. An Editor that was + // unreachable and then acknowledged queries is back with its main thread blocked. + return compileStatusResponse{}, err } remaining := time.Until(deadline) @@ -107,7 +122,7 @@ func probePendingCompileStatus( select { case <-ctx.Done(): timer.Stop() - return compileStatusResponse{}, false + return compileStatusResponse{}, ctx.Err() case <-timer.C: } } @@ -315,6 +330,27 @@ func logCompileAttachStart(connection unityipc.Connection, requestID string, mod }) } +// logCompileAttachProbeFailed records why a status probe for the pending compile failed and whether +// the command then waits for that compile or starts a new one. +func logCompileAttachProbeFailed(connection unityipc.Connection, requestID string, probeErr error, next string) { + writeCompileVibeLog(connection.ProjectRoot, func() vibelog.CLIVibeLogEntry { + return vibelog.CLIVibeLogEntry{ + Level: "WARNING", + Operation: "cli_compile_attach_probe_failed", + Message: "Status probe for a previously timed-out compile request failed.", + Context: map[string]any{ + "command": clicore.CompileCommandName, + "request_id": requestID, + "transport_error": clicore.ErrorMessage(probeErr), + "next": next, + "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{ diff --git a/cli/project-runner/internal/projectrunner/compile_attach_probe_test.go b/cli/project-runner/internal/projectrunner/compile_attach_probe_test.go new file mode 100644 index 0000000000..cb23b2daac --- /dev/null +++ b/cli/project-runner/internal/projectrunner/compile_attach_probe_test.go @@ -0,0 +1,423 @@ +package projectrunner + +import ( + "bytes" + "context" + "encoding/json" + "fmt" + "os" + "runtime" + "strings" + "testing" + "time" + + "github.com/hatayama/unity-cli-loop/common/unityipc" +) + +const ( + attachProbeTestPendingErrorCount = 2 + attachProbeTestNewCompileErrorCount = 5 + // Why 10: long enough for a loaded machine to finish the waits these tests expect, short enough + // that a regression which waits where it must not fails in seconds instead of the default 10 minutes. + attachProbeTestWaitTimeoutSeconds = 10 + // Why 20: compileWaitTestDeps gives the probe a 40ms deadline at a 5ms interval, so it queries at + // most 10 times, and timers never fire early, so a slow machine only lowers that count. The probe + // therefore always ends on one of these answers, and the wait sees the rest. + attachProbeTestUnansweredCalls = 20 + // Why 200ms: tests whose answers change after the first query need the probe to query more than + // once even when the machine stalls on that first query. + attachProbeTestLongProbeTimeout = 200 * time.Millisecond + // Why 100: a 200ms probe at a 5ms interval queries at most 42 times. + attachProbeTestLongProbeUnansweredCalls = 100 + + vibeLogAttachStart = `"operation":"cli_compile_attach_start"` + vibeLogProbeFailed = `"operation":"cli_compile_attach_probe_failed"` + vibeLogNewCompileRequest = `"operation":"cli_compile_request_prepared"` + vibeLogNextWaiting = `"next":"waiting"` + vibeLogNextNewCompile = `"next":"new_compile"` +) + +// Verifies a probe that Unity acknowledged but never answered waits for the in-flight compile instead +// of sending a new compile, which the Editor would reject as busy while that compile runs. +func TestRunCompileAttachUnansweredProbeWaitsForInFlightCompile(t *testing.T) { + test := newAttachProbeTest(t, "compile_attach_unanswered_wait") + deps := compileWaitTestDeps(pendingCompileStatusQuery(test.requestID, func(call int) (compileStatusResponse, error) { + if call <= attachProbeTestUnansweredCalls { + return compileStatusResponse{}, unansweredStatusQueryError() + } + return finishedCompileStatus(attachProbeTestPendingErrorCount), nil + })) + params := map[string]any{compileWaitTimeoutParam: attachProbeTestWaitTimeoutSeconds} + + code, stdout, stderr := test.runCompile(context.Background(), params, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr) + } + if got := compileResultErrorCount(t, stdout); got != attachProbeTestPendingErrorCount { + t.Fatalf("expected the in-flight compile's result, got ErrorCount %d", got) + } + test.assertRecordCleared(t) + test.assertVibeLog(t, + []string{vibeLogProbeFailed, vibeLogNextWaiting, vibeLogAttachStart, `"attach_outcome":"completed"`}, + []string{vibeLogNewCompileRequest}) + test.assertServerHealthy(t) +} + +// Verifies a probe and a wait that Unity never answers end in COMPILE_WAIT_TIMEOUT without a new +// compile, and leave the pending record as the first timeout wrote it so a later rerun can reattach. +func TestRunCompileAttachUnansweredProbeRetimesOutKeepsRecord(t *testing.T) { + test := newAttachProbeTest(t, "compile_attach_unanswered_retimeout") + deps := compileWaitTestDeps(pendingCompileStatusQuery(test.requestID, func(int) (compileStatusResponse, error) { + return compileStatusResponse{}, unansweredStatusQueryError() + })) + params := map[string]any{compileWaitTimeoutParam: 1} + + code, _, stderr := test.runCompile(context.Background(), params, deps) + if code != 1 { + t.Fatalf("expected timeout exit 1: code=%d stderr=%s", code, stderr) + } + if !strings.Contains(stderr, "Compile status wait timed out after 1000ms") { + t.Fatalf("expected COMPILE_WAIT_TIMEOUT from the reattach wait: %s", stderr) + } + test.assertRecordUnchanged(t) + test.assertVibeLog(t, + []string{vibeLogNextWaiting, `"attach_outcome":"timeout"`}, + []string{vibeLogNewCompileRequest}) + test.assertServerHealthy(t) +} + +// Verifies a wait entered after an unanswered probe still gives up on a compile Unity no longer knows +// and starts a new one, as it does after a probe that Unity answered. +func TestRunCompileAttachUnansweredProbeThenDisappearedStartsNewCompile(t *testing.T) { + test := newAttachProbeTest(t, "compile_attach_unanswered_disappeared") + deps := compileWaitTestDeps(pendingCompileStatusQuery(test.requestID, func(call int) (compileStatusResponse, error) { + if call <= attachProbeTestUnansweredCalls { + return compileStatusResponse{}, unansweredStatusQueryError() + } + return compileStatusResponse{Ready: true, HasResult: false}, nil + })) + params := map[string]any{compileWaitTimeoutParam: attachProbeTestWaitTimeoutSeconds} + + code, stdout, stderr := test.runCompile(context.Background(), params, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr) + } + if got := compileResultErrorCount(t, stdout); got != attachProbeTestNewCompileErrorCount { + t.Fatalf("expected the new compile's result, got ErrorCount %d", got) + } + test.assertRecordCleared(t) + test.assertVibeLog(t, + []string{vibeLogNextWaiting, vibeLogAttachStart, `"attach_outcome":"disappeared"`, vibeLogNewCompileRequest}, + nil) + test.assertServerHealthy(t) +} + +// Verifies a probe that timed out before Unity acknowledged it keeps the pending record and starts a +// new compile: without the ack nothing shows the Editor is still working on the pending compile. +func TestRunCompileAttachUnacknowledgedProbeTimeoutStartsNewCompile(t *testing.T) { + test := newAttachProbeTest(t, "compile_attach_unacknowledged_probe") + deps := compileWaitTestDeps(pendingCompileStatusQuery(test.requestID, func(int) (compileStatusResponse, error) { + return compileStatusResponse{}, unacknowledgedStatusQueryError() + })) + params := map[string]any{compileWaitTimeoutParam: attachProbeTestWaitTimeoutSeconds} + + code, stdout, stderr := test.runCompile(context.Background(), params, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr) + } + if got := compileResultErrorCount(t, stdout); got != attachProbeTestNewCompileErrorCount { + t.Fatalf("expected the new compile's result, got ErrorCount %d", got) + } + test.assertRecordUnchanged(t) + test.assertVibeLog(t, + []string{vibeLogProbeFailed, vibeLogNextNewCompile, vibeLogNewCompileRequest}, + []string{vibeLogAttachStart}) + test.assertServerHealthy(t) +} + +// Verifies --force-recompile does not send a new compile while an unanswered probe shows a compile +// still holds the Editor; the wait warns that the flag was not applied, as it does after an answered probe. +func TestRunCompileAttachUnansweredProbeWithForceRecompileWarnsAndWaits(t *testing.T) { + test := newAttachProbeTest(t, "compile_attach_unanswered_force") + deps := compileWaitTestDeps(pendingCompileStatusQuery(test.requestID, func(call int) (compileStatusResponse, error) { + if call <= attachProbeTestUnansweredCalls { + return compileStatusResponse{}, unansweredStatusQueryError() + } + return finishedCompileStatus(attachProbeTestPendingErrorCount), nil + })) + params := map[string]any{ + compileForceParam: true, + compileWaitTimeoutParam: attachProbeTestWaitTimeoutSeconds, + } + + code, stdout, stderr := test.runCompile(context.Background(), params, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr) + } + if !strings.Contains(stderr, "--force-recompile is not applied") { + t.Fatalf("expected force-recompile ignored warning: %s", stderr) + } + if got := compileResultErrorCount(t, stdout); got != attachProbeTestPendingErrorCount { + t.Fatalf("expected the in-flight compile's result, got ErrorCount %d", got) + } + test.assertVibeLog(t, []string{vibeLogNextWaiting}, []string{vibeLogNewCompileRequest}) + test.assertServerHealthy(t) +} + +// Verifies a probe that cannot connect keeps the pending record and starts a new compile, even when +// the connection error wraps a timeout. +func TestRunCompileAttachUnreachableProbeKeepsRecordAndStartsNewCompile(t *testing.T) { + test := newAttachProbeTest(t, "compile_attach_unreachable_probe") + deps := compileWaitTestDeps(pendingCompileStatusQuery(test.requestID, func(int) (compileStatusResponse, error) { + return compileStatusResponse{}, unreachableStatusQueryError(test.connection.ProjectRoot) + })) + params := map[string]any{compileWaitTimeoutParam: attachProbeTestWaitTimeoutSeconds} + + code, stdout, stderr := test.runCompile(context.Background(), params, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr) + } + if got := compileResultErrorCount(t, stdout); got != attachProbeTestNewCompileErrorCount { + t.Fatalf("expected the new compile's result, got ErrorCount %d", got) + } + test.assertRecordUnchanged(t) + test.assertVibeLog(t, + []string{vibeLogProbeFailed, vibeLogNextNewCompile, vibeLogNewCompileRequest}, + []string{vibeLogAttachStart}) + test.assertServerHealthy(t) +} + +// Verifies the last probe answer decides: an Editor that was unreachable at first and then +// acknowledged the query without answering it is waited on. +func TestRunCompileAttachProbeLastAnswerDecidesAfterReconnect(t *testing.T) { + test := newAttachProbeTest(t, "compile_attach_probe_reconnect") + deps := compileWaitTestDeps(pendingCompileStatusQuery(test.requestID, func(call int) (compileStatusResponse, error) { + switch { + case call == 1: + return compileStatusResponse{}, unreachableStatusQueryError(test.connection.ProjectRoot) + case call <= attachProbeTestLongProbeUnansweredCalls: + return compileStatusResponse{}, unansweredStatusQueryError() + default: + return finishedCompileStatus(attachProbeTestPendingErrorCount), nil + } + })) + deps.attachProbeTimeout = attachProbeTestLongProbeTimeout + params := map[string]any{compileWaitTimeoutParam: attachProbeTestWaitTimeoutSeconds} + + code, stdout, stderr := test.runCompile(context.Background(), params, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr) + } + if got := compileResultErrorCount(t, stdout); got != attachProbeTestPendingErrorCount { + t.Fatalf("expected the in-flight compile's result, got ErrorCount %d", got) + } + test.assertVibeLog(t, + []string{vibeLogNextWaiting, vibeLogAttachStart}, + []string{vibeLogNewCompileRequest}) + test.assertServerHealthy(t) +} + +// Verifies the last probe answer decides: an Editor that acknowledged the query without answering and +// then stopped accepting connections is left to a new compile, which retries the connection. +func TestRunCompileAttachProbeLastAnswerDecidesAfterDisconnect(t *testing.T) { + test := newAttachProbeTest(t, "compile_attach_probe_disconnect") + deps := compileWaitTestDeps(pendingCompileStatusQuery(test.requestID, func(call int) (compileStatusResponse, error) { + if call == 1 { + return compileStatusResponse{}, unansweredStatusQueryError() + } + return compileStatusResponse{}, unreachableStatusQueryError(test.connection.ProjectRoot) + })) + deps.attachProbeTimeout = attachProbeTestLongProbeTimeout + params := map[string]any{compileWaitTimeoutParam: attachProbeTestWaitTimeoutSeconds} + + code, stdout, stderr := test.runCompile(context.Background(), params, deps) + if code != 1 { + t.Fatalf("expected failed compile envelope: code=%d stderr=%s", code, stderr) + } + if got := compileResultErrorCount(t, stdout); got != attachProbeTestNewCompileErrorCount { + t.Fatalf("expected the new compile's result, got ErrorCount %d", got) + } + test.assertRecordUnchanged(t) + test.assertVibeLog(t, + []string{vibeLogProbeFailed, vibeLogNextNewCompile, vibeLogNewCompileRequest}, + []string{vibeLogAttachStart}) + test.assertServerHealthy(t) +} + +// Verifies a probe cut off by the caller's own deadline does not start the wait even though Unity had +// acknowledged the query, because the command has no time left to wait. +func TestRunCompileAttachProbeContextDeadlineDoesNotWait(t *testing.T) { + test := newAttachProbeTest(t, "compile_attach_probe_context_deadline") + deps := compileWaitTestDeps(func(ctx context.Context, _ unityipc.Connection, requestID string) (compileStatusResponse, error) { + if requestID != test.requestID { + return finishedCompileStatus(attachProbeTestNewCompileErrorCount), nil + } + <-ctx.Done() + // This is how a status query ends when the caller's deadline passes after Unity's ack. + return compileStatusResponse{}, classifyCompileStatusQueryError( + unityipc.UnitySendOutcome{RequestDispatched: true, RequestAccepted: true}, + ctx.Err(), + ) + }) + params := map[string]any{compileWaitTimeoutParam: attachProbeTestWaitTimeoutSeconds} + // Why longer than the 40ms probe deadline: the query then returns after that deadline, so the probe + // reports the query's error instead of stopping on its own check of the finished context. + ctx, cancel := context.WithTimeout(context.Background(), 100*time.Millisecond) + defer cancel() + + _, _, _ = test.runCompile(ctx, params, deps) + test.assertRecordUnchanged(t) + test.assertVibeLog(t, nil, []string{vibeLogAttachStart}) +} + +// attachProbeTest holds what the probe-failure reattach tests share: a pending record for a compile +// that timed out a minute ago, and a server that accepts the one new compile a test may send. +type attachProbeTest struct { + connection unityipc.Connection + requestID string + timedOutAt time.Time + serverErr <-chan error +} + +func newAttachProbeTest(t *testing.T, requestID string) attachProbeTest { + t.Helper() + 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() + 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) + } + return attachProbeTest{ + connection: unityipc.Connection{Endpoint: endpoint, ProjectRoot: projectRoot}, + requestID: requestID, + timedOutAt: timedOutAt, + serverErr: serverErr, + } +} + +// runCompile runs compile with domain reload wait and returns the exit code, stdout, and stderr. +func (test attachProbeTest) runCompile( + ctx context.Context, + params map[string]any, + deps compileWaitDeps, +) (int, string, string) { + var stdout, stderr bytes.Buffer + code := runCompileWithDomainReloadWaitWithDeps(ctx, test.connection, params, &stdout, &stderr, deps) + return code, stdout.String(), stderr.String() +} + +func (test attachProbeTest) assertRecordUnchanged(t *testing.T) { + t.Helper() + got, ok := readCompilePendingRecord(test.connection.ProjectRoot) + if !ok { + t.Fatal("pending record must remain") + } + if got.RequestID != test.requestID || !got.TimedOutAtUtc.Equal(test.timedOutAt) { + t.Fatalf("pending record mutated: %#v", got) + } +} + +func (test attachProbeTest) assertRecordCleared(t *testing.T) { + t.Helper() + if _, err := os.Stat(compilePendingRecordPath(test.connection.ProjectRoot)); !os.IsNotExist(err) { + t.Fatalf("pending record should be cleared: %v", err) + } +} + +// assertVibeLog checks that the CLI Vibe log holds every entry of logged and none of notLogged. +func (test attachProbeTest) assertVibeLog(t *testing.T, logged []string, notLogged []string) { + t.Helper() + logContent := readOnlyCliVibeLog(t, test.connection.ProjectRoot) + for _, expected := range logged { + if !strings.Contains(logContent, expected) { + t.Fatalf("vibe log missing %q:\n%s", expected, logContent) + } + } + for _, unexpected := range notLogged { + if strings.Contains(logContent, unexpected) { + t.Fatalf("vibe log must not contain %q:\n%s", unexpected, logContent) + } + } +} + +func (test attachProbeTest) assertServerHealthy(t *testing.T) { + t.Helper() + select { + case err := <-test.serverErr: + t.Fatalf("server failed: %v", err) + default: + } +} + +// pendingCompileStatusQuery answers status queries for the pending request with answer(call), where +// call counts those queries from 1, and answers any other request, which is a new compile, with a +// finished result whose ErrorCount tells the two compiles apart. +func pendingCompileStatusQuery( + pendingRequestID string, + answer func(call int) (compileStatusResponse, error), +) func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + calls := 0 + return func(_ context.Context, _ unityipc.Connection, requestID string) (compileStatusResponse, error) { + if requestID != pendingRequestID { + return finishedCompileStatus(attachProbeTestNewCompileErrorCount), nil + } + calls++ + return answer(calls) + } +} + +func finishedCompileStatus(errorCount int) compileStatusResponse { + return compileStatusResponse{ + Ready: true, + HasResult: true, + // Why Success false: a successful result makes the command wait for tool readiness, which a + // temporary directory never reaches. + Result: json.RawMessage(fmt.Sprintf(`{"Success":false,"ErrorCount":%d}`, errorCount)), + } +} + +// unansweredStatusQueryError is how a status query ends when Unity acknowledged it and the query +// deadline passed before the answer, which is what a blocked main thread produces. +func unansweredStatusQueryError() error { + return classifyCompileStatusQueryError( + unityipc.UnitySendOutcome{RequestDispatched: true, RequestAccepted: true}, + context.DeadlineExceeded, + ) +} + +// unacknowledgedStatusQueryError is how a status query ends when its read deadline passes before +// any ack arrives. +func unacknowledgedStatusQueryError() error { + return classifyCompileStatusQueryError( + unityipc.UnitySendOutcome{RequestDispatched: true}, + fmt.Errorf("read unix: %w", os.ErrDeadlineExceeded), + ) +} + +// unreachableStatusQueryError is how a status query ends when its dial times out. +func unreachableStatusQueryError(projectRoot string) error { + return classifyCompileStatusQueryError( + unityipc.UnitySendOutcome{}, + &unityipc.ConnectionAttemptError{ProjectRoot: projectRoot, Endpoint: "test", Cause: os.ErrDeadlineExceeded}, + ) +} + +// compileResultErrorCount reads ErrorCount from the compile result printed on stdout. +func compileResultErrorCount(t *testing.T, stdout string) int { + t.Helper() + var result struct { + ErrorCount int + } + if err := json.Unmarshal([]byte(stdout), &result); err != nil { + t.Fatalf("stdout is not a compile result: %v\n%s", err, stdout) + } + return result.ErrorCount +} diff --git a/cli/project-runner/internal/projectrunner/compile_status_query_test.go b/cli/project-runner/internal/projectrunner/compile_status_query_test.go new file mode 100644 index 0000000000..675426aa37 --- /dev/null +++ b/cli/project-runner/internal/projectrunner/compile_status_query_test.go @@ -0,0 +1,95 @@ +package projectrunner + +import ( + "bufio" + "context" + "net" + "runtime" + "testing" + "time" + + clierrors "github.com/hatayama/unity-cli-loop/common/errors" + "github.com/hatayama/unity-cli-loop/common/unityipc" +) + +// Verifies a status query that Unity acknowledged but did not answer before the deadline is marked +// unanswered, which is what lets a reattach wait for a compile that blocks the main thread. +func TestQueryCompileStatusFromUnityMarksAcknowledgedDeadlineUnanswered(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("TCP endpoint injection is only used by this non-Windows client test") + } + + endpoint := startCompileStatusSilentServer(t, true) + ctx, cancel := context.WithTimeout(context.Background(), 200*time.Millisecond) + defer cancel() + + _, err := queryCompileStatusFromUnity( + ctx, + unityipc.Connection{Endpoint: endpoint, ProjectRoot: t.TempDir()}, + "compile_status_acknowledged") + if !isUnansweredStatusProbe(err) { + t.Fatalf("an acknowledged query that ran out of time should be unanswered: %v", err) + } +} + +// Verifies a status query whose read deadline passed before any ack stays unmarked: without the ack +// nothing shows that Unity is processing requests at all. +func TestQueryCompileStatusFromUnityLeavesUnacknowledgedDeadlineUnmarked(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("TCP endpoint injection is only used by this non-Windows client test") + } + + endpoint := startCompileStatusSilentServer(t, false) + ctx, cancel := context.WithTimeout(context.Background(), 200*time.Millisecond) + defer cancel() + + _, err := queryCompileStatusFromUnity( + ctx, + unityipc.Connection{Endpoint: endpoint, ProjectRoot: t.TempDir()}, + "compile_status_unacknowledged") + if !clierrors.IsFinalResponseTimeoutError(err) { + t.Fatalf("expected the read deadline to end the query: %v", err) + } + if isUnansweredStatusProbe(err) { + t.Fatalf("a query without an ack must not count as unanswered: %v", err) + } +} + +// startCompileStatusSilentServer accepts one status query, writes the dispatch ack when acknowledge is +// true, and then holds the connection without answering until the client closes it. +func startCompileStatusSilentServer(t *testing.T, acknowledge bool) unityipc.Endpoint { + 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() + }) + + go func() { + conn, acceptErr := listener.Accept() + if acceptErr != nil { + return + } + defer func() { + _ = conn.Close() + }() + + reader := bufio.NewReader(conn) + if _, readErr := unityipc.Read(reader); readErr != nil { + return + } + if acknowledge { + accepted := []byte(`{"jsonrpc":"2.0","result":{"accepted":true},"uloop":{"phase":"accepted"},"id":1}`) + if writeErr := unityipc.Write(conn, accepted); writeErr != nil { + return + } + } + // Why read again: it blocks until the client gives up and closes the connection, so the query + // sees Unity holding the request rather than dropping the connection. + _, _ = unityipc.Read(reader) + }() + + return unityipc.Endpoint{Network: "tcp", Address: listener.Addr().String()} +} diff --git a/cli/project-runner/internal/projectrunner/compile_wait.go b/cli/project-runner/internal/projectrunner/compile_wait.go index 15a5661eda..b46aa32ca4 100644 --- a/cli/project-runner/internal/projectrunner/compile_wait.go +++ b/cli/project-runner/internal/projectrunner/compile_wait.go @@ -5,6 +5,7 @@ import ( "crypto/rand" "encoding/hex" "encoding/json" + "errors" "fmt" "math" "time" @@ -266,22 +267,55 @@ func queryCompileStatusFromUnity(ctx context.Context, connection unityipc.Connec probeContext, cancel := context.WithTimeout(ctx, compileStatusProbeTimeout) defer cancel() - response, err := unityipc.NewClient(connection, clicontract.ProjectRunnerVersion()).Send( + outcome, err := unityipc.NewClient(connection, clicontract.ProjectRunnerVersion()).SendWithProgressOutcome( probeContext, compileStatusCommandName, map[string]any{compileRequestIDParam: requestID}, + nil, ) if err != nil { - return compileStatusResponse{}, err + return compileStatusResponse{}, classifyCompileStatusQueryError(outcome, err) } var status compileStatusResponse - if err := json.Unmarshal(response, &status); err != nil { + if err := json.Unmarshal(outcome.Result, &status); err != nil { return compileStatusResponse{}, err } return status, nil } +// compileStatusUnansweredError marks a status query that Unity acknowledged but did not answer +// before the query ran out of time. +type compileStatusUnansweredError struct { + cause error +} + +func (err *compileStatusUnansweredError) Error() string { + return err.cause.Error() +} + +func (err *compileStatusUnansweredError) Unwrap() error { + return err.cause +} + +// classifyCompileStatusQueryError marks a status query that ran out of time after Unity's dispatch +// ack. Unity writes that ack from its IPC thread before it switches to the main thread that answers +// status queries, so an ack followed by the deadline shows a live server whose main thread stayed +// blocked. A deadline before the ack shows neither and stays unmarked. +func classifyCompileStatusQueryError(outcome unityipc.UnitySendOutcome, err error) error { + if outcome.RequestAccepted && clierrors.IsFinalResponseTimeoutError(err) { + return &compileStatusUnansweredError{cause: err} + } + return err +} + +// isUnansweredStatusProbe reports whether a status query failed because Unity acknowledged it but +// did not answer in time. +func isUnansweredStatusProbe(err error) bool { + var unanswered *compileStatusUnansweredError + return errors.As(err, &unanswered) +} + func shouldWaitForCompileStatus(err error, outcome unityipc.UnitySendOutcome) bool { if err == nil { return true From 92f5f3c3e2acdf33f2966c4812df47717f2bc1fd Mon Sep 17 00:00:00 2001 From: hatayama Date: Wed, 30 Sep 2026 04:01:58 +0900 Subject: [PATCH 2/2] Make the caller-deadline reattach test hold under load TestRunCompileAttachProbeContextDeadlineDoesNotWait pins the check that keeps the reattach from waiting once the caller's own deadline has passed. It relied on the caller's 100ms deadline landing after the probe's 40ms deadline. When more than 60ms passed before the probe set its deadline, as on a loaded machine, the probe stopped on its own check of the finished context and returned a bare ctx.Err(). That error starts a new compile with or without the check, so removing the check went unnoticed. - The fake status query now also waits out the probe deadline before answering. Timers never fire early, so the probe always reports the acknowledged-then-timed-out error and the check alone decides. - The test now asserts the new-compile decision in the Vibe log instead of only the absence of the attach wait. Found by the independent review of the pull request. With a 70ms delay injected before the run, the committed test passed with the check removed, while the fixed test fails; without that mutation both pass. --- .../projectrunner/compile_attach_probe_test.go | 18 +++++++++++++----- 1 file changed, 13 insertions(+), 5 deletions(-) diff --git a/cli/project-runner/internal/projectrunner/compile_attach_probe_test.go b/cli/project-runner/internal/projectrunner/compile_attach_probe_test.go index cb23b2daac..4ff83f233a 100644 --- a/cli/project-runner/internal/projectrunner/compile_attach_probe_test.go +++ b/cli/project-runner/internal/projectrunner/compile_attach_probe_test.go @@ -248,26 +248,34 @@ func TestRunCompileAttachProbeLastAnswerDecidesAfterDisconnect(t *testing.T) { // acknowledged the query, because the command has no time left to wait. func TestRunCompileAttachProbeContextDeadlineDoesNotWait(t *testing.T) { test := newAttachProbeTest(t, "compile_attach_probe_context_deadline") - deps := compileWaitTestDeps(func(ctx context.Context, _ unityipc.Connection, requestID string) (compileStatusResponse, error) { + deps := compileWaitTestDeps(nil) + deps.queryCompileStatus = func(ctx context.Context, _ unityipc.Connection, requestID string) (compileStatusResponse, error) { if requestID != test.requestID { return finishedCompileStatus(attachProbeTestNewCompileErrorCount), nil } + calledAt := time.Now() <-ctx.Done() + // Why also wait out the probe deadline: the probe set it before this call, so the probe then + // reports this error. Returning before it lets the probe stop on its own check of the finished + // context, and that bare ctx.Err() starts a new compile even without the caller-deadline check. + time.Sleep(time.Until(calledAt.Add(deps.attachProbeTimeout))) // This is how a status query ends when the caller's deadline passes after Unity's ack. return compileStatusResponse{}, classifyCompileStatusQueryError( unityipc.UnitySendOutcome{RequestDispatched: true, RequestAccepted: true}, ctx.Err(), ) - }) + } params := map[string]any{compileWaitTimeoutParam: attachProbeTestWaitTimeoutSeconds} - // Why longer than the 40ms probe deadline: the query then returns after that deadline, so the probe - // reports the query's error instead of stopping on its own check of the finished context. + // Why a deadline, not a cancel: only a deadline that passes after the ack marks the query as + // unanswered, which is the case the caller-deadline check exists for. ctx, cancel := context.WithTimeout(context.Background(), 100*time.Millisecond) defer cancel() _, _, _ = test.runCompile(ctx, params, deps) test.assertRecordUnchanged(t) - test.assertVibeLog(t, nil, []string{vibeLogAttachStart}) + test.assertVibeLog(t, + []string{vibeLogProbeFailed, vibeLogNextNewCompile}, + []string{vibeLogNextWaiting, vibeLogAttachStart}) } // attachProbeTest holds what the probe-failure reattach tests share: a pending record for a compile