diff --git a/Packages/src/Editor/FirstPartyTools/ExecuteDynamicCode/ExecuteDynamicCodeUseCase.cs b/Packages/src/Editor/FirstPartyTools/ExecuteDynamicCode/ExecuteDynamicCodeUseCase.cs index 91f9ace150..44a12287ae 100644 --- a/Packages/src/Editor/FirstPartyTools/ExecuteDynamicCode/ExecuteDynamicCodeUseCase.cs +++ b/Packages/src/Editor/FirstPartyTools/ExecuteDynamicCode/ExecuteDynamicCodeUseCase.cs @@ -32,13 +32,19 @@ public async Task ExecuteAsync( { using DynamicCodeDomainReloadWaitSignal domainReloadWaitSignal = DynamicCodeDomainReloadWaitSignal.Start(parameters); + // Declared outside the try so the catch below can still correlate a cancellation + // against this same execute_dynamic_code_start entry, and so it can tell whether the + // finalResult path below already logged completion before a later await in that same + // path (e.g. ApplyPauseStateAsync) throws OperationCanceledException. + string correlationId = UnityCliLoopConstants.GenerateCorrelationId(); + bool completionLogged = false; try { object[] parametersArray = ConvertParameters(parameters.Parameters); string originalCode = parameters.Code ?? string.Empty; - LogExecutionStart(parameters, UnityCliLoopConstants.GenerateCorrelationId()); + LogExecutionStart(parameters, correlationId); DynamicCodeExecutionRequest request = CreateExecutionRequest( originalCode, @@ -66,6 +72,9 @@ await WarmForegroundExecutionPathIfNeededAsync(parameters, cancellationToken) DynamicCodeForegroundWarmupState.MarkCompletedBySuccessfulExecution(); } + LogExecutionComplete(finalResult, correlationId); + completionLogged = true; + if (DynamicCodeExecutionResponseFactory.IsCancelledResult(finalResult)) { ExecuteDynamicCodeResponse cancelledResponse = @@ -108,6 +117,10 @@ await WarmForegroundExecutionPathIfNeededAsync(parameters, cancellationToken) } catch (OperationCanceledException) { + if (!completionLogged) + { + LogExecutionCancelledBeforeResult(correlationId); + } ExecuteDynamicCodeResponse response = DynamicCodeExecutionResponseFactory.CreateCancelledResponse(); response.EmitTimingsInJsonResponse = parameters?.IncludeTimings ?? false; // Why CancellationToken.None: cancellationToken is already cancelled on this path, @@ -156,6 +169,49 @@ private static void LogExecutionStart( "Monitor execution flow and performance"); } + // Why this exists: execute_dynamic_code_start had no matching completion log, so a + // client-side stall diagnosis (e.g. EditorUnresponsiveError) could not be correlated + // against whether Unity had actually finished the snippet by the time the CLI gave up. + private static void LogExecutionComplete(ExecutionResult finalResult, string correlationId) + { + LogExecutionCompleteEntry( + finalResult.Success, + DynamicCodeExecutionResponseFactory.IsCancelledResult(finalResult), + DynamicCodeExecutionResponseFactory.IsRuntimeRestartingResult(finalResult), + finalResult.ExecutionTime.TotalMilliseconds, + correlationId); + } + + // Covers cancellation paths that throw before a final ExecutionResult exists (e.g. during + // foreground warmup), which LogExecutionComplete above cannot reach. + private static void LogExecutionCancelledBeforeResult(string correlationId) + { + LogExecutionCompleteEntry(success: false, cancelled: true, runtimeRestarting: false, executionTimeMs: 0, correlationId); + } + + private static void LogExecutionCompleteEntry( + bool success, + bool cancelled, + bool runtimeRestarting, + double executionTimeMs, + string correlationId) + { + VibeLogger.LogInfo( + "execute_dynamic_code_complete", + "Dynamic code execution completed", + new + { + correlationId, + success, + cancelled, + runtimeRestarting, + executionTimeMs + }, + correlationId, + "Dynamic code execution finished; correlate against execute_dynamic_code_start by correlationId", + "Monitor execution flow and performance"); + } + private static object[] ConvertParameters(Dictionary parameters) { if (parameters == null || parameters.Count == 0) diff --git a/cli/common/unityipc/client.go b/cli/common/unityipc/client.go index e3f86ca3da..09cba20138 100644 --- a/cli/common/unityipc/client.go +++ b/cli/common/unityipc/client.go @@ -142,6 +142,10 @@ func (client *Client) WithMainThreadStallHandler(handler func(float64)) *Client return client.withOption(WithMainThreadStallHandler(handler)) } +func (client *Client) WithSelfInducedMainThreadStallTolerance() *Client { + return client.withOption(WithSelfInducedMainThreadStallTolerance()) +} + func (client *Client) withOption(option ClientOption) *Client { clientOptions := client.options option(&clientOptions) @@ -235,6 +239,7 @@ func (client *Client) SendWithProgressOutcomeAcceptContext( if response.ULoop.Phase == rpcResponsePhaseAccepted { outcome.RequestAccepted = true + acceptedAt := time.Now() if progress != nil { progress(cliprogress.Event{Stage: cliprogress.StageAccepted}) } @@ -246,6 +251,7 @@ func (client *Client) SendWithProgressOutcomeAcceptContext( progress, cancelAccept, startedAt, + acceptedAt, timing, outcome, response, @@ -262,6 +268,7 @@ func (client *Client) readAcceptedResponse( progress ProgressFunc, cancelAccept context.CancelFunc, startedAt time.Time, + acceptedAt time.Time, timing UnitySendTiming, outcome UnitySendOutcome, response rpcResponse, @@ -301,6 +308,7 @@ func (client *Client) readAcceptedResponse( progress, heartbeatSilence, absoluteDeadline, + acceptedAt, ); err != nil { return finishOutcomeWithError(outcome, timing, startedAt, err) } @@ -341,12 +349,14 @@ func (client *Client) handleHeartbeatResponse( progress ProgressFunc, heartbeatSilence time.Duration, absoluteDeadline time.Time, + acceptedAt time.Time, ) error { stallSeconds := response.ULoop.MainThreadStallSeconds + selfInducedStall := client.isSelfInducedStall(stallSeconds, acceptedAt) if stallSeconds >= mainThreadStallProgressThresholdSeconds { - client.reportMainThreadStall(stallSeconds, progress) + client.reportMainThreadStall(stallSeconds, selfInducedStall, progress) } - if stallSeconds >= client.getMainThreadStallLimit().Seconds() { + if stallSeconds >= client.getMainThreadStallLimit().Seconds() && !selfInducedStall { return &EditorUnresponsiveError{StallSeconds: stallSeconds} } if heartbeatSilence > 0 { @@ -355,18 +365,22 @@ func (client *Client) handleHeartbeatResponse( return nil } -func (client *Client) reportMainThreadStall(stallSeconds float64, progress ProgressFunc) { +func (client *Client) reportMainThreadStall(stallSeconds float64, selfInducedStall bool, progress ProgressFunc) { if client.options.mainThreadStallHandler != nil { client.options.mainThreadStallHandler(stallSeconds) } - if progress != nil { - progress(cliprogress.Event{ - Stage: cliprogress.StageMessage, - Message: fmt.Sprintf( - "Unity main thread stuck %.0fs; check modal/long operation...", - stallSeconds), - }) + if progress == nil { + return + } + // Why classify rather than just check the option: a stall that predates this request's + // accept is a genuine freeze even on a self-induced-stall-tolerant client (it is about to + // fail with EditorUnresponsiveError below), so it must keep the "stuck" wording instead of + // wrongly implying the command itself is the cause. + message := fmt.Sprintf("Unity main thread stuck %.0fs; check modal/long operation...", stallSeconds) + if selfInducedStall { + message = fmt.Sprintf("Unity main thread busy executing this command for %.0fs; still waiting...", stallSeconds) } + progress(cliprogress.Event{Stage: cliprogress.StageMessage, Message: message}) } func finishRPCResponse( diff --git a/cli/common/unityipc/client_heartbeat_test.go b/cli/common/unityipc/client_heartbeat_test.go index 82f995bcb6..8f682d6a0c 100644 --- a/cli/common/unityipc/client_heartbeat_test.go +++ b/cli/common/unityipc/client_heartbeat_test.go @@ -265,6 +265,110 @@ func TestSendFailsWhenMainThreadStallExceedsLimit(t *testing.T) { } } +// Verifies that a self-induced-stall-tolerant client keeps waiting through a main-thread +// stall reported shortly after this request's own accept, instead of failing with +// EditorUnresponsiveError: a command that itself blocks the main thread synchronously +// (e.g. a long execute-dynamic-code snippet) must not be treated as a frozen editor. +func TestSendKeepsWaitingThroughSelfInducedMainThreadStall(t *testing.T) { + stalledHeartbeat := `{"jsonrpc":"2.0","id":1,"result":{"alive":true},"uloop":{"phase":"heartbeat","mainThreadStallSeconds":3}}` + connection := startHeartbeatTestServer(t, func(conn net.Conn) { + writeFrame(t, conn, heartbeatAck) + writeFrame(t, conn, stalledHeartbeat) + writeFrame(t, conn, `{"jsonrpc":"2.0","id":1,"result":{"ok":true}}`) + }) + + client := NewClient( + connection, + "9.9.9", + WithSelfInducedMainThreadStallTolerance(), + withHeartbeatSilenceOverrideForTest(5*time.Second), + withMainThreadStallLimitForTest(2*time.Second), + ) + + outcome, err := client.SendWithProgressOutcome(context.Background(), "execute-dynamic-code", map[string]any{}, nil) + if err != nil { + t.Fatalf("expected success through a self-induced stall, got %v", err) + } + if len(outcome.Result) == 0 { + t.Fatal("expected final result") + } +} + +// Verifies that self-induced-stall tolerance does not mask a genuine freeze: a stall that +// already exceeds the time elapsed since this request's own accept (plus margin) predates +// the request and must still fail with EditorUnresponsiveError. +func TestSendFailsWhenMainThreadStallPredatesAcceptDespiteTolerance(t *testing.T) { + // Why 40s: exceeds the elapsed-since-accept time (a few ms in this test) plus the + // self-induced-stall margin (30s), so this stall could not have started after accept. + stalledHeartbeat := `{"jsonrpc":"2.0","id":1,"result":{"alive":true},"uloop":{"phase":"heartbeat","mainThreadStallSeconds":40}}` + done := make(chan struct{}) + connection := startHeartbeatTestServer(t, func(conn net.Conn) { + writeFrame(t, conn, heartbeatAck) + writeFrame(t, conn, stalledHeartbeat) + <-done + }) + defer close(done) + + client := NewClient( + connection, + "9.9.9", + WithSelfInducedMainThreadStallTolerance(), + withHeartbeatSilenceOverrideForTest(5*time.Second), + withMainThreadStallLimitForTest(2*time.Second), + ) + + _, err := client.SendWithProgressOutcome(context.Background(), "execute-dynamic-code", map[string]any{}, nil) + var unresponsiveErr *EditorUnresponsiveError + if !errors.As(err, &unresponsiveErr) { + t.Fatalf("expected EditorUnresponsiveError for a stall predating accept, got %v", err) + } +} + +// Verifies that a self-induced-stall-tolerant client still reports the "stuck" wording +// (not the "busy executing" wording) for a stall that predates this request's accept: it +// is a genuine freeze, and the progress message must not imply the command itself caused +// it right before failing with EditorUnresponsiveError. +func TestSendReportsStuckMessageForStallPredatingAcceptDespiteTolerance(t *testing.T) { + stalledHeartbeat := `{"jsonrpc":"2.0","id":1,"result":{"alive":true},"uloop":{"phase":"heartbeat","mainThreadStallSeconds":40}}` + done := make(chan struct{}) + connection := startHeartbeatTestServer(t, func(conn net.Conn) { + writeFrame(t, conn, heartbeatAck) + writeFrame(t, conn, stalledHeartbeat) + <-done + }) + defer close(done) + + client := NewClient( + connection, + "9.9.9", + WithSelfInducedMainThreadStallTolerance(), + withHeartbeatSilenceOverrideForTest(5*time.Second), + withMainThreadStallLimitForTest(2*time.Second), + ) + + progressMessages := []string{} + _, err := client.SendWithProgressOutcome( + context.Background(), + "execute-dynamic-code", + map[string]any{}, + func(event progress.Event) { + progressMessages = append(progressMessages, event.Message) + }, + ) + var unresponsiveErr *EditorUnresponsiveError + if !errors.As(err, &unresponsiveErr) { + t.Fatalf("expected EditorUnresponsiveError for a stall predating accept, got %v", err) + } + + joinedMessages := strings.Join(progressMessages, "\n") + if !strings.Contains(joinedMessages, "stuck") { + t.Fatalf("progress should still say stuck for a genuine freeze: %#v", progressMessages) + } + if strings.Contains(joinedMessages, "busy executing") { + t.Fatalf("progress must not say busy executing for a stall predating accept: %#v", progressMessages) + } +} + // Verifies that an explicit response timeout stays an absolute deadline: heartbeats // are skipped but must not extend it (compile relies on this to fall back to polling). func TestSendKeepsExplicitResponseTimeoutDespiteHeartbeats(t *testing.T) { diff --git a/cli/common/unityipc/client_options.go b/cli/common/unityipc/client_options.go index 1b4f8d3d90..5955e31f68 100644 --- a/cli/common/unityipc/client_options.go +++ b/cli/common/unityipc/client_options.go @@ -9,6 +9,7 @@ type ClientOptions struct { heartbeatSilenceOverride time.Duration mainThreadStallLimit time.Duration mainThreadStallHandler func(float64) + selfInducedStallTolerant bool } // ClientOption applies one optional IPC client setting. @@ -28,6 +29,18 @@ func WithMainThreadStallHandler(handler func(float64)) ClientOption { } } +// WithSelfInducedMainThreadStallTolerance exempts a heartbeat's main-thread stall from +// EditorUnresponsiveError when the stall cannot predate this request's own accept (within a +// margin): a command that itself blocks the main thread synchronously (e.g. a long +// execute-dynamic-code snippet) looks identical to a frozen editor on the stall counter alone. +// A stall that already exceeds the elapsed-since-accept time was running before this request +// started and still fails as a genuine freeze. +func WithSelfInducedMainThreadStallTolerance() ClientOption { + return func(options *ClientOptions) { + options.selfInducedStallTolerant = true + } +} + func withAcceptTimeoutForTest(timeout time.Duration) ClientOption { return func(options *ClientOptions) { options.acceptTimeout = timeout @@ -84,6 +97,19 @@ func (client *Client) getMainThreadStallLimit() time.Duration { return defaultMainThreadStallLimit } +// Why margin: heartbeat delivery and clock skew between accept and the first stall report +// add slack; a stall a few seconds beyond elapsed-since-accept is still self-induced, not +// evidence the freeze predates this request. +const selfInducedStallMargin = 30 * time.Second + +func (client *Client) isSelfInducedStall(stallSeconds float64, acceptedAt time.Time) bool { + if !client.options.selfInducedStallTolerant { + return false + } + elapsedSinceAccept := time.Since(acceptedAt) + selfInducedStallMargin + return stallSeconds <= elapsedSinceAccept.Seconds() +} + func (client *Client) nextRequestID() int { client.requestIDMu.Lock() defer client.requestIDMu.Unlock() diff --git a/cli/dispatcher/shared-inputs-stamp.json b/cli/dispatcher/shared-inputs-stamp.json index 78a6de6f57..9bb4aef54a 100644 --- a/cli/dispatcher/shared-inputs-stamp.json +++ b/cli/dispatcher/shared-inputs-stamp.json @@ -1,4 +1,4 @@ { "schemaVersion": 1, - "sharedInputsHash": "9861856df997eec3000b92ac75d9da01a6b4ef40" + "sharedInputsHash": "e9449b2ff1773625d43f39e1d71cab7440bb70ca" } diff --git a/cli/project-runner/internal/projectrunner/connection_retry.go b/cli/project-runner/internal/projectrunner/connection_retry.go index 1ac03cd378..6c163230b9 100644 --- a/cli/project-runner/internal/projectrunner/connection_retry.go +++ b/cli/project-runner/internal/projectrunner/connection_retry.go @@ -210,7 +210,7 @@ func sendWithTransientConnectionRetryWithDeps( retryTicker := time.NewTicker(deps.retryPoll) defer retryTicker.Stop() for { - client := newConnectionRetryClient(connection, responseTimeout, func(stallSeconds float64) { + client := newConnectionRetryClient(connection, method, responseTimeout, func(stallSeconds float64) { focusController.handleMainThreadStall(ctx, stallSeconds) }) // Each attempt keeps the base accept bound: a dispatched request that never gets diff --git a/cli/project-runner/internal/projectrunner/connection_retry_flow.go b/cli/project-runner/internal/projectrunner/connection_retry_flow.go index c242a150f6..411ec0fae2 100644 --- a/cli/project-runner/internal/projectrunner/connection_retry_flow.go +++ b/cli/project-runner/internal/projectrunner/connection_retry_flow.go @@ -7,12 +7,14 @@ import ( clierrors "github.com/hatayama/unity-cli-loop/common/errors" "github.com/hatayama/unity-cli-loop/common/clicontract" + "github.com/hatayama/unity-cli-loop/common/clicore" "github.com/hatayama/unity-cli-loop/common/unityipc" "github.com/hatayama/unity-cli-loop/common/unityprocess" ) func newConnectionRetryClient( connection unityipc.Connection, + method string, responseTimeout time.Duration, mainThreadStallHandler func(float64), ) *unityipc.Client { @@ -20,7 +22,18 @@ func newConnectionRetryClient( if responseTimeout > 0 { client = client.WithResponseTimeout(responseTimeout) } - return client.WithMainThreadStallHandler(mainThreadStallHandler) + client = client.WithMainThreadStallHandler(mainThreadStallHandler) + if commandNeedsSelfInducedStallTolerance(method) { + client = client.WithSelfInducedMainThreadStallTolerance() + } + return client +} + +// Why only execute-dynamic-code: a long synchronous snippet blocks Unity's main thread +// from pumping update ticks by design, which looks identical to a frozen editor on the +// stall counter alone. Other commands' stalls stay a genuine freeze signal. +func commandNeedsSelfInducedStallTolerance(method string) bool { + return method == clicore.ExecuteDynamicCodeCommandName } func finishBusyRetry( diff --git a/cli/project-runner/internal/projectrunner/connection_retry_flow_test.go b/cli/project-runner/internal/projectrunner/connection_retry_flow_test.go new file mode 100644 index 0000000000..e38f4e0330 --- /dev/null +++ b/cli/project-runner/internal/projectrunner/connection_retry_flow_test.go @@ -0,0 +1,21 @@ +package projectrunner + +import ( + "testing" + + "github.com/hatayama/unity-cli-loop/common/clicore" +) + +// Verifies only execute-dynamic-code gets main-thread stall tolerance: other commands' +// stalls must keep failing as a genuine freeze signal. +func TestCommandNeedsSelfInducedStallToleranceOnlyForExecuteDynamicCode(t *testing.T) { + if !commandNeedsSelfInducedStallTolerance(clicore.ExecuteDynamicCodeCommandName) { + t.Fatal("expected execute-dynamic-code to need self-induced stall tolerance") + } + if commandNeedsSelfInducedStallTolerance("compile") { + t.Fatal("expected compile to not need self-induced stall tolerance") + } + if commandNeedsSelfInducedStallTolerance("run-tests") { + t.Fatal("expected run-tests to not need self-induced stall tolerance") + } +} diff --git a/cli/project-runner/shared-inputs-stamp.json b/cli/project-runner/shared-inputs-stamp.json index 88c51ab58d..58da24ec82 100644 --- a/cli/project-runner/shared-inputs-stamp.json +++ b/cli/project-runner/shared-inputs-stamp.json @@ -1,4 +1,4 @@ { "schemaVersion": 1, - "sharedInputsHash": "f40c86b687ba208461a39f19ecca41b522d0fd3f" + "sharedInputsHash": "15c05452ea2fa09b729ea0916c41f168ce5d4c8f" }