diff --git a/cli/project-runner/internal/projectrunner/connection_retry_flow.go b/cli/project-runner/internal/projectrunner/connection_retry_flow.go index cfdeb61dcb..856512656f 100644 --- a/cli/project-runner/internal/projectrunner/connection_retry_flow.go +++ b/cli/project-runner/internal/projectrunner/connection_retry_flow.go @@ -70,17 +70,20 @@ func finishNonRetryableConnectionAttempt( responseTimeout time.Duration, focusController *connectionRetryFocusController, ) (unityipc.UnitySendOutcome, error) { - // A transport error after a busy response in this window must not mask the - // busy; the server answered moments ago, so busy is the truer diagnosis. - // An RPC error is a real Unity answer, not a transport artifact, and must - // surface as-is. The transport error is not compared against the window - // deadline because the connection deadline can fire microseconds before - // the context reports expiry. + // A busy answer earlier in this window wins only over an attempt whose request never reached + // Unity, such as a failed connect or write: nothing ran, so busy is the truer diagnosis. A + // request that reached Unity may already be running, so that attempt's own error and outcome + // take the same path as a first attempt's, and the caller recovers from them (compile, for + // one, asks Unity for its compile status). An RPC error is a real Unity answer, not a + // transport artifact, and must surface as-is. if currentAttempt.err != nil && !isRPCError(currentAttempt.err) && isUnityServerBusyRPCError(lastAttempt.err) { + // A caller that cancelled gets the cancellation back, whichever attempt failed. if ctx.Err() != nil { return currentAttempt.outcome, ctx.Err() } - return lastAttempt.outcome, lastAttempt.err + if !currentAttempt.outcome.RequestDispatched { + return lastAttempt.outcome, lastAttempt.err + } } if reason, ok := connectionRetryFocusReasonForError(currentAttempt.err, currentAttempt.outcome, responseTimeout); ok { focusController.tryFocus(ctx, reason, currentAttempt.err) diff --git a/cli/project-runner/internal/projectrunner/connection_retry_flow_test.go b/cli/project-runner/internal/projectrunner/connection_retry_flow_test.go index 9f7b7fa13e..fa4e5aa890 100644 --- a/cli/project-runner/internal/projectrunner/connection_retry_flow_test.go +++ b/cli/project-runner/internal/projectrunner/connection_retry_flow_test.go @@ -6,6 +6,7 @@ import ( "io" "os" "path/filepath" + "reflect" "strings" "testing" "time" @@ -211,11 +212,11 @@ func TestFinishBusyRetryStopsWithTheRightError(t *testing.T) { } } -// Verifies a transport error right after a busy answer reports the busy answer, unless the caller -// cancelled, in which case the cancellation wins. -func TestFinishNonRetryableConnectionAttemptPrefersBusyOverTransportError(t *testing.T) { +// Verifies a transport error from an attempt that never reached Unity reports the earlier busy +// answer, unless the caller cancelled, in which case the cancellation wins. +func TestFinishNonRetryableConnectionAttemptPrefersBusyOverAnUndispatchedTransportError(t *testing.T) { busy := serverBusyRPCError(t) - current := sendAttempt{outcome: unityipc.UnitySendOutcome{RequestDispatched: true}, err: io.ErrUnexpectedEOF} + current := sendAttempt{err: io.ErrUnexpectedEOF} last := sendAttempt{err: busy} _, err := finishNonRetryableConnectionAttempt(context.Background(), current, last, 0, nil) @@ -229,6 +230,104 @@ func TestFinishNonRetryableConnectionAttemptPrefersBusyOverTransportError(t *tes } } +// Verifies a dropped connection, a timeout, or any other non-RPC error from an attempt that reached +// Unity after a busy answer comes back as that attempt's own error and outcome, so the caller can +// recover from what really happened, and that a caller's cancellation still wins over it. +func TestFinishNonRetryableConnectionAttemptKeepsADispatchedFailureAfterBusy(t *testing.T) { + busy := serverBusyRPCError(t) + last := busyAttemptAfterAccept(busy) + cases := []struct { + name string + current sendAttempt + }{ + { + name: "dropped after the accept", + current: sendAttempt{outcome: unityipc.UnitySendOutcome{RequestDispatched: true, RequestAccepted: true}, err: io.ErrUnexpectedEOF}, + }, + { + name: "dropped before the accept", + current: sendAttempt{outcome: unityipc.UnitySendOutcome{RequestDispatched: true}, err: io.EOF}, + }, + { + name: "final response timed out after the accept", + current: sendAttempt{outcome: unityipc.UnitySendOutcome{RequestDispatched: true, RequestAccepted: true}, err: os.ErrDeadlineExceeded}, + }, + { + // Stands for an error that is neither a disconnect nor a timeout, such as a final response + // that fails to decode: the rule does not depend on the kind of error. + name: "failed another way after the accept", + current: sendAttempt{outcome: unityipc.UnitySendOutcome{RequestDispatched: true, RequestAccepted: true}, err: errors.New("final response could not be decoded")}, + }, + } + for _, testCase := range cases { + t.Run(testCase.name, func(t *testing.T) { + t.Run("reports the dispatched failure", func(t *testing.T) { + // A positive response timeout keeps the accepted timeout out of the focus handling, + // which needs a focus controller this test does not build. + outcome, err := finishNonRetryableConnectionAttempt(context.Background(), testCase.current, last, time.Second, nil) + if !errors.Is(err, testCase.current.err) || isUnityServerBusyRPCError(err) { + t.Fatalf("err = %v, want the dispatched attempt's own error %v", err, testCase.current.err) + } + if !reflect.DeepEqual(outcome, testCase.current.outcome) { + t.Fatalf("outcome = %+v, want the dispatched attempt's outcome %+v", outcome, testCase.current.outcome) + } + }) + t.Run("reports the cancellation", func(t *testing.T) { + _, err := finishNonRetryableConnectionAttempt(cancelledContext(), testCase.current, last, time.Second, nil) + if !errors.Is(err, context.Canceled) { + t.Fatalf("err = %v, want context.Canceled", err) + } + }) + }) + } +} + +// busyAttemptAfterAccept returns a busy answer to an accepted request. Its distinct timing tells its +// outcome apart from a current attempt whose flags are the same, so a test can see which outcome +// came back. +func busyAttemptAfterAccept(busy error) sendAttempt { + return sendAttempt{ + outcome: unityipc.UnitySendOutcome{ + RequestDispatched: true, + RequestAccepted: true, + Timing: unityipc.UnitySendTiming{Total: time.Millisecond}, + }, + err: busy, + } +} + +// Verifies an editor-unresponsive error from an attempt that Unity accepted after a busy answer comes +// back as that attempt's own error and outcome, and goes through the main-thread-stall focus handling +// a first attempt would get, instead of being reported as the busy answer. +func TestFinishNonRetryableConnectionAttemptKeepsAnEditorUnresponsiveErrorAfterBusy(t *testing.T) { + busy := serverBusyRPCError(t) + last := busyAttemptAfterAccept(busy) + current := sendAttempt{ + outcome: unityipc.UnitySendOutcome{RequestDispatched: true, RequestAccepted: true}, + err: &unityipc.EditorUnresponsiveError{StallSeconds: 30}, + } + processLookups := 0 + deps := defaultConnectionRetryDeps() + deps.findRunningUnityProcess = func(context.Context, string) (*clicore.UnityProcess, error) { + processLookups++ + return nil, nil + } + // This error enters the focus handling whatever the response timeout is, so it needs a real focus + // controller. Finding no Unity process keeps the focus itself from running. + focusController := newConnectionRetryFocusController(unityipc.Connection{ProjectRoot: t.TempDir()}, "get-logs", deps) + + outcome, err := finishNonRetryableConnectionAttempt(context.Background(), current, last, 0, focusController) + if !errors.Is(err, current.err) || isUnityServerBusyRPCError(err) { + t.Errorf("err = %v, want the accepted attempt's own error %v", err, current.err) + } + if !reflect.DeepEqual(outcome, current.outcome) { + t.Errorf("outcome = %+v, want the accepted attempt's outcome %+v", outcome, current.outcome) + } + if processLookups != 1 { + t.Errorf("Unity process lookups = %d, want 1 from the main-thread-stall focus handling", processLookups) + } +} + // Verifies the unity-alive retry reports the caller's cancellation when its retry context ends // because the caller cancelled, and Unity-not-responding otherwise. func TestFinishUnityAliveRetryWaitWhenRetryContextEnds(t *testing.T) { diff --git a/cli/project-runner/internal/projectrunner/connection_retry_test.go b/cli/project-runner/internal/projectrunner/connection_retry_test.go index 93defc4123..fa120a499d 100644 --- a/cli/project-runner/internal/projectrunner/connection_retry_test.go +++ b/cli/project-runner/internal/projectrunner/connection_retry_test.go @@ -6,6 +6,7 @@ import ( "encoding/json" "errors" "fmt" + "io" "net" "os" "path/filepath" @@ -1469,3 +1470,185 @@ func TestSendWithTransientConnectionRetrySurfacesDispatchedFailureAfterBusy(t *t t.Fatalf("dispatched failure must surface as the original RPC error, got: %v", err) } } + +// busyFirstServerConnection starts a TCP stand-in for Unity that answers the first connection with +// a busy error and hands every later connection, once its request has been read, to +// handleDispatched. The returned connection points at the stand-in. +func busyFirstServerConnection(t *testing.T, handleDispatched func(conn net.Conn)) unityipc.Connection { + 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() + }) + + busy := `{"jsonrpc":"2.0","id":1,"error":{"code":-32603,"message":"Unity is busy running 'execute-dynamic-code'.","data":{"type":"server_busy","runningToolName":"execute-dynamic-code","requestedToolName":"compile","message":"busy"}}}` + go func() { + first := true + for { + conn, acceptErr := listener.Accept() + if acceptErr != nil { + return + } + sendBusy := first + first = false + go func(conn net.Conn, sendBusy bool) { + defer func() { + _ = conn.Close() + }() + if _, readErr := unityipc.Read(bufio.NewReader(conn)); readErr != nil { + return + } + if sendBusy { + _ = unityipc.Write(conn, []byte(busy)) + return + } + handleDispatched(conn) + }(conn, sendBusy) + } + }() + + return unityipc.Connection{ + Endpoint: unityipc.Endpoint{ + Network: "tcp", + Address: listener.Addr().String(), + }, + ProjectRoot: t.TempDir(), + } +} + +// Verifies a connection that drops after Unity accepted the retried request comes back as that +// disconnect, not as the busy answer from the attempt before it, so compile can go on to ask Unity +// for its compile status. +func TestSendWithTransientConnectionRetrySurfacesADroppedConnectionAfterBusy(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("TCP endpoint injection is only used by this non-Windows client test") + } + + deps := defaultConnectionRetryDeps() + deps.retryTimeout = 150 * time.Millisecond + deps.retryPoll = 5 * time.Millisecond + deps.findRunningUnityProcess = func(context.Context, string) (*clicore.UnityProcess, error) { + return nil, nil + } + connection := busyFirstServerConnection(t, func(conn net.Conn) { + accepted := `{"jsonrpc":"2.0","result":{"accepted":true},"uloop":{"phase":"accepted"},"id":1}` + _ = unityipc.Write(conn, []byte(accepted)) + }) + + outcome, err := sendWithTransientConnectionRetryWithDeps( + context.Background(), + connection, + "compile", + map[string]any{}, + nil, + 0, + deps) + if err == nil { + t.Fatal("expected the dropped connection to surface") + } + if isUnityServerBusyRPCError(err) { + t.Fatalf("a request that reached Unity must not be reported as the earlier busy answer, got: %v", err) + } + if !clierrors.IsTransportDisconnectError(err) { + t.Fatalf("err = %v, want a transport disconnect", err) + } + if !outcome.RequestDispatched || !outcome.RequestAccepted { + t.Fatalf("outcome = %+v, want a dispatched and accepted request", outcome) + } + if !shouldWaitForCompileStatus(err, outcome) { + t.Fatalf("compile must be able to wait for its status after err = %v, outcome = %+v", err, outcome) + } +} + +// Verifies a final response wait that times out after Unity accepted the retried request, which is +// how a compile longer than its response timeout ends, comes back as that timeout and not as the +// busy answer from the attempt before it, so compile can go on to ask Unity for its compile status. +func TestSendWithTransientConnectionRetrySurfacesAFinalResponseTimeoutAfterBusy(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("TCP endpoint injection is only used by this non-Windows client test") + } + + deps := defaultConnectionRetryDeps() + deps.retryTimeout = 150 * time.Millisecond + deps.retryPoll = 5 * time.Millisecond + deps.findRunningUnityProcess = func(context.Context, string) (*clicore.UnityProcess, error) { + return nil, nil + } + connection := busyFirstServerConnection(t, func(conn net.Conn) { + accepted := `{"jsonrpc":"2.0","result":{"accepted":true},"uloop":{"phase":"accepted"},"id":1}` + if writeErr := unityipc.Write(conn, []byte(accepted)); writeErr != nil { + return + } + // Staying silent until the client hangs up means the client's own deadline is always what + // ends the wait, never a close from this side. + _, _ = io.Copy(io.Discard, conn) + }) + + outcome, err := sendWithTransientConnectionRetryWithDeps( + context.Background(), + connection, + "compile", + map[string]any{}, + nil, + 50*time.Millisecond, + deps) + if err == nil { + t.Fatal("expected the final response timeout to surface") + } + if isUnityServerBusyRPCError(err) { + t.Fatalf("a request that reached Unity must not be reported as the earlier busy answer, got: %v", err) + } + if !clierrors.IsFinalResponseTimeoutError(err) { + t.Fatalf("err = %v, want a final response timeout", err) + } + if !outcome.RequestAccepted { + t.Fatalf("outcome = %+v, want an accepted request", outcome) + } + if !shouldWaitForCompileStatus(err, outcome) { + t.Fatalf("compile must be able to wait for its status after err = %v, outcome = %+v", err, outcome) + } +} + +// Verifies a retried request that Unity read but never acknowledged times out as an unanswered +// request, not as the busy answer from the attempt before it. +func TestSendWithTransientConnectionRetrySurfacesAnUnansweredRequestAfterBusy(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("TCP endpoint injection is only used by this non-Windows client test") + } + + deps := defaultConnectionRetryDeps() + deps.retryTimeout = 150 * time.Millisecond + deps.retryPoll = 5 * time.Millisecond + deps.findRunningUnityProcess = func(context.Context, string) (*clicore.UnityProcess, error) { + return nil, nil + } + connection := busyFirstServerConnection(t, func(conn net.Conn) { + // Staying silent until the client hangs up means the client's own accept deadline is always + // what ends the wait, never a close from this side. + _, _ = io.Copy(io.Discard, conn) + }) + + outcome, err := sendWithTransientConnectionRetryWithDeps( + context.Background(), + connection, + "compile", + map[string]any{}, + nil, + 0, + deps) + if err == nil { + t.Fatal("expected the unanswered request to surface") + } + if isUnityServerBusyRPCError(err) { + t.Fatalf("a request that reached Unity must not be reported as the earlier busy answer, got: %v", err) + } + if !clierrors.IsFinalResponseTimeoutError(err) { + t.Fatalf("err = %v, want a response timeout", err) + } + if !outcome.RequestDispatched || outcome.RequestAccepted { + t.Fatalf("outcome = %+v, want a dispatched request that was never accepted", outcome) + } +}