diff --git a/cli/project-runner/internal/projectrunner/compile_attach.go b/cli/project-runner/internal/projectrunner/compile_attach.go index b6a8afe67..29c1d2990 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 000000000..4ff83f233 --- /dev/null +++ b/cli/project-runner/internal/projectrunner/compile_attach_probe_test.go @@ -0,0 +1,431 @@ +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(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 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, + []string{vibeLogProbeFailed, vibeLogNextNewCompile}, + []string{vibeLogNextWaiting, 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 000000000..675426aa3 --- /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 15a5661ed..b46aa32ca 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