fix: Keep execute-dynamic-code waiting through self-induced main-thread stalls

Packages/src/Editor/FirstPartyTools/ExecuteDynamicCode/ExecuteDynamicCodeUseCase.cs

@@ -32,13 +32,19 @@ public async Task<ExecuteDynamicCodeResponse> 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<string, object> parameters)
         {
             if (parameters == null || parameters.Count == 0)

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(

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) {

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()

cli/dispatcher/shared-inputs-stamp.json

@@ -1,4 +1,4 @@
 {
   "schemaVersion": 1,
-  "sharedInputsHash": "9861856df997eec3000b92ac75d9da01a6b4ef40"
+  "sharedInputsHash": "e9449b2ff1773625d43f39e1d71cab7440bb70ca"
 }

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

cli/project-runner/internal/projectrunner/connection_retry_flow.go

@@ -7,20 +7,33 @@ 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 {
 	client := unityipc.NewClient(connection, clicontract.ProjectRunnerVersion())
 	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(