diff --git a/Packages/src/Editor/Domain/CliConstants.cs b/Packages/src/Editor/Domain/CliConstants.cs index aa953aac8b..1e063fecbd 100644 --- a/Packages/src/Editor/Domain/CliConstants.cs +++ b/Packages/src/Editor/Domain/CliConstants.cs @@ -6,7 +6,7 @@ namespace io.github.hatayama.UnityCliLoop.Domain public static class CliConstants { public const string EXECUTABLE_NAME = "uloop"; - public const string MINIMUM_REQUIRED_CLI_VERSION = "3.0.0-beta.24"; + public const string MINIMUM_REQUIRED_CLI_VERSION = "3.0.0-beta.25"; public const string MINIMUM_REQUIRED_CLI_RELEASE_TAG = CLI_RELEASE_TAG_PREFIX + MINIMUM_REQUIRED_CLI_VERSION; public const string VERSION_FLAG = "--version"; public const string SHORT_VERSION_FLAG = "-v"; diff --git a/Packages/src/Editor/FirstPartyTools/Compile/CompileController.cs b/Packages/src/Editor/FirstPartyTools/Compile/CompileController.cs index 71f6b5a303..fc5eeb205e 100644 --- a/Packages/src/Editor/FirstPartyTools/Compile/CompileController.cs +++ b/Packages/src/Editor/FirstPartyTools/Compile/CompileController.cs @@ -24,6 +24,7 @@ public class CompileController : IDisposable private bool _isForceCompile = false; private bool _reloadExternalSceneChanges = true; private CompileResultRecordingContext _resultRecordingContext = CompileResultRecordingContext.Disabled(); + private DateTime _compileStartedAtUtc = DateTime.MinValue; /// /// Event that occurs when compilation is complete. @@ -134,6 +135,7 @@ public async Task TryCompileAsync(bool forceRecompile, Cancellati _isCompiling = true; _compileMessages.Clear(); + _compileStartedAtUtc = DateTime.UtcNow; TaskCompletionSource compileTask = new(); _currentCompileTask = compileTask; _isForceCompile = forceRecompile; @@ -198,6 +200,7 @@ public async Task TryCompileAsync(bool forceRecompile, Cancellati _currentCompileTask = null; _isCompiling = false; _isForceCompile = false; + _compileStartedAtUtc = DateTime.MinValue; compileTask.TrySetCanceled(); } } @@ -486,6 +489,7 @@ private void CompleteCompileRequest(CompileResult result, bool unregisterEvents) _isCompiling = false; _isForceCompile = false; _resultRecordingContext = CompileResultRecordingContext.Disabled(); + _compileStartedAtUtc = DateTime.MinValue; } task?.TrySetResult(result); @@ -542,9 +546,42 @@ public void ClearMessages() private void HandleCompileFinished(object context) { CompileResult result = CreateCompileResult(); + LogCompileFinishCallbackReceived(result); CompleteCompileRequest(result, unregisterEvents: true); } + private void LogCompileFinishCallbackReceived(CompileResult result) + { + UnityEngine.Debug.Assert(result != null, "result must not be null"); + + string requestId = _resultRecordingContext.Enabled + ? _resultRecordingContext.RequestId + : ""; + VibeLogger.LogInfo( + "compile_finish_callback_received", + "Unity compilationFinished callback was received.", + new + { + request_id = requestId, + success = result.Success, + error_count = result.ErrorCount, + warning_count = result.WarningCount, + is_indeterminate = result.IsIndeterminate, + elapsed_ms = CompileElapsedMilliseconds() + }, + requestId); + } + + private long CompileElapsedMilliseconds() + { + if (_compileStartedAtUtc == DateTime.MinValue) + { + return 0; + } + + return (long)(DateTime.UtcNow - _compileStartedAtUtc).TotalMilliseconds; + } + /// /// Handler for when assembly compilation is complete. /// @@ -755,6 +792,7 @@ public void Cleanup() _isForceCompile = false; _reloadExternalSceneChanges = true; _resultRecordingContext = CompileResultRecordingContext.Disabled(); + _compileStartedAtUtc = DateTime.MinValue; } /// diff --git a/Packages/src/Editor/FirstPartyTools/Compile/CompileSessionResultService.cs b/Packages/src/Editor/FirstPartyTools/Compile/CompileSessionResultService.cs index c791a7792f..71bc73a85b 100644 --- a/Packages/src/Editor/FirstPartyTools/Compile/CompileSessionResultService.cs +++ b/Packages/src/Editor/FirstPartyTools/Compile/CompileSessionResultService.cs @@ -62,6 +62,10 @@ internal static void StoreCompileResult( result.ProjectRoot = UnityCliLoopPathResolver.GetProjectRoot(); string resultJson = JsonConvert.SerializeObject(result, Formatting.None); + UnityCliLoopStoredCompileResult previousResult = + sessionStateService.GetCompileResult(requestId); + UnityCliLoopPendingCompileRequest pendingRequest = + sessionStateService.GetPendingCompileRequestForRequestId(requestId); sessionStateService.StoreCompileResult( requestId, forceRecompile, @@ -80,7 +84,10 @@ internal static void StoreCompileResult( error_count = result.ErrorCount, warning_count = result.WarningCount, result_bytes = System.Text.Encoding.UTF8.GetByteCount(resultJson), - pending_request_cleared = pendingRequestCleared + store_sequence = previousResult.HasResult ? 2 : 1, + pending_request_before = pendingRequest.HasRequest, + pending_request_cleared = pendingRequestCleared, + duplicate_result_for_request = previousResult.HasResult }, correlationId); } diff --git a/Packages/src/Editor/FirstPartyTools/Compile/CompileUseCase.cs b/Packages/src/Editor/FirstPartyTools/Compile/CompileUseCase.cs index 4ef4de6191..0475478a67 100644 --- a/Packages/src/Editor/FirstPartyTools/Compile/CompileUseCase.cs +++ b/Packages/src/Editor/FirstPartyTools/Compile/CompileUseCase.cs @@ -42,11 +42,12 @@ public async Task CompileAsync(UnityCliLoopCompileReq PrepareResultStorage(request); string correlationId = ResolveCorrelationId(request); + LogCompileRequestReceived(request, correlationId); DateTime utcNow = DateTime.UtcNow; _sessionStateService.ClearExpiredCompileResult(utcNow); _sessionStateService.ClearExpiredPendingCompileRequest(utcNow); - MarkPendingCompileRequestIfNeeded(request, utcNow); + MarkPendingCompileRequestIfNeeded(request, utcNow, correlationId); // 1. Play Mode preparation check PlayModeCompilationPreparationService preparationService = new(); @@ -234,7 +235,8 @@ private UnityCliLoopCompileResult StoreResponseIfNeeded( private void MarkPendingCompileRequestIfNeeded( UnityCliLoopCompileRequest request, - DateTime markedAtUtc) + DateTime markedAtUtc, + string correlationId) { Debug.Assert(request != null, "request must not be null"); Debug.Assert(markedAtUtc.Kind == DateTimeKind.Utc, "markedAtUtc must be UTC"); @@ -245,10 +247,47 @@ private void MarkPendingCompileRequestIfNeeded( } Debug.Assert(!string.IsNullOrWhiteSpace(request.RequestId), "request.RequestId must not be null or whitespace"); + UnityCliLoopPendingCompileRequest[] previousPendingRequests = + _sessionStateService.GetPendingCompileRequests(); _sessionStateService.MarkPendingCompileRequest( request.RequestId, request.ForceRecompile, markedAtUtc); + VibeLogger.LogInfo( + "compile_request_registered_for_status_polling", + "Registered compile request for CLI status polling.", + new + { + request_id = request.RequestId, + force_recompile = request.ForceRecompile, + pending_request_replaced = false, + pending_request_count_before = previousPendingRequests.Length, + previous_request_id = previousPendingRequests.Length > 0 + ? previousPendingRequests[0].RequestId + : "" + }, + correlationId); + } + + private static void LogCompileRequestReceived( + UnityCliLoopCompileRequest request, + string correlationId) + { + Debug.Assert(request != null, "request must not be null"); + + VibeLogger.LogInfo( + "compile_request_received", + "Received compile request from CLI.", + new + { + request_id = request.RequestId, + force_recompile = request.ForceRecompile, + wait_for_domain_reload = request.WaitForDomainReload, + stop_on_external_scene_changes = !request.ReloadExternalSceneChanges, + is_compiling = EditorApplication.isCompiling, + is_updating = EditorApplication.isUpdating + }, + correlationId); } private static string ResolveCorrelationId(UnityCliLoopCompileRequest request) diff --git a/Packages/src/Editor/Infrastructure/Api/CompileStatusBridgeCommand.cs b/Packages/src/Editor/Infrastructure/Api/CompileStatusBridgeCommand.cs index b13c19482f..061b2b38ae 100644 --- a/Packages/src/Editor/Infrastructure/Api/CompileStatusBridgeCommand.cs +++ b/Packages/src/Editor/Infrastructure/Api/CompileStatusBridgeCommand.cs @@ -30,12 +30,14 @@ public static GetCompileStatusResponse Execute(JToken paramsToken) bool isDomainReloadInProgress = sessionStateService.GetIsDomainReloadInProgress() || DomainReloadStateRegistry.IsDomainReloadInProgress(); - return BuildResponse( + GetCompileStatusResponse response = BuildResponse( requestId, isCompiling, isUpdating, isDomainReloadInProgress, sessionStateService); + LogCompileStatusQueryReceived(requestId, response); + return response; } internal static GetCompileStatusResponse BuildResponse( @@ -81,6 +83,28 @@ private static string ReadRequestId(JToken paramsToken) return requestIdToken?.ToString() ?? ""; } + private static void LogCompileStatusQueryReceived( + string requestId, + GetCompileStatusResponse response) + { + Debug.Assert(response != null, "response must not be null"); + + VibeLogger.LogInfo( + "compile_status_query_received", + "Received compile status polling request from CLI.", + new + { + request_id = requestId, + ready = response.Ready, + has_result = response.HasResult, + is_compiling = response.IsCompiling, + is_updating = response.IsUpdating, + is_domain_reload_in_progress = response.IsDomainReloadInProgress, + message = response.Message + }, + requestId); + } + private static UnityCliLoopStoredCompileResult RecoverPendingCompileResult( string requestId, UnityCliLoopEditorSessionStateService sessionStateService) diff --git a/Packages/src/Editor/Infrastructure/Server/DomainReloadDetectionFileService.cs b/Packages/src/Editor/Infrastructure/Server/DomainReloadDetectionFileService.cs index 6501dc3270..c18385cfda 100644 --- a/Packages/src/Editor/Infrastructure/Server/DomainReloadDetectionFileService.cs +++ b/Packages/src/Editor/Infrastructure/Server/DomainReloadDetectionFileService.cs @@ -58,6 +58,8 @@ public void StartDomainReload(string correlationId, bool serverIsRunning) return; } + UnityCliLoopPendingCompileRequest[] pendingCompileRequests = + _sessionStateService.GetPendingCompileRequests(); _sessionStateService.MarkDomainReloadStarted(serverIsRunning); UnityCliLoopEditorDomainReloadStateProvider.SetDomainReloadInProgressFromMainThread(true); @@ -68,7 +70,9 @@ public void StartDomainReload(string correlationId, bool serverIsRunning) "Domain reload starting", new { - server_running = serverIsRunning + server_running = serverIsRunning, + pending_compile_request_count = pendingCompileRequests.Length, + pending_compile_request_ids = ToPendingCompileRequestIds(pendingCompileRequests) }, correlationId ); @@ -88,6 +92,8 @@ public void CompleteDomainReload(string correlationId) MigrateLegacySessionStateIfNeeded(); bool serverWillRecover = !_sessionStateService.GetIsServerManuallyStopped(); + UnityCliLoopPendingCompileRequest[] pendingCompileRequests = + _sessionStateService.GetPendingCompileRequests(); // Clear Domain Reload completion flag _sessionStateService.ClearDomainReloadFlag(); @@ -99,7 +105,12 @@ public void CompleteDomainReload(string correlationId) serverWillRecover ? "Domain reload completed - starting server recovery process" : "Domain reload completed - server was manually stopped before recovery", - new { transport = "project_ipc" }, + new + { + transport = "project_ipc", + pending_compile_request_count = pendingCompileRequests.Length, + pending_compile_request_ids = ToPendingCompileRequestIds(pendingCompileRequests) + }, correlationId ); } @@ -171,5 +182,19 @@ private void MigrateLegacySessionStateIfNeeded() _legacySessionStateReader.Clear(); } + + private static string[] ToPendingCompileRequestIds( + UnityCliLoopPendingCompileRequest[] pendingCompileRequests) + { + UnityEngine.Debug.Assert(pendingCompileRequests != null, "pendingCompileRequests must not be null"); + + string[] requestIds = new string[pendingCompileRequests.Length]; + for (int i = 0; i < pendingCompileRequests.Length; i++) + { + requestIds[i] = pendingCompileRequests[i].RequestId; + } + + return requestIds; + } } } diff --git a/Packages/src/Editor/Infrastructure/Server/UnityCliLoopServerController.cs b/Packages/src/Editor/Infrastructure/Server/UnityCliLoopServerController.cs index 4c431175d1..1e9cbe6092 100644 --- a/Packages/src/Editor/Infrastructure/Server/UnityCliLoopServerController.cs +++ b/Packages/src/Editor/Infrastructure/Server/UnityCliLoopServerController.cs @@ -629,7 +629,10 @@ private async Task TryBindWithWaitAsync( server = _serverInstanceFactory.Create(); server.StartServer(); _bridgeServer = server; - VibeLogger.LogInfo("binding_success", $"endpoint={server.Endpoint}"); + VibeLogger.LogInfo( + "binding_success", + "Unity CLI Loop server bound the project IPC endpoint.", + new { endpoint = server.Endpoint }); return true; } catch (Exception ex) diff --git a/cli/contract.json b/cli/contract.json index 6279babbe5..06e57c6b20 100644 --- a/cli/contract.json +++ b/cli/contract.json @@ -1,4 +1,4 @@ { "schemaVersion": 1, - "cliVersion": "3.0.0-beta.24" + "cliVersion": "3.0.0-beta.25" } diff --git a/cli/internal/cli/cli_vibe.go b/cli/internal/cli/cli_vibe.go index 2280fc72e1..79651e0733 100644 --- a/cli/internal/cli/cli_vibe.go +++ b/cli/internal/cli/cli_vibe.go @@ -1,6 +1,8 @@ package cli import ( + "crypto/sha256" + "encoding/hex" "encoding/json" "fmt" "os" @@ -13,6 +15,8 @@ const ( cliVibeLogDirectory = ".uloop/outputs/VibeLogs" cliVibeLogPrefix = "cli_vibe" cliVibeLogEnvName = "ULOOP_DEBUG" + + cliProjectIdentityHashLength = 16 ) type cliVibeLogEntry struct { @@ -81,3 +85,16 @@ func isCliVibeLogEnabled() bool { } return !strings.EqualFold(value, "false") } + +func projectIdentity(projectRoot string) string { + if projectRoot == "" { + return "" + } + + canonicalProjectRoot, err := filepath.EvalSymlinks(projectRoot) + if err != nil { + canonicalProjectRoot = projectRoot + } + sum := sha256.Sum256([]byte(canonicalProjectRoot)) + return "project_" + hex.EncodeToString(sum[:])[:cliProjectIdentityHashLength] +} diff --git a/cli/internal/cli/compile_wait.go b/cli/internal/cli/compile_wait.go index ed87faae18..a0364023c7 100644 --- a/cli/internal/cli/compile_wait.go +++ b/cli/internal/cli/compile_wait.go @@ -105,6 +105,12 @@ func isSafeCompileRequestID(requestID string) bool { func waitForCompileCompletion(ctx context.Context, options compileCompletionOptions) (json.RawMessage, bool, error) { startedAt := time.Now() deadline := startedAt.Add(options.timeout) + attempts := 0 + var lastStatus compileStatusResponse + var lastErr error + lastObservationKey := "" + + logCompileStatusPollStart(options, startedAt, deadline) for { now := time.Now() @@ -112,20 +118,28 @@ func waitForCompileCompletion(ctx context.Context, options compileCompletionOpti break } + attempts++ status, err := queryCompileStatus(ctx, options.connection, options.requestID) + lastErr = err if err == nil && status.Ready && status.HasResult && len(status.Result) > 0 { + logCompileStatusPollObservedIfChanged(options, startedAt, attempts, status, nil, &lastObservationKey) + logCompileStatusPollComplete(options, startedAt, attempts, status) return status.Result, true, nil } + if err == nil { + lastStatus = status + } + logCompileStatusPollObservedIfChanged(options, startedAt, attempts, status, err, &lastObservationKey) select { case <-ctx.Done(): - logCompileWaitCancelled(options, startedAt, ctx.Err()) + logCompileWaitCancelled(options, startedAt, attempts, lastStatus, lastErr, ctx.Err()) return nil, false, ctx.Err() case <-time.After(options.pollInterval): } } - logCompileWaitTimedOut(options, startedAt) + logCompileWaitTimedOut(options, startedAt, attempts, lastStatus, lastErr) return nil, false, nil } @@ -134,6 +148,14 @@ func compileForceRecompileEnabled(params map[string]any) bool { return ok && value } +func compileReloadExternalSceneChangesEnabled(params map[string]any) bool { + value, ok := params[reloadExternalSceneChangesPropertyName].(bool) + if !ok { + return true + } + return value +} + func queryCompileStatusFromUnity(ctx context.Context, connection unityipc.Connection, requestID string) (compileStatusResponse, error) { probeContext, cancel := context.WithTimeout(ctx, compileStatusProbeTimeout) defer cancel() @@ -180,23 +202,248 @@ func isFinalResponseTimeoutError(err error) bool { return strings.Contains(err.Error(), "i/o timeout") } -func logCompileWaitTimedOut(options compileCompletionOptions, startedAt time.Time) { +func logCliDebugModeResolved(connection unityipc.Connection, command string) { + if !isCliVibeLogEnabled() { + return + } + + _ = writeCliVibeLog(connection.ProjectRoot, cliVibeLogEntry{ + Level: "INFO", + Operation: "cli_debug_mode_resolved", + Message: "Resolved CLI debug mode for the command.", + Context: map[string]any{ + "command": command, + "debug_enabled": true, + "debug_source": "env", + "project_identity": projectIdentity(connection.ProjectRoot), + "cli_version": version, + }, + }) +} + +func logCompileRequestPrepared( + connection unityipc.Connection, + params map[string]any, + requestID string, +) { + if !isCliVibeLogEnabled() { + return + } + + reloadExternalSceneChanges := compileReloadExternalSceneChangesEnabled(params) + _ = writeCliVibeLog(connection.ProjectRoot, cliVibeLogEntry{ + Level: "INFO", + Operation: "cli_compile_request_prepared", + Message: "Prepared compile request parameters before dispatch.", + Context: map[string]any{ + "command": compileCommandName, + "request_id": requestID, + "wait_for_domain_reload": true, + "force_recompile": compileForceRecompileEnabled(params), + "reload_external_scene_changes": reloadExternalSceneChanges, + "stop_on_external_scene_changes": !reloadExternalSceneChanges, + "project_identity": projectIdentity(connection.ProjectRoot), + "endpoint": connection.Endpoint.Address, + "timeout_ms": compileWaitTimeout.Milliseconds(), + "poll_interval_ms": compileWaitPollInterval.Milliseconds(), + "response_timeout_ms": compileResponseTimeout.Milliseconds(), + }, + CorrelationID: requestID, + }) +} + +func logCompileRequestSendResult( + connection unityipc.Connection, + requestID string, + outcome unityipc.UnitySendOutcome, + err error, + startedAt time.Time, +) { + if !isCliVibeLogEnabled() { + return + } + + _ = writeCliVibeLog(connection.ProjectRoot, cliVibeLogEntry{ + Level: compileRequestSendResultLogLevel(err), + Operation: "cli_compile_request_send_result", + Message: "Recorded compile request dispatch outcome before status polling.", + Context: map[string]any{ + "command": compileCommandName, + "request_id": requestID, + "request_dispatched": outcome.RequestDispatched, + "request_accepted": outcome.RequestAccepted, + "response_received": err == nil && len(outcome.Result) > 0, + "response_timeout": err != nil && isFinalResponseTimeoutError(err), + "transport_error": errorMessage(err), + "elapsed_ms": time.Since(startedAt).Milliseconds(), + "endpoint": connection.Endpoint.Address, + "project_identity": projectIdentity(connection.ProjectRoot), + "outcome_total_ms": outcome.Timing.Total.Milliseconds(), + "outcome_dial_ms": outcome.Timing.Dial.Milliseconds(), + "outcome_write_ms": outcome.Timing.Write.Milliseconds(), + "outcome_read_ms": outcome.Timing.Read.Milliseconds(), + "outcome_decode_ms": outcome.Timing.Decode.Milliseconds(), + }, + CorrelationID: requestID, + }) +} + +func compileRequestSendResultLogLevel(err error) string { + if err == nil { + return "INFO" + } + return "WARNING" +} + +func logCompileStatusPollStart( + options compileCompletionOptions, + startedAt time.Time, + deadline time.Time, +) { + if !isCliVibeLogEnabled() { + return + } + + _ = writeCliVibeLog(options.connection.ProjectRoot, cliVibeLogEntry{ + Level: "INFO", + Operation: "cli_compile_status_poll_start", + Message: "Started polling Unity compile status.", + Context: compileWaitLogContext(options, startedAt, map[string]any{ + "started_at": startedAt.UTC().Format(time.RFC3339Nano), + "deadline_at": deadline.UTC().Format(time.RFC3339Nano), + "project_identity": projectIdentity(options.connection.ProjectRoot), + }), + CorrelationID: options.requestID, + }) +} + +func logCompileStatusPollObservedIfChanged( + options compileCompletionOptions, + startedAt time.Time, + attempt int, + status compileStatusResponse, + err error, + lastObservationKey *string, +) { + if !isCliVibeLogEnabled() { + return + } + + observationKey := compileStatusObservationKey(status, err) + if observationKey == *lastObservationKey { + return + } + + *lastObservationKey = observationKey + _ = writeCliVibeLog(options.connection.ProjectRoot, cliVibeLogEntry{ + Level: compileStatusPollObservedLogLevel(err), + Operation: "cli_compile_status_poll_observed", + Message: "Observed Unity compile status while polling.", + Context: compileWaitLogContext(options, startedAt, map[string]any{ + "attempt": attempt, + "ready": status.Ready, + "has_result": status.HasResult, + "is_compiling": status.IsCompiling, + "is_updating": status.IsUpdating, + "is_domain_reload_in_progress": status.IsDomainReloadInProgress, + "message": status.Message, + "transport_error": errorMessage(err), + }), + CorrelationID: options.requestID, + }) +} + +func compileStatusPollObservedLogLevel(err error) string { + if err == nil { + return "INFO" + } + return "WARNING" +} + +func compileStatusObservationKey(status compileStatusResponse, err error) string { + return fmt.Sprintf( + "%t|%t|%t|%t|%t|%s|%s", + status.Ready, + status.HasResult, + status.IsCompiling, + status.IsUpdating, + status.IsDomainReloadInProgress, + status.Message, + errorMessage(err), + ) +} + +func logCompileStatusPollComplete( + options compileCompletionOptions, + startedAt time.Time, + attempts int, + status compileStatusResponse, +) { + if !isCliVibeLogEnabled() { + return + } + + summary := compileResultLogSummary(status.Result) + _ = writeCliVibeLog(options.connection.ProjectRoot, cliVibeLogEntry{ + Level: "INFO", + Operation: "cli_compile_status_poll_complete", + Message: "Unity compile status polling returned the stored result.", + Context: compileWaitLogContext(options, startedAt, map[string]any{ + "poll_attempts": attempts, + "success": summary.success, + "error_count": summary.errorCount, + "warning_count": summary.warningCount, + }), + CorrelationID: options.requestID, + }) +} + +func logCompileWaitTimedOut( + options compileCompletionOptions, + startedAt time.Time, + attempts int, + lastStatus compileStatusResponse, + lastErr error, +) { + if !isCliVibeLogEnabled() { + return + } + _ = writeCliVibeLog(options.connection.ProjectRoot, cliVibeLogEntry{ - Level: "WARNING", - Operation: "cli_compile_status_wait_timed_out", - Message: "Timed out while polling Unity compile status.", - Context: compileWaitLogContext(options, startedAt, nil), + Level: "WARNING", + Operation: "cli_compile_status_poll_timeout", + Message: "Timed out while polling Unity compile status.", + Context: compileWaitLogContext(options, startedAt, map[string]any{ + "poll_attempts": attempts, + "last_status": compileStatusLogContext(lastStatus), + "last_transport_error": errorMessage(lastErr), + "project_identity": projectIdentity(options.connection.ProjectRoot), + }), CorrelationID: options.requestID, }) } -func logCompileWaitCancelled(options compileCompletionOptions, startedAt time.Time, err error) { +func logCompileWaitCancelled( + options compileCompletionOptions, + startedAt time.Time, + attempts int, + lastStatus compileStatusResponse, + lastErr error, + cancelErr error, +) { + if !isCliVibeLogEnabled() { + return + } + _ = writeCliVibeLog(options.connection.ProjectRoot, cliVibeLogEntry{ Level: "WARNING", - Operation: "cli_compile_status_wait_cancelled", + Operation: "cli_compile_status_poll_cancelled", Message: "Compile status polling was cancelled.", Context: compileWaitLogContext(options, startedAt, map[string]any{ - "error": errorMessage(err), + "poll_attempts": attempts, + "last_status": compileStatusLogContext(lastStatus), + "last_transport_error": errorMessage(lastErr), + "cancel_error": errorMessage(cancelErr), }), CorrelationID: options.requestID, }) @@ -221,3 +468,32 @@ func compileWaitLogContext( } return context } + +type compileResultSummary struct { + success any + errorCount any + warningCount any +} + +func compileResultLogSummary(result json.RawMessage) compileResultSummary { + var payload map[string]any + if err := json.Unmarshal(result, &payload); err != nil { + return compileResultSummary{} + } + return compileResultSummary{ + success: payload["Success"], + errorCount: payload["ErrorCount"], + warningCount: payload["WarningCount"], + } +} + +func compileStatusLogContext(status compileStatusResponse) map[string]any { + return map[string]any{ + "ready": status.Ready, + "has_result": status.HasResult, + "is_compiling": status.IsCompiling, + "is_updating": status.IsUpdating, + "is_domain_reload_in_progress": status.IsDomainReloadInProgress, + "message": status.Message, + } +} diff --git a/cli/internal/cli/compile_wait_test.go b/cli/internal/cli/compile_wait_test.go index fa302e7691..275bfe0b41 100644 --- a/cli/internal/cli/compile_wait_test.go +++ b/cli/internal/cli/compile_wait_test.go @@ -1,10 +1,13 @@ package cli import ( + "bufio" "bytes" "context" "encoding/json" "fmt" + "net" + "runtime" "strings" "testing" "time" @@ -175,6 +178,63 @@ func TestWaitForCompileCompletionReturnsReadyStatusResult(t *testing.T) { } } +// Verifies compile wait writes the status polling lifecycle to CLI Vibe logs. +func TestWaitForCompileCompletionWritesPollLifecycleVibeLogs(t *testing.T) { + enableCliVibeLog(t) + connection := compileWaitTestConnection(t) + requestID := "compile_poll_lifecycle_test" + callCount := 0 + replaceQueryCompileStatus(t, func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + callCount++ + if callCount == 1 { + return compileStatusResponse{ + Ready: false, + HasResult: false, + IsCompiling: true, + Message: "Compiling", + }, nil + } + return compileStatusResponse{ + Ready: true, + HasResult: true, + Result: json.RawMessage(`{"Success":false,"ErrorCount":2,"WarningCount":1}`), + Message: "Compile result is available.", + }, nil + }) + + result, completed, err := waitForCompileCompletion(context.Background(), compileCompletionOptions{ + connection: connection, + requestID: requestID, + timeout: time.Second, + pollInterval: 5 * time.Millisecond, + }) + if err != nil { + t.Fatalf("waitForCompileCompletion failed: %v", err) + } + if !completed { + t.Fatal("compile wait did not complete") + } + if string(result) != `{"Success":false,"ErrorCount":2,"WarningCount":1}` { + t.Fatalf("result mismatch: %s", result) + } + + logContent := readOnlyCliVibeLog(t, connection.ProjectRoot) + for _, expected := range []string{ + `"operation":"cli_compile_status_poll_start"`, + `"operation":"cli_compile_status_poll_observed"`, + `"operation":"cli_compile_status_poll_complete"`, + `"request_id":"compile_poll_lifecycle_test"`, + `"poll_attempts":2`, + `"success":false`, + `"error_count":2`, + `"warning_count":1`, + } { + if !strings.Contains(logContent, expected) { + t.Fatalf("CLI Vibe log missing %q:\n%s", expected, logContent) + } + } +} + // Verifies force compile waits for Unity's stored result instead of fabricating one from idle status. func TestWaitForCompileCompletionForceCompileWaitsForStoredResult(t *testing.T) { connection := compileWaitTestConnection(t) @@ -254,7 +314,7 @@ func TestWaitForCompileCompletionWritesTimeoutVibeLog(t *testing.T) { connection := compileWaitTestConnection(t) requestID := "compile_timeout_log_test" replaceQueryCompileStatus(t, func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { - return compileStatusResponse{Ready: false}, nil + return compileStatusResponse{Ready: false, IsCompiling: true, Message: "Compiling"}, nil }) _, completed, err := waitForCompileCompletion(context.Background(), compileCompletionOptions{ @@ -272,8 +332,12 @@ func TestWaitForCompileCompletionWritesTimeoutVibeLog(t *testing.T) { logContent := readOnlyCliVibeLog(t, connection.ProjectRoot) for _, expected := range []string{ - `"operation":"cli_compile_status_wait_timed_out"`, + `"operation":"cli_compile_status_poll_start"`, + `"operation":"cli_compile_status_poll_observed"`, + `"operation":"cli_compile_status_poll_timeout"`, `"request_id":"compile_timeout_log_test"`, + `"last_status"`, + `"poll_attempts"`, } { if !strings.Contains(logContent, expected) { t.Fatalf("CLI Vibe log missing %q:\n%s", expected, logContent) @@ -281,6 +345,139 @@ func TestWaitForCompileCompletionWritesTimeoutVibeLog(t *testing.T) { } } +// Verifies that compile status wait cancellations are visible in CLI Vibe logs. +func TestWaitForCompileCompletionWritesCancellationVibeLog(t *testing.T) { + enableCliVibeLog(t) + connection := compileWaitTestConnection(t) + requestID := "compile_cancel_log_test" + ctx, cancel := context.WithCancel(context.Background()) + replaceQueryCompileStatus(t, func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + cancel() + return compileStatusResponse{Ready: false, IsDomainReloadInProgress: true}, nil + }) + + _, completed, err := waitForCompileCompletion(ctx, compileCompletionOptions{ + connection: connection, + requestID: requestID, + timeout: time.Second, + pollInterval: time.Second, + }) + if err == nil { + t.Fatal("waitForCompileCompletion should return the cancellation error") + } + if completed { + t.Fatal("compile wait should not complete after cancellation") + } + + logContent := readOnlyCliVibeLog(t, connection.ProjectRoot) + for _, expected := range []string{ + `"operation":"cli_compile_status_poll_cancelled"`, + `"request_id":"compile_cancel_log_test"`, + `"last_status"`, + `"poll_attempts":1`, + } { + if !strings.Contains(logContent, expected) { + t.Fatalf("CLI Vibe log missing %q:\n%s", expected, logContent) + } + } +} + +// Verifies the compile command records request preparation and send outcome diagnostics. +func TestRunCompileWithDomainReloadWaitWritesRequestLifecycleVibeLogs(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("TCP endpoint injection is only used by this non-Windows client test") + } + + enableCliVibeLog(t) + listener, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatalf("failed to listen: %v", err) + } + defer func() { + _ = listener.Close() + }() + + serverErr := make(chan error, 1) + go func() { + conn, err := listener.Accept() + if err != nil { + serverErr <- err + return + } + defer func() { + _ = conn.Close() + }() + + if _, err := unityipc.Read(bufio.NewReader(conn)); err != nil { + serverErr <- err + return + } + + accepted := []byte(`{"jsonrpc":"2.0","result":{"accepted":true},"uloop":{"phase":"accepted"},"id":1}`) + if err := unityipc.Write(conn, accepted); err != nil { + serverErr <- err + return + } + + final := []byte(`{"jsonrpc":"2.0","result":{"Accepted":true},"id":1}`) + if err := unityipc.Write(conn, final); err != nil { + serverErr <- err + return + } + }() + + replaceQueryCompileStatus(t, func(context.Context, unityipc.Connection, string) (compileStatusResponse, error) { + return compileStatusResponse{ + Ready: true, + HasResult: true, + Result: json.RawMessage(`{"Success":false,"ErrorCount":1,"WarningCount":0}`), + }, nil + }) + + projectRoot := t.TempDir() + connection := unityipc.Connection{ + Endpoint: unityipc.Endpoint{ + Network: "tcp", + Address: listener.Addr().String(), + }, + ProjectRoot: projectRoot, + } + params := map[string]any{ + compileForceParam: true, + reloadExternalSceneChangesPropertyName: false, + } + var stdout bytes.Buffer + var stderr bytes.Buffer + + code := runCompileWithDomainReloadWait(context.Background(), connection, params, &stdout, &stderr) + if code != 0 { + t.Fatalf("runCompileWithDomainReloadWait failed: code=%d stdout=%s stderr=%s", code, stdout.String(), stderr.String()) + } + + logContent := readOnlyCliVibeLog(t, projectRoot) + for _, expected := range []string{ + `"operation":"cli_debug_mode_resolved"`, + `"operation":"cli_compile_request_prepared"`, + `"operation":"cli_compile_request_send_result"`, + `"debug_source":"env"`, + `"request_dispatched":true`, + `"request_accepted":true`, + `"response_received":true`, + `"force_recompile":true`, + `"reload_external_scene_changes":false`, + } { + if !strings.Contains(logContent, expected) { + t.Fatalf("CLI Vibe log missing %q:\n%s", expected, logContent) + } + } + + select { + case err := <-serverErr: + t.Fatalf("server failed: %v", err) + default: + } +} + func TestShouldWaitForCompileStatusRequiresDispatchedTransportError(t *testing.T) { if shouldWaitForCompileStatus(fmt.Errorf("missing"), unityipc.UnitySendOutcome{}) { t.Fatal("undispatched error should not wait") diff --git a/cli/internal/cli/run.go b/cli/internal/cli/run.go index 7f9ec89f3a..a830b3a372 100644 --- a/cli/internal/cli/run.go +++ b/cli/internal/cli/run.go @@ -226,6 +226,9 @@ func runCompileWithDomainReloadWait(ctx context.Context, connection unityipc.Con return 1 } + logCliDebugModeResolved(connection, compileCommandName) + logCompileRequestPrepared(connection, params, requestID) + startedAt := time.Now() spinner := newToolSpinner(stderr, compileCommandName) outcome, err := sendWithTransientConnectionRetryAndResponseTimeout( @@ -238,6 +241,7 @@ func runCompileWithDomainReloadWait(ctx context.Context, connection unityipc.Con }, compileResponseTimeout, ) + logCompileRequestSendResult(connection, requestID, outcome, err, startedAt) if err != nil && shouldWaitForCompileStatus(err, outcome) { spinner.Update("Connection changed during compile. Waiting for Unity status...") } diff --git a/cli/internal/tools/default-tools.json b/cli/internal/tools/default-tools.json index 904923ef8f..15575a6171 100644 --- a/cli/internal/tools/default-tools.json +++ b/cli/internal/tools/default-tools.json @@ -1,5 +1,5 @@ { - "version": "3.0.0-beta.24", + "version": "3.0.0-beta.25", "tools": [ { "name": "compile",