From 0b8cce869e54d9bc8011203ede81465c52526080 Mon Sep 17 00:00:00 2001 From: hatayama Date: Wed, 3 Jun 2026 21:51:41 +0900 Subject: [PATCH 1/2] Improve compile wait VibeLog diagnostics Enable CLI VibeLog from the target Unity project's debug define so consumer runs keep CLI-side evidence without a shell override. Add structured compile request, send, polling, status, and result-store diagnostics so timeouts and duplicate Unity stores can be diagnosed after the fact. Harden Unity VibeLog JSONL appends with serialized writes, retrying, and integrity diagnostics. --- .../CompileSessionResultServiceTests.cs | 52 ++++ .../Editor/CompileStatusBridgeCommandTests.cs | 27 ++ .../Compile/CompileController.cs | 27 ++ .../Compile/CompileSessionResultService.cs | 9 +- .../FirstPartyTools/Compile/CompileUseCase.cs | 36 +++ .../Api/CompileStatusBridgeCommand.cs | 56 +++- .../DomainReloadDetectionFileService.cs | 31 +- .../Server/UnityCliLoopServerController.cs | 20 +- .../src/Editor/ToolContracts/VibeLogger.cs | 191 +++++++++--- cli/internal/cli/cli_vibe.go | 138 ++++++++- cli/internal/cli/cli_vibe_test.go | 60 ++++ cli/internal/cli/compile_wait.go | 291 +++++++++++++++++- cli/internal/cli/compile_wait_test.go | 70 ++++- cli/internal/cli/run.go | 4 + 14 files changed, 944 insertions(+), 68 deletions(-) diff --git a/Assets/Tests/Editor/CompileSessionResultServiceTests.cs b/Assets/Tests/Editor/CompileSessionResultServiceTests.cs index 000533691d..9306237cfb 100644 --- a/Assets/Tests/Editor/CompileSessionResultServiceTests.cs +++ b/Assets/Tests/Editor/CompileSessionResultServiceTests.cs @@ -1,8 +1,12 @@ using System; +using Newtonsoft.Json.Linq; using NUnit.Framework; using UnityEditor.Compilation; +using io.github.hatayama.UnityCliLoop.Domain; using io.github.hatayama.UnityCliLoop.FirstPartyTools; +using io.github.hatayama.UnityCliLoop.Infrastructure; +using io.github.hatayama.UnityCliLoop.ToolContracts; namespace io.github.hatayama.UnityCliLoop.Tests.Editor { @@ -138,5 +142,53 @@ public void CreateCompileResult_WhenForceCompileHasPreservedFailure_MapsDetailed Assert.That(response.Errors[0].File, Is.EqualTo("Assets/Scenes/SampleScene.unity")); Assert.That(response.Message, Does.Contain("externally")); } + + [Test] + public void StoreCompileResult_WhenRequestAlreadyHasResult_WritesDuplicateVibeLogContext() + { + // Verifies duplicate compile result stores are detectable from Unity-side diagnostics. + UnityCliLoopEditorSessionStateService sessionStateService = + UnityCliLoopEditorSessionStateTestFactory.CreateService(); + UnityCliLoopEditorSessionStateSnapshot originalSnapshot = + UnityCliLoopEditorSessionStateTestFactory.CaptureSnapshot(sessionStateService); + + try + { + sessionStateService.ClearAll(); + VibeLogger.ClearMemoryLogs(); + UnityCliLoopCompileResult result = new UnityCliLoopCompileResult + { + Success = true, + ErrorCount = 0, + WarningCount = 0, + }; + + CompileSessionResultService.StoreCompileResult( + sessionStateService, + "compile_duplicate_store_request", + forceRecompile: false, + result, + "compile_duplicate_store_request"); + CompileSessionResultService.StoreCompileResult( + sessionStateService, + "compile_duplicate_store_request", + forceRecompile: false, + result, + "compile_duplicate_store_request"); + + JArray logs = JArray.Parse(VibeLogger.GetLogsForAi("compile_result_session_state_store_complete")); + Assert.That(logs, Has.Count.EqualTo(2)); + JObject secondContext = (JObject)logs[1]["context"]; + Assert.That(secondContext["duplicate_result_for_request"]?.Value(), Is.True); + Assert.That(secondContext["store_sequence"]?.Value(), Is.EqualTo(2)); + Assert.That(secondContext["pending_request_before"]?.Value(), Is.False); + Assert.That(secondContext["pending_request_cleared"]?.Value(), Is.False); + } + finally + { + VibeLogger.ClearMemoryLogs(); + originalSnapshot.Restore(sessionStateService); + } + } } } diff --git a/Assets/Tests/Editor/CompileStatusBridgeCommandTests.cs b/Assets/Tests/Editor/CompileStatusBridgeCommandTests.cs index 5207ace587..1eeb32b4cb 100644 --- a/Assets/Tests/Editor/CompileStatusBridgeCommandTests.cs +++ b/Assets/Tests/Editor/CompileStatusBridgeCommandTests.cs @@ -3,6 +3,7 @@ using io.github.hatayama.UnityCliLoop.Domain; using io.github.hatayama.UnityCliLoop.Infrastructure; +using io.github.hatayama.UnityCliLoop.ToolContracts; namespace io.github.hatayama.UnityCliLoop.Tests.Editor { @@ -26,6 +27,7 @@ public void SetUp() [TearDown] public void TearDown() { + VibeLogger.ClearMemoryLogs(); _originalSnapshot.Restore(_sessionStateService); } @@ -189,5 +191,30 @@ public void BuildResponse_WhenForceCompilePendingRequestHasNoResult_ReturnsNullM Assert.That(response.Result["ErrorCount"]?.Type, Is.EqualTo(JTokenType.Null)); Assert.That(response.Result["Message"]?.Type, Is.EqualTo(JTokenType.Null)); } + + [Test] + public void BuildResponse_WhenStatusIsQueried_WritesVibeLogContext() + { + // Verifies status polling leaves enough Unity-side context to correlate CLI wait diagnostics. + VibeLogger.ClearMemoryLogs(); + string requestId = "compile_status_log_request_" + System.Guid.NewGuid().ToString("N"); + + GetCompileStatusResponse response = CompileStatusBridgeCommand.BuildResponse( + requestId, + isCompiling: true, + isUpdating: false, + isDomainReloadInProgress: false, + _sessionStateService); + + Assert.That(response.Ready, Is.False); + JArray logs = JArray.Parse(VibeLogger.GetLogsForAi("compile_status_query_received")); + Assert.That(logs, Has.Count.EqualTo(1)); + JObject context = (JObject)logs[0]["context"]; + Assert.That(context["request_id"]?.ToString(), Is.EqualTo(requestId)); + Assert.That(context["ready"]?.Value(), Is.False); + Assert.That(context["has_result"]?.Value(), Is.False); + Assert.That(context["is_compiling"]?.Value(), Is.True); + Assert.That(context["message"]?.ToString(), Does.Contain("still compiling")); + } } } diff --git a/Packages/src/Editor/FirstPartyTools/Compile/CompileController.cs b/Packages/src/Editor/FirstPartyTools/Compile/CompileController.cs index 71f6b5a303..d0d6d4c2cd 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. @@ -137,6 +138,7 @@ public async Task TryCompileAsync(bool forceRecompile, Cancellati TaskCompletionSource compileTask = new(); _currentCompileTask = compileTask; _isForceCompile = forceRecompile; + _compileStartedAtUtc = DateTime.UtcNow; bool eventsRegistered = false; bool compileTaskTransferred = false; @@ -542,9 +544,33 @@ public void ClearMessages() private void HandleCompileFinished(object context) { CompileResult result = CreateCompileResult(); + VibeLogger.LogInfo( + "compile_finish_callback_received", + "Unity compilationFinished callback fired.", + BuildCompileFinishCallbackContext(result), + _resultRecordingContext.Enabled ? _resultRecordingContext.RequestId : null); CompleteCompileRequest(result, unregisterEvents: true); } + private object BuildCompileFinishCallbackContext(CompileResult result) + { + UnityEngine.Debug.Assert(result != null, "result must not be null"); + + DateTime utcNow = DateTime.UtcNow; + double elapsedMs = _compileStartedAtUtc == DateTime.MinValue + ? 0 + : (utcNow - _compileStartedAtUtc).TotalMilliseconds; + return new + { + request_id = _resultRecordingContext.Enabled ? _resultRecordingContext.RequestId : "", + success = result.Success, + error_count = result.ErrorCount, + warning_count = result.WarningCount, + is_indeterminate = result.IsIndeterminate, + elapsed_ms = Math.Max(0, (int)elapsedMs) + }; + } + /// /// Handler for when assembly compilation is complete. /// @@ -755,6 +781,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..d15a468730 100644 --- a/Packages/src/Editor/FirstPartyTools/Compile/CompileSessionResultService.cs +++ b/Packages/src/Editor/FirstPartyTools/Compile/CompileSessionResultService.cs @@ -60,6 +60,10 @@ internal static void StoreCompileResult( Debug.Assert(!string.IsNullOrWhiteSpace(requestId), "requestId must not be null or whitespace"); Debug.Assert(result != null, "result must not be null"); + UnityCliLoopStoredCompileResult existingResult = + sessionStateService.GetCompileResult(requestId); + UnityCliLoopPendingCompileRequest pendingRequest = + sessionStateService.GetPendingCompileRequestForRequestId(requestId); result.ProjectRoot = UnityCliLoopPathResolver.GetProjectRoot(); string resultJson = JsonConvert.SerializeObject(result, Formatting.None); sessionStateService.StoreCompileResult( @@ -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 = existingResult.HasResult ? 2 : 1, + pending_request_before = pendingRequest.HasRequest, + pending_request_cleared = pendingRequestCleared, + duplicate_result_for_request = existingResult.HasResult }, correlationId); } diff --git a/Packages/src/Editor/FirstPartyTools/Compile/CompileUseCase.cs b/Packages/src/Editor/FirstPartyTools/Compile/CompileUseCase.cs index 4ef4de6191..c30c5db994 100644 --- a/Packages/src/Editor/FirstPartyTools/Compile/CompileUseCase.cs +++ b/Packages/src/Editor/FirstPartyTools/Compile/CompileUseCase.cs @@ -42,6 +42,7 @@ public async Task CompileAsync(UnityCliLoopCompileReq PrepareResultStorage(request); string correlationId = ResolveCorrelationId(request); + LogCompileRequestReceived(request, correlationId); DateTime utcNow = DateTime.UtcNow; _sessionStateService.ClearExpiredCompileResult(utcNow); @@ -245,10 +246,24 @@ private void MarkPendingCompileRequestIfNeeded( } Debug.Assert(!string.IsNullOrWhiteSpace(request.RequestId), "request.RequestId must not be null or whitespace"); + UnityCliLoopPendingCompileRequest previousRequest = + _sessionStateService.GetPendingCompileRequest(); _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, + pending_request_replaced = + previousRequest.HasRequest && previousRequest.RequestId != request.RequestId, + previous_request_id = previousRequest.HasRequest ? previousRequest.RequestId : "", + force_recompile = request.ForceRecompile + }, + request.RequestId); } private static string ResolveCorrelationId(UnityCliLoopCompileRequest request) @@ -276,6 +291,27 @@ private static object BuildCompileLogContext(UnityCliLoopCompileRequest request) }; } + 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 CreateRequestId() { long unixTimeMilliseconds = DateTimeOffset.UtcNow.ToUnixTimeMilliseconds(); diff --git a/Packages/src/Editor/Infrastructure/Api/CompileStatusBridgeCommand.cs b/Packages/src/Editor/Infrastructure/Api/CompileStatusBridgeCommand.cs index b13c19482f..a4e6e32aad 100644 --- a/Packages/src/Editor/Infrastructure/Api/CompileStatusBridgeCommand.cs +++ b/Packages/src/Editor/Infrastructure/Api/CompileStatusBridgeCommand.cs @@ -1,4 +1,5 @@ using System; +using System.Collections.Generic; using Newtonsoft.Json; using Newtonsoft.Json.Linq; using UnityEditor; @@ -18,6 +19,8 @@ internal static class CompileStatusBridgeCommand private const string RequestIdParamName = "RequestId"; private const string RecoveredCompileResultMessage = "Compilation completed, but Unity reloaded scripts before Unity CLI Loop could record detailed errors or warnings. Use get-logs to inspect the compiler output."; + private static readonly Dictionary LastLoggedStatusByRequestId = + new Dictionary(); public static GetCompileStatusResponse Execute(JToken paramsToken) { @@ -58,7 +61,7 @@ internal static GetCompileStatusResponse BuildResponse( } JToken result = storedResult.HasResult ? JToken.Parse(storedResult.ResultJson) : null; - return new GetCompileStatusResponse + GetCompileStatusResponse response = new GetCompileStatusResponse { Ready = ready, HasResult = storedResult.HasResult, @@ -68,6 +71,8 @@ internal static GetCompileStatusResponse BuildResponse( Result = result, Message = CreateMessage(ready, storedResult.HasResult) }; + LogCompileStatusQueryReceived(requestId, response); + return response; } private static string ReadRequestId(JToken paramsToken) @@ -155,5 +160,54 @@ private static string CreateMessage(bool ready, bool hasResult) return "Compile result is available."; } + + private static void LogCompileStatusQueryReceived( + string requestId, + GetCompileStatusResponse response) + { + Debug.Assert(response != null, "response must not be null"); + + string signature = CreateStatusSignature(response); + if (!string.IsNullOrWhiteSpace(requestId) && + LastLoggedStatusByRequestId.TryGetValue(requestId, out string previousSignature) && + previousSignature == signature) + { + return; + } + + if (!string.IsNullOrWhiteSpace(requestId)) + { + LastLoggedStatusByRequestId[requestId] = signature; + } + + VibeLogger.LogInfo( + "compile_status_query_received", + "CLI queried Unity compile status.", + 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 string CreateStatusSignature(GetCompileStatusResponse response) + { + Debug.Assert(response != null, "response must not be null"); + + return string.Join( + "|", + response.Ready, + response.HasResult, + response.IsCompiling, + response.IsUpdating, + response.IsDomainReloadInProgress, + response.Message ?? ""); + } } } diff --git a/Packages/src/Editor/Infrastructure/Server/DomainReloadDetectionFileService.cs b/Packages/src/Editor/Infrastructure/Server/DomainReloadDetectionFileService.cs index 6501dc3270..e555f8c81a 100644 --- a/Packages/src/Editor/Infrastructure/Server/DomainReloadDetectionFileService.cs +++ b/Packages/src/Editor/Infrastructure/Server/DomainReloadDetectionFileService.cs @@ -66,10 +66,7 @@ public void StartDomainReload(string correlationId, bool serverIsRunning) VibeLogger.LogInfo( "domain_reload_start", "Domain reload starting", - new - { - server_running = serverIsRunning - }, + BuildDomainReloadStartLogContext(serverIsRunning), correlationId ); } @@ -99,11 +96,35 @@ 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" }, + BuildDomainReloadCompleteLogContext(serverWillRecover), correlationId ); } + private object BuildDomainReloadStartLogContext(bool serverRunning) + { + UnityCliLoopPendingCompileRequest pendingRequest = + _sessionStateService.GetPendingCompileRequest(); + return new + { + transport = "project_ipc", + server_running = serverRunning, + request_id = pendingRequest.HasRequest ? pendingRequest.RequestId : "" + }; + } + + private object BuildDomainReloadCompleteLogContext(bool serverWillRecover) + { + UnityCliLoopPendingCompileRequest pendingRequest = + _sessionStateService.GetPendingCompileRequest(); + return new + { + transport = "project_ipc", + server_recovery_expected = serverWillRecover, + request_id = pendingRequest.HasRequest ? pendingRequest.RequestId : "" + }; + } + public void RollbackDomainReloadStart(string correlationId) { if (IsBackgroundUnityProcess()) diff --git a/Packages/src/Editor/Infrastructure/Server/UnityCliLoopServerController.cs b/Packages/src/Editor/Infrastructure/Server/UnityCliLoopServerController.cs index 4c431175d1..68c84a37c0 100644 --- a/Packages/src/Editor/Infrastructure/Server/UnityCliLoopServerController.cs +++ b/Packages/src/Editor/Infrastructure/Server/UnityCliLoopServerController.cs @@ -36,6 +36,7 @@ private enum ServerStopIntent private readonly SemaphoreSlim _startupSemaphore = new SemaphoreSlim(1, 1); private long _startupProtectionUntilTicks = 0; private Task _currentRecoveryTask; + private int _serverGeneration = 0; internal UnityCliLoopServerControllerService( IUnityCliLoopServerInstanceFactory serverInstanceFactory, @@ -85,6 +86,7 @@ internal void RegisterRecoveredServer(IUnityCliLoopServerInstance server) System.Diagnostics.Debug.Assert(server != null, "server must not be null"); _bridgeServer = server; + _serverGeneration++; SaveRunningServerState(); } @@ -629,7 +631,11 @@ private async Task TryBindWithWaitAsync( server = _serverInstanceFactory.Create(); server.StartServer(); _bridgeServer = server; - VibeLogger.LogInfo("binding_success", $"endpoint={server.Endpoint}"); + _serverGeneration++; + VibeLogger.LogInfo( + "binding_success", + $"endpoint={server.Endpoint}", + BuildBindingLogContext(server.Endpoint, _serverGeneration)); return true; } catch (Exception ex) @@ -664,6 +670,18 @@ private async Task TryBindWithWaitAsync( } } + private object BuildBindingLogContext(string endpoint, int serverGeneration) + { + UnityCliLoopPendingCompileRequest pendingRequest = + _sessionStateService.GetPendingCompileRequest(); + return new + { + endpoint, + server_generation = serverGeneration, + request_id = pendingRequest.HasRequest ? pendingRequest.RequestId : "" + }; + } + private void SaveRunningServerState() { _sessionStateService.MarkServerStarted(); diff --git a/Packages/src/Editor/ToolContracts/VibeLogger.cs b/Packages/src/Editor/ToolContracts/VibeLogger.cs index 59f3f8cdd6..5ed4465ef2 100644 --- a/Packages/src/Editor/ToolContracts/VibeLogger.cs +++ b/Packages/src/Editor/ToolContracts/VibeLogger.cs @@ -3,7 +3,10 @@ using System.Diagnostics; using System.IO; using System.Linq; +using System.Text; +using System.Threading; using Newtonsoft.Json; +using Newtonsoft.Json.Linq; using UnityEditor; using UnityEngine; @@ -25,10 +28,13 @@ public sealed class VibeLoggerService private const int MAX_FILE_SIZE_MB = 10; private const int MAX_MEMORY_LOGS = 1000; private const int MAX_LOG_FILES = 3; + private const int MAX_WRITE_RETRIES = 20; + private const int WRITE_RETRY_DELAY_MS = 25; private readonly List _memoryLogs = new List(); private readonly object _lockObject = new object(); private bool _hasCleanedUpOnStartup = false; + private bool _hasReportedInterleaving = false; /// /// Represents one Vibe Log entry in the owning workflow. @@ -215,6 +221,18 @@ private void Log(string level, string operation, string message, object context, } catch (Exception ex) { + TrySaveFileDiagnosticLog( + "vibe_log_write_failed", + "VibeLogger failed to append a JSONL entry.", + new + { + log_path_identity = LOG_FILE_PREFIX, + source = "Unity", + operation = "append", + failed_operation = operation, + error = ex.Message, + retry_count = MAX_WRITE_RETRIES + }); // Fallback to Unity console if file logging fails UnityEngine.Debug.LogError($"[VibeLogger] Failed to save log to file: {ex.Message}"); UnityEngine.Debug.Log($"[VibeLogger] {level} | {operation} | {message}"); @@ -225,13 +243,17 @@ private void Log(string level, string operation, string message, object context, /// Save log entry to file with file locking for concurrent access /// private void SaveLogToFile(VibeLogEntry logEntry) + { + SaveLogToFile(logEntry, validateIntegrity: true); + } + + private void SaveLogToFile(VibeLogEntry logEntry, bool validateIntegrity) { if (!Directory.Exists(_logDirectory)) { Directory.CreateDirectory(_logDirectory); } - // Clean up old log files on first access only lock (_lockObject) { if (!_hasCleanedUpOnStartup) @@ -239,58 +261,155 @@ private void SaveLogToFile(VibeLogEntry logEntry) CleanupOldLogFiles(); _hasCleanedUpOnStartup = true; } - } - - string fileName = $"{LOG_FILE_PREFIX}_{DateTime.UtcNow:yyyyMMdd}.json"; - string filePath = Path.Combine(_logDirectory, fileName); - - // Check file size and rotate if necessary - if (File.Exists(filePath)) - { - FileInfo fileInfo = new(filePath); - if (fileInfo.Length > MAX_FILE_SIZE_MB * 1024 * 1024) + + string fileName = $"{LOG_FILE_PREFIX}_{DateTime.UtcNow:yyyyMMdd}.json"; + string filePath = Path.Combine(_logDirectory, fileName); + RotateLogFileIfNeeded(filePath); + AppendJsonLineWithRetry(filePath, JsonConvert.SerializeObject(logEntry) + "\n"); + if (validateIntegrity) { - string rotatedFileName = $"{LOG_FILE_PREFIX}_{DateTime.UtcNow:yyyyMMdd_HHmmss}.json"; - string rotatedFilePath = Path.Combine(_logDirectory, rotatedFileName); - File.Move(filePath, rotatedFilePath); - - // Clean up old files after rotation - CleanupOldLogFiles(); + DetectInterleavingIfNeeded(filePath); } } - - string jsonLog = JsonConvert.SerializeObject(logEntry) + "\n"; - - // Use file locking with retry mechanism to handle concurrent access - int maxRetries = 3; - int retryDelayMs = 50; - - for (int retry = 0; retry < maxRetries; retry++) + } + + private void RotateLogFileIfNeeded(string filePath) + { + if (!File.Exists(filePath)) + { + return; + } + + FileInfo fileInfo = new(filePath); + if (fileInfo.Length <= MAX_FILE_SIZE_MB * 1024 * 1024) + { + return; + } + + string rotatedFileName = $"{LOG_FILE_PREFIX}_{DateTime.UtcNow:yyyyMMdd_HHmmss}.json"; + string rotatedFilePath = Path.Combine(_logDirectory, rotatedFileName); + File.Move(filePath, rotatedFilePath); + CleanupOldLogFiles(); + } + + private static void AppendJsonLineWithRetry(string filePath, string jsonLine) + { + byte[] payload = Encoding.UTF8.GetBytes(jsonLine); + for (int retry = 0; retry < MAX_WRITE_RETRIES; retry++) { try { using (FileStream fileStream = new FileStream(filePath, FileMode.Append, FileAccess.Write, FileShare.Read)) - using (StreamWriter writer = new StreamWriter(fileStream)) { - writer.Write(jsonLog); - writer.Flush(); - return; // Success - exit retry loop + fileStream.Write(payload, 0, payload.Length); + fileStream.Flush(); + return; } } - catch (IOException ex) when (IsFileSharingViolation(ex) && retry < maxRetries - 1) + catch (IOException ex) when (IsFileSharingViolation(ex) && retry < MAX_WRITE_RETRIES - 1) { - // Wait and retry for sharing violations - System.Threading.Thread.Sleep(retryDelayMs * (retry + 1)); + Thread.Sleep(WRITE_RETRY_DELAY_MS * (retry + 1)); } catch (Exception ex) { - // For other exceptions, throw immediately throw new InvalidOperationException($"Failed to write VibeLogger entry to file: {ex.Message}", ex); } } - - // If all retries failed, throw with sharing violation context - throw new InvalidOperationException($"Failed to write VibeLogger entry after {maxRetries} retries due to file sharing violations"); + + throw new InvalidOperationException($"Failed to write VibeLogger entry after {MAX_WRITE_RETRIES} retries due to file sharing violations"); + } + + private void DetectInterleavingIfNeeded(string filePath) + { + if (_hasReportedInterleaving) + { + return; + } + + (bool HasMalformedLine, int LastValidLineNumber) result = + InspectJsonLines(filePath); + if (!result.HasMalformedLine) + { + return; + } + + _hasReportedInterleaving = true; + SaveLogToFile( + CreateDiagnosticLogEntry( + "WARNING", + "vibe_log_write_interleaving_detected", + "Detected a malformed VibeLog JSONL entry after append.", + new + { + log_path_identity = Path.GetFileName(filePath), + source = "Unity", + process_id = Process.GetCurrentProcess().Id, + thread_id = Thread.CurrentThread.ManagedThreadId, + last_valid_line_number = result.LastValidLineNumber + }), + validateIntegrity: false); + } + + private static (bool HasMalformedLine, int LastValidLineNumber) InspectJsonLines(string filePath) + { + int lineNumber = 0; + int lastValidLineNumber = 0; + foreach (string line in File.ReadLines(filePath)) + { + lineNumber++; + if (string.IsNullOrWhiteSpace(line)) + { + continue; + } + + try + { + JToken.Parse(line); + lastValidLineNumber = lineNumber; + } + catch (JsonReaderException) + { + return (true, lastValidLineNumber); + } + } + + return (false, lastValidLineNumber); + } + + private void TrySaveFileDiagnosticLog( + string operation, + string message, + object context) + { + try + { + SaveLogToFile( + CreateDiagnosticLogEntry("ERROR", operation, message, context), + validateIntegrity: false); + } + catch (Exception diagnosticException) + { + UnityEngine.Debug.LogWarning($"[VibeLogger] Failed to save diagnostic log: {diagnosticException.Message}"); + } + } + + private static VibeLogEntry CreateDiagnosticLogEntry( + string level, + string operation, + string message, + object context) + { + return new VibeLogEntry + { + timestamp = DateTime.Now.ToString("yyyy-MM-ddTHH:mm:ss.fffzzz"), + level = level, + operation = operation, + message = message, + context = context, + correlation_id = $"unity_{Guid.NewGuid().ToString("N")[..8]}_{DateTime.Now:HHmmss}", + source = "Unity", + environment = GetEnvironmentInfo() + }; } /// diff --git a/cli/internal/cli/cli_vibe.go b/cli/internal/cli/cli_vibe.go index 2280fc72e1..09af227ea4 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" @@ -10,11 +12,29 @@ import ( ) const ( - cliVibeLogDirectory = ".uloop/outputs/VibeLogs" - cliVibeLogPrefix = "cli_vibe" - cliVibeLogEnvName = "ULOOP_DEBUG" + cliVibeLogDirectory = ".uloop/outputs/VibeLogs" + cliVibeLogPrefix = "cli_vibe" + cliVibeLogEnvName = "ULOOP_DEBUG" + cliVibeProjectSettingsDirectory = "ProjectSettings" + cliVibeProjectSettingsFileName = "ProjectSettings.asset" + cliVibeDebugDefine = "ULOOP_DEBUG" + cliProjectIdentityHashLength = 16 ) +type cliVibeDebugSource string + +const ( + cliVibeDebugSourceEnv cliVibeDebugSource = "env" + cliVibeDebugSourceUnityProject cliVibeDebugSource = "unity_project" + cliVibeDebugSourceBoth cliVibeDebugSource = "both" + cliVibeDebugSourceNone cliVibeDebugSource = "none" +) + +type cliVibeDebugMode struct { + enabled bool + source cliVibeDebugSource +} + type cliVibeLogEntry struct { Timestamp string `json:"timestamp"` Level string `json:"level"` @@ -34,7 +54,7 @@ func newCliVibeCorrelationID() string { } func writeCliVibeLog(projectRoot string, entry cliVibeLogEntry) error { - if !isCliVibeLogEnabled() { + if !resolveCliVibeDebugMode(projectRoot).enabled { return nil } @@ -74,10 +94,118 @@ func writeCliVibeLog(projectRoot string, entry cliVibeLogEntry) error { return err } -func isCliVibeLogEnabled() bool { +func resolveCliVibeDebugMode(projectRoot string) cliVibeDebugMode { + envEnabled := isCliVibeLogEnvEnabled() + projectEnabled := isUnityProjectVibeLogEnabled(projectRoot) + switch { + case envEnabled && projectEnabled: + return cliVibeDebugMode{enabled: true, source: cliVibeDebugSourceBoth} + case envEnabled: + return cliVibeDebugMode{enabled: true, source: cliVibeDebugSourceEnv} + case projectEnabled: + return cliVibeDebugMode{enabled: true, source: cliVibeDebugSourceUnityProject} + default: + return cliVibeDebugMode{source: cliVibeDebugSourceNone} + } +} + +func isCliVibeLogEnvEnabled() bool { value := strings.TrimSpace(os.Getenv(cliVibeLogEnvName)) if value == "" || value == "0" { return false } return !strings.EqualFold(value, "false") } + +func isUnityProjectVibeLogEnabled(projectRoot string) bool { + if projectRoot == "" { + return false + } + + content, err := os.ReadFile(filepath.Join( + projectRoot, + cliVibeProjectSettingsDirectory, + cliVibeProjectSettingsFileName, + )) + if err != nil { + return false + } + return projectSettingsContainUnityDebugDefine(string(content)) +} + +func projectSettingsContainUnityDebugDefine(content string) bool { + lines := strings.Split(content, "\n") + inScriptingDefineSymbols := false + scriptingDefineIndent := 0 + for _, line := range lines { + trimmed := strings.TrimSpace(line) + if trimmed == "" { + continue + } + + indent := leadingSpaceCount(line) + if !inScriptingDefineSymbols { + if strings.HasPrefix(trimmed, "scriptingDefineSymbols:") { + inScriptingDefineSymbols = true + scriptingDefineIndent = indent + if containsUnityDebugDefineToken(trimmed) { + return true + } + } + continue + } + + if indent <= scriptingDefineIndent { + inScriptingDefineSymbols = false + if strings.HasPrefix(trimmed, "scriptingDefineSymbols:") { + inScriptingDefineSymbols = true + scriptingDefineIndent = indent + if containsUnityDebugDefineToken(trimmed) { + return true + } + } + continue + } + + if containsUnityDebugDefineToken(trimmed) { + return true + } + } + return false +} + +func containsUnityDebugDefineToken(value string) bool { + tokens := strings.FieldsFunc(value, func(r rune) bool { + return r == ':' || r == ';' || r == ',' || r == '[' || r == ']' || r == '"' || r == '\'' + }) + for _, token := range tokens { + if strings.TrimSpace(token) == cliVibeDebugDefine { + return true + } + } + return false +} + +func leadingSpaceCount(value string) int { + count := 0 + for _, r := range value { + if r != ' ' { + return count + } + count++ + } + return count +} + +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/cli_vibe_test.go b/cli/internal/cli/cli_vibe_test.go index 6aa0201d54..8dada7b59f 100644 --- a/cli/internal/cli/cli_vibe_test.go +++ b/cli/internal/cli/cli_vibe_test.go @@ -1,7 +1,9 @@ package cli import ( + "os" "path/filepath" + "strings" "testing" ) @@ -31,3 +33,61 @@ func TestWriteCliVibeLogSkipsWhenDebugDisabled(t *testing.T) { t.Fatalf("expected no CLI Vibe logs, got %d: %#v", len(logFiles), logFiles) } } + +// Verifies project-level Unity debug defines enable CLI Vibe logs without a shell environment override. +func TestWriteCliVibeLogUsesUnityProjectDebugDefine(t *testing.T) { + t.Setenv(cliVibeLogEnvName, "") + projectRoot := t.TempDir() + writeUnityProjectSettings(t, projectRoot, "Standalone: ULOOP_DEBUG;EXAMPLE_SYMBOL") + + err := writeCliVibeLog(projectRoot, cliVibeLogEntry{ + Level: "INFO", + Operation: "test_project_debug_operation", + Message: "test message", + }) + if err != nil { + t.Fatalf("writeCliVibeLog failed: %v", err) + } + + logContent := readOnlyCliVibeLog(t, projectRoot) + if !strings.Contains(logContent, `"operation":"test_project_debug_operation"`) { + t.Fatalf("CLI Vibe log missing project-debug entry:\n%s", logContent) + } +} + +// Verifies debug source resolution distinguishes shell, project, and combined sources. +func TestResolveCliVibeDebugModeReportsSource(t *testing.T) { + projectRoot := t.TempDir() + writeUnityProjectSettings(t, projectRoot, "Standalone: ULOOP_DEBUG") + + t.Setenv(cliVibeLogEnvName, "") + projectOnly := resolveCliVibeDebugMode(projectRoot) + if !projectOnly.enabled || projectOnly.source != cliVibeDebugSourceUnityProject { + t.Fatalf("project debug source mismatch: %#v", projectOnly) + } + + t.Setenv(cliVibeLogEnvName, "1") + both := resolveCliVibeDebugMode(projectRoot) + if !both.enabled || both.source != cliVibeDebugSourceBoth { + t.Fatalf("combined debug source mismatch: %#v", both) + } + + noDebugRoot := t.TempDir() + t.Setenv(cliVibeLogEnvName, "0") + none := resolveCliVibeDebugMode(noDebugRoot) + if none.enabled || none.source != cliVibeDebugSourceNone { + t.Fatalf("disabled debug source mismatch: %#v", none) + } +} + +func writeUnityProjectSettings(t *testing.T, projectRoot string, scriptingDefineLine string) { + t.Helper() + projectSettingsDirectory := filepath.Join(projectRoot, "ProjectSettings") + if err := os.MkdirAll(projectSettingsDirectory, 0o755); err != nil { + t.Fatalf("failed to create ProjectSettings: %v", err) + } + content := "PlayerSettings:\n scriptingDefineSymbols:\n " + scriptingDefineLine + "\n" + if err := os.WriteFile(filepath.Join(projectSettingsDirectory, "ProjectSettings.asset"), []byte(content), 0o644); err != nil { + t.Fatalf("failed to write ProjectSettings.asset: %v", err) + } +} diff --git a/cli/internal/cli/compile_wait.go b/cli/internal/cli/compile_wait.go index ed87faae18..3681c0418b 100644 --- a/cli/internal/cli/compile_wait.go +++ b/cli/internal/cli/compile_wait.go @@ -42,6 +42,15 @@ type compileStatusResponse struct { Message string `json:"Message"` } +type compileStatusPollState struct { + attempts int + hasLastStatus bool + lastStatus compileStatusResponse + lastTransportError string + lastLogSignature string + bridgeRecoveryLogged bool +} + var queryCompileStatus = queryCompileStatusFromUnity func shouldWaitForCompileDomainReload(command string, params map[string]any) bool { @@ -105,6 +114,8 @@ func isSafeCompileRequestID(requestID string) bool { func waitForCompileCompletion(ctx context.Context, options compileCompletionOptions) (json.RawMessage, bool, error) { startedAt := time.Now() deadline := startedAt.Add(options.timeout) + pollState := compileStatusPollState{} + logCompileStatusPollStart(options, startedAt, deadline) for { now := time.Now() @@ -112,20 +123,24 @@ func waitForCompileCompletion(ctx context.Context, options compileCompletionOpti break } + pollState.attempts++ status, err := queryCompileStatus(ctx, options.connection, options.requestID) + updateCompileStatusPollState(options, startedAt, &pollState, status, err) if err == nil && status.Ready && status.HasResult && len(status.Result) > 0 { + logCompileStatusPollComplete(options, startedAt, pollState, status) return status.Result, true, nil } select { case <-ctx.Done(): - logCompileWaitCancelled(options, startedAt, ctx.Err()) + logCompileStatusPollCancelled(options, startedAt, pollState, ctx.Err()) return nil, false, ctx.Err() case <-time.After(options.pollInterval): } } - logCompileWaitTimedOut(options, startedAt) + logCompileStatusPollObserved(options, startedAt, pollState, true) + logCompileStatusPollTimedOut(options, startedAt, pollState) return nil, false, nil } @@ -180,44 +195,288 @@ 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) { + debugMode := resolveCliVibeDebugMode(connection.ProjectRoot) + _ = writeCliVibeLog(connection.ProjectRoot, cliVibeLogEntry{ + Level: "INFO", + Operation: "cli_debug_mode_resolved", + Message: "Resolved CLI debug logging mode for this command.", + Context: map[string]any{ + "command": command, + "debug_enabled": debugMode.enabled, + "debug_source": string(debugMode.source), + "project_identity": projectIdentity(connection.ProjectRoot), + "cli_version": version, + }, + }) +} + +func logCompileRequestPrepared(connection unityipc.Connection, requestID string, params map[string]any) { + _ = writeCliVibeLog(connection.ProjectRoot, cliVibeLogEntry{ + Level: "INFO", + Operation: "cli_compile_request_prepared", + Message: "Prepared Unity compile request for domain reload polling.", + Context: map[string]any{ + "request_id": requestID, + "command": compileCommandName, + "wait_for_domain_reload": true, + "force_recompile": compileForceRecompileEnabled(params), + "stop_on_external_scene_changes": compileStopOnExternalSceneChangesEnabled(params), + "project_identity": projectIdentity(connection.ProjectRoot), + "endpoint": connection.Endpoint.Address, + "timeout_ms": compileWaitTimeout.Milliseconds(), + "poll_interval_ms": compileWaitPollInterval.Milliseconds(), + }, + CorrelationID: requestID, + }) +} + +func logCompileRequestSendResult( + connection unityipc.Connection, + requestID string, + outcome unityipc.UnitySendOutcome, + err error, + elapsed time.Duration, +) { + responseTimeout := err != nil && isFinalResponseTimeoutError(err) + _ = writeCliVibeLog(connection.ProjectRoot, cliVibeLogEntry{ + Level: compileRequestSendResultLevel(err), + Operation: "cli_compile_request_send_result", + Message: "Recorded Unity compile request send result.", + Context: map[string]any{ + "request_id": requestID, + "request_dispatched": outcome.RequestDispatched, + "request_accepted": outcome.RequestAccepted, + "response_received": err == nil && len(outcome.Result) > 0, + "response_timeout": responseTimeout, + "transport_error": errorMessage(err), + "elapsed_ms": elapsed.Milliseconds(), + }, + CorrelationID: requestID, + }) +} + +func compileRequestSendResultLevel(err error) string { + if err == nil { + return "INFO" + } + return "WARNING" +} + +func compileStopOnExternalSceneChangesEnabled(params map[string]any) bool { + value, ok := params[reloadExternalSceneChangesPropertyName].(bool) + return ok && !value +} + +func logCompileStatusPollStart(options compileCompletionOptions, startedAt time.Time, deadline time.Time) { + _ = writeCliVibeLog(options.connection.ProjectRoot, cliVibeLogEntry{ + Level: "INFO", + Operation: "cli_compile_status_poll_start", + Message: "Started polling Unity compile status.", + Context: map[string]any{ + "command": compileCommandName, + "request_id": options.requestID, + "started_at": startedAt.UTC().Format(time.RFC3339Nano), + "deadline_at": deadline.UTC().Format(time.RFC3339Nano), + "endpoint": options.connection.Endpoint.Address, + "timeout_ms": options.timeout.Milliseconds(), + "poll_interval_ms": options.pollInterval.Milliseconds(), + "project_identity": projectIdentity(options.connection.ProjectRoot), + }, + CorrelationID: options.requestID, + }) +} + +func updateCompileStatusPollState( + options compileCompletionOptions, + startedAt time.Time, + pollState *compileStatusPollState, + status compileStatusResponse, + err error, +) { + if err == nil { + if pollState.lastTransportError != "" && !pollState.bridgeRecoveryLogged { + logCompileBridgeRecoveryObserved(options, startedAt) + pollState.bridgeRecoveryLogged = true + } + pollState.hasLastStatus = true + pollState.lastStatus = status + pollState.lastTransportError = "" + } else { + pollState.lastTransportError = errorMessage(err) + } + + signature := compileStatusPollSignature(*pollState) + if signature == pollState.lastLogSignature { + return + } + pollState.lastLogSignature = signature + logCompileStatusPollObserved(options, startedAt, *pollState, false) +} + +func compileStatusPollSignature(pollState compileStatusPollState) string { + payload, err := json.Marshal(map[string]any{ + "has_last_status": pollState.hasLastStatus, + "last_status": compileStatusLogContext(pollState.lastStatus), + "last_transport_error": pollState.lastTransportError, + }) + if err != nil { + return pollState.lastTransportError + } + return string(payload) +} + +func logCompileStatusPollObserved( + options compileCompletionOptions, + startedAt time.Time, + pollState compileStatusPollState, + finalBeforeTimeout bool, +) { + context := compileStatusLogContext(pollState.lastStatus) + context["command"] = compileCommandName + context["request_id"] = options.requestID + context["attempt"] = pollState.attempts + context["transport_error"] = pollState.lastTransportError + context["elapsed_ms"] = time.Since(startedAt).Milliseconds() + if finalBeforeTimeout { + context["final_before_timeout"] = true + } + _ = writeCliVibeLog(options.connection.ProjectRoot, cliVibeLogEntry{ + Level: compileStatusObservationLevel(pollState), + Operation: "cli_compile_status_poll_observed", + Message: "Observed Unity compile status while polling.", + Context: context, + CorrelationID: options.requestID, + }) +} + +func compileStatusObservationLevel(pollState compileStatusPollState) string { + if pollState.lastTransportError == "" { + return "INFO" + } + return "WARNING" +} + +func logCompileStatusPollComplete( + options compileCompletionOptions, + startedAt time.Time, + pollState compileStatusPollState, + status compileStatusResponse, +) { + context := compileResultLogSummary(status.Result) + context["command"] = compileCommandName + context["request_id"] = options.requestID + context["elapsed_ms"] = time.Since(startedAt).Milliseconds() + context["poll_attempts"] = pollState.attempts + context["last_status"] = compileStatusLogContext(status) + _ = writeCliVibeLog(options.connection.ProjectRoot, cliVibeLogEntry{ + Level: "INFO", + Operation: "cli_compile_status_poll_complete", + Message: "Unity compile result became available.", + Context: context, + CorrelationID: options.requestID, + }) +} + +func logCompileStatusPollTimedOut( + options compileCompletionOptions, + startedAt time.Time, + pollState compileStatusPollState, +) { _ = writeCliVibeLog(options.connection.ProjectRoot, cliVibeLogEntry{ Level: "WARNING", - Operation: "cli_compile_status_wait_timed_out", + Operation: "cli_compile_status_poll_timeout", Message: "Timed out while polling Unity compile status.", - Context: compileWaitLogContext(options, startedAt, nil), + Context: compileWaitLogContext(options, startedAt, pollState, nil), CorrelationID: options.requestID, }) } -func logCompileWaitCancelled(options compileCompletionOptions, startedAt time.Time, err error) { +func logCompileStatusPollCancelled( + options compileCompletionOptions, + startedAt time.Time, + pollState compileStatusPollState, + err error, +) { _ = 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), + Context: compileWaitLogContext(options, startedAt, pollState, map[string]any{ + "cancel_error": errorMessage(err), }), CorrelationID: options.requestID, }) } +func logCompileBridgeRecoveryObserved(options compileCompletionOptions, startedAt time.Time) { + _ = writeCliVibeLog(options.connection.ProjectRoot, cliVibeLogEntry{ + Level: "INFO", + Operation: "cli_compile_bridge_rebind_observed", + Message: "Unity compile status polling recovered after a transport error.", + Context: map[string]any{ + "command": compileCommandName, + "request_id": options.requestID, + "old_endpoint": options.connection.Endpoint.Address, + "new_endpoint": options.connection.Endpoint.Address, + "elapsed_ms": time.Since(startedAt).Milliseconds(), + }, + CorrelationID: options.requestID, + }) +} + func compileWaitLogContext( options compileCompletionOptions, startedAt time.Time, + pollState compileStatusPollState, extra map[string]any, ) map[string]any { context := map[string]any{ - "command": compileCommandName, - "request_id": options.requestID, - "force_recompile": options.forceRecompile, - "endpoint": options.connection.Endpoint.Address, - "timeout_ms": options.timeout.Milliseconds(), - "poll_interval_ms": options.pollInterval.Milliseconds(), - "elapsed_ms": time.Since(startedAt).Milliseconds(), + "command": compileCommandName, + "request_id": options.requestID, + "force_recompile": options.forceRecompile, + "endpoint": options.connection.Endpoint.Address, + "timeout_ms": options.timeout.Milliseconds(), + "poll_interval_ms": options.pollInterval.Milliseconds(), + "elapsed_ms": time.Since(startedAt).Milliseconds(), + "poll_attempts": pollState.attempts, + "last_status": compileStatusLogContext(pollState.lastStatus), + "last_transport_error": pollState.lastTransportError, + "project_identity": projectIdentity(options.connection.ProjectRoot), } for key, value := range extra { context[key] = value } return context } + +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, + } +} + +func compileResultLogSummary(result json.RawMessage) map[string]any { + context := map[string]any{ + "success": nil, + "error_count": nil, + "warning_count": nil, + } + if len(result) == 0 { + return context + } + + var payload map[string]any + if err := json.Unmarshal(result, &payload); err != nil { + return context + } + context["success"] = payload["Success"] + context["error_count"] = payload["ErrorCount"] + context["warning_count"] = payload["WarningCount"] + return context +} diff --git a/cli/internal/cli/compile_wait_test.go b/cli/internal/cli/compile_wait_test.go index fa302e7691..027c7c3116 100644 --- a/cli/internal/cli/compile_wait_test.go +++ b/cli/internal/cli/compile_wait_test.go @@ -175,6 +175,60 @@ func TestWaitForCompileCompletionReturnsReadyStatusResult(t *testing.T) { } } +// Verifies successful compile status polling leaves start, observed, and completion diagnostics. +func TestWaitForCompileCompletionWritesPollingVibeLogs(t *testing.T) { + enableCliVibeLog(t) + connection := compileWaitTestConnection(t) + requestID := "compile_poll_log_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":true,"ErrorCount":0,"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) == "" { + t.Fatal("compile wait returned an empty 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_log_test"`, + `"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) @@ -248,13 +302,20 @@ func TestWaitForCompileCompletionForceCompileTimesOutWithoutStoredResult(t *test } } -// Verifies that compile status wait timeouts are visible in CLI Vibe logs. +// Verifies that compile status wait timeouts include the last observed Unity status. func TestWaitForCompileCompletionWritesTimeoutVibeLog(t *testing.T) { enableCliVibeLog(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, + HasResult: false, + IsCompiling: true, + IsUpdating: false, + IsDomainReloadInProgress: false, + Message: "Compiling", + }, nil }) _, completed, err := waitForCompileCompletion(context.Background(), compileCompletionOptions{ @@ -272,8 +333,11 @@ 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_timeout"`, `"request_id":"compile_timeout_log_test"`, + `"poll_attempts":`, + `"last_status"`, + `"message":"Compiling"`, } { if !strings.Contains(logContent, expected) { t.Fatalf("CLI Vibe log missing %q:\n%s", expected, logContent) diff --git a/cli/internal/cli/run.go b/cli/internal/cli/run.go index 7f9ec89f3a..9ca149a215 100644 --- a/cli/internal/cli/run.go +++ b/cli/internal/cli/run.go @@ -225,9 +225,12 @@ func runCompileWithDomainReloadWait(ctx context.Context, connection unityipc.Con }) return 1 } + logCliDebugModeResolved(connection, compileCommandName) + logCompileRequestPrepared(connection, requestID, params) startedAt := time.Now() spinner := newToolSpinner(stderr, compileCommandName) + sendStartedAt := time.Now() outcome, err := sendWithTransientConnectionRetryAndResponseTimeout( ctx, connection, @@ -238,6 +241,7 @@ func runCompileWithDomainReloadWait(ctx context.Context, connection unityipc.Con }, compileResponseTimeout, ) + logCompileRequestSendResult(connection, requestID, outcome, err, time.Since(sendStartedAt)) if err != nil && shouldWaitForCompileStatus(err, outcome) { spinner.Update("Connection changed during compile. Waiting for Unity status...") } From 701e7aa2ff23fd191aca50c1374185ce9ed7cd9e Mon Sep 17 00:00:00 2001 From: hatayama Date: Wed, 3 Jun 2026 22:08:49 +0900 Subject: [PATCH 2/2] Bound compile wait diagnostic overhead Limit compile status duplicate-suppression state and avoid full-file VibeLog integrity scans so debug diagnostics do not grow unbounded in long-lived Unity sessions. --- .../Editor/CompileStatusBridgeCommandTests.cs | 66 +++++++++++++++++ Assets/Tests/Editor/VibeLoggerTests.cs | 65 ++++++++++++++++ Assets/Tests/Editor/VibeLoggerTests.cs.meta | 11 +++ .../Api/CompileStatusBridgeCommand.cs | 28 ++++++- .../src/Editor/ToolContracts/VibeLogger.cs | 74 +++++++++++++------ 5 files changed, 219 insertions(+), 25 deletions(-) create mode 100644 Assets/Tests/Editor/VibeLoggerTests.cs create mode 100644 Assets/Tests/Editor/VibeLoggerTests.cs.meta diff --git a/Assets/Tests/Editor/CompileStatusBridgeCommandTests.cs b/Assets/Tests/Editor/CompileStatusBridgeCommandTests.cs index 1eeb32b4cb..dd1989fc2f 100644 --- a/Assets/Tests/Editor/CompileStatusBridgeCommandTests.cs +++ b/Assets/Tests/Editor/CompileStatusBridgeCommandTests.cs @@ -216,5 +216,71 @@ public void BuildResponse_WhenStatusIsQueried_WritesVibeLogContext() Assert.That(context["is_compiling"]?.Value(), Is.True); Assert.That(context["message"]?.ToString(), Does.Contain("still compiling")); } + + [Test] + public void BuildResponse_WhenReadyStatusRepeats_DoesNotRetainDuplicateSuppressionCache() + { + // Verifies completed status signatures do not stay in the duplicate-suppression cache. + VibeLogger.ClearMemoryLogs(); + string requestId = "compile_status_ready_cache_request_" + System.Guid.NewGuid().ToString("N"); + + CompileStatusBridgeCommand.BuildResponse( + requestId, + isCompiling: true, + isUpdating: false, + isDomainReloadInProgress: false, + _sessionStateService); + CompileStatusBridgeCommand.BuildResponse( + requestId, + isCompiling: true, + isUpdating: false, + isDomainReloadInProgress: false, + _sessionStateService); + CompileStatusBridgeCommand.BuildResponse( + requestId, + isCompiling: false, + isUpdating: false, + isDomainReloadInProgress: false, + _sessionStateService); + CompileStatusBridgeCommand.BuildResponse( + requestId, + isCompiling: false, + isUpdating: false, + isDomainReloadInProgress: false, + _sessionStateService); + + JArray logs = JArray.Parse(VibeLogger.GetLogsForAi("compile_status_query_received")); + Assert.That(logs, Has.Count.EqualTo(3)); + } + + [Test] + public void BuildResponse_WhenManyUniqueBusyRequestsAreQueried_BoundsDuplicateSuppressionCache() + { + // Verifies arbitrary status probes cannot grow the duplicate-suppression cache forever. + VibeLogger.ClearMemoryLogs(); + const int requestCount = 257; + string requestPrefix = "compile_status_cache_request_" + System.Guid.NewGuid().ToString("N") + "_"; + + for (int index = 0; index < requestCount; index++) + { + CompileStatusBridgeCommand.BuildResponse( + requestPrefix + index, + isCompiling: true, + isUpdating: false, + isDomainReloadInProgress: false, + _sessionStateService); + } + + CompileStatusBridgeCommand.BuildResponse( + requestPrefix + "0", + isCompiling: true, + isUpdating: false, + isDomainReloadInProgress: false, + _sessionStateService); + + JArray logs = JArray.Parse( + VibeLogger.GetLogsForAi("compile_status_query_received", maxCount: requestCount + 1)); + Assert.That(logs, Has.Count.EqualTo(requestCount + 1)); + } } } diff --git a/Assets/Tests/Editor/VibeLoggerTests.cs b/Assets/Tests/Editor/VibeLoggerTests.cs new file mode 100644 index 0000000000..c806e8f492 --- /dev/null +++ b/Assets/Tests/Editor/VibeLoggerTests.cs @@ -0,0 +1,65 @@ +using System; +using System.IO; +using NUnit.Framework; + +using io.github.hatayama.UnityCliLoop.ToolContracts; + +namespace io.github.hatayama.UnityCliLoop.Tests.Editor +{ + /// + /// Tests VibeLogger append diagnostics without relying on the Unity request pipeline. + /// + [TestFixture] + public sealed class VibeLoggerTests + { + private const string LogFilePrefix = "unity_vibe"; + + [Test] + public void LogInfo_WhenExistingLogFileHasMalformedOldLine_DoesNotScanWholeFile() + { + // Verifies append integrity diagnostics inspect only the newly appended JSONL tail. + string logFilePath = CurrentLogFilePath(); + string logDirectory = Path.GetDirectoryName(logFilePath); + Assert.That(logDirectory, Is.Not.Null); + Directory.CreateDirectory(logDirectory); + + bool hadOriginalFile = File.Exists(logFilePath); + string originalContent = hadOriginalFile ? File.ReadAllText(logFilePath) : ""; + + try + { + File.WriteAllText(logFilePath, "{\"operation\":\"old_valid\"}\n{malformed_json\n"); + + VibeLoggerService logger = new VibeLoggerService(); + logger.LogInfo( + "vibe_logger_tail_validation_test", + "Tail validation should ignore malformed historical content."); + + string updatedContent = File.ReadAllText(logFilePath); + Assert.That(updatedContent, Does.Contain("vibe_logger_tail_validation_test")); + Assert.That(updatedContent, Does.Not.Contain("vibe_log_write_interleaving_detected")); + } + finally + { + if (hadOriginalFile) + { + File.WriteAllText(logFilePath, originalContent); + } + else if (File.Exists(logFilePath)) + { + File.Delete(logFilePath); + } + } + } + + private static string CurrentLogFilePath() + { + string projectRoot = Path.GetFullPath(Path.Combine(UnityEngine.Application.dataPath, "..")); + return Path.Combine( + projectRoot, + UnityCliLoopConstants.OUTPUT_ROOT_DIR, + UnityCliLoopConstants.VIBE_LOGS_DIR, + $"{LogFilePrefix}_{DateTime.UtcNow:yyyyMMdd}.json"); + } + } +} diff --git a/Assets/Tests/Editor/VibeLoggerTests.cs.meta b/Assets/Tests/Editor/VibeLoggerTests.cs.meta new file mode 100644 index 0000000000..25f8d9ab65 --- /dev/null +++ b/Assets/Tests/Editor/VibeLoggerTests.cs.meta @@ -0,0 +1,11 @@ +fileFormatVersion: 2 +guid: 60a5645b6aeb4734822496106a079c68 +MonoImporter: + externalObjects: {} + serializedVersion: 2 + defaultReferences: [] + executionOrder: 0 + icon: {instanceID: 0} + userData: + assetBundleName: + assetBundleVariant: diff --git a/Packages/src/Editor/Infrastructure/Api/CompileStatusBridgeCommand.cs b/Packages/src/Editor/Infrastructure/Api/CompileStatusBridgeCommand.cs index a4e6e32aad..2fe4f4687d 100644 --- a/Packages/src/Editor/Infrastructure/Api/CompileStatusBridgeCommand.cs +++ b/Packages/src/Editor/Infrastructure/Api/CompileStatusBridgeCommand.cs @@ -19,8 +19,11 @@ internal static class CompileStatusBridgeCommand private const string RequestIdParamName = "RequestId"; private const string RecoveredCompileResultMessage = "Compilation completed, but Unity reloaded scripts before Unity CLI Loop could record detailed errors or warnings. Use get-logs to inspect the compiler output."; +#if ULOOP_DEBUG + private const int MaxLoggedStatusSignatureCacheEntries = 256; private static readonly Dictionary LastLoggedStatusByRequestId = new Dictionary(); +#endif public static GetCompileStatusResponse Execute(JToken paramsToken) { @@ -165,6 +168,7 @@ private static void LogCompileStatusQueryReceived( string requestId, GetCompileStatusResponse response) { +#if ULOOP_DEBUG Debug.Assert(response != null, "response must not be null"); string signature = CreateStatusSignature(response); @@ -177,7 +181,7 @@ private static void LogCompileStatusQueryReceived( if (!string.IsNullOrWhiteSpace(requestId)) { - LastLoggedStatusByRequestId[requestId] = signature; + StoreLoggedStatusSignature(requestId, signature); } VibeLogger.LogInfo( @@ -194,6 +198,27 @@ private static void LogCompileStatusQueryReceived( message = response.Message }, requestId); + + if (!string.IsNullOrWhiteSpace(requestId) && response.Ready) + { + LastLoggedStatusByRequestId.Remove(requestId); + } +#endif + } + +#if ULOOP_DEBUG + private static void StoreLoggedStatusSignature(string requestId, string signature) + { + Debug.Assert(!string.IsNullOrWhiteSpace(requestId), "requestId must not be null or whitespace"); + Debug.Assert(!string.IsNullOrWhiteSpace(signature), "signature must not be null or whitespace"); + + if (!LastLoggedStatusByRequestId.ContainsKey(requestId) && + LastLoggedStatusByRequestId.Count >= MaxLoggedStatusSignatureCacheEntries) + { + LastLoggedStatusByRequestId.Clear(); + } + + LastLoggedStatusByRequestId[requestId] = signature; } private static string CreateStatusSignature(GetCompileStatusResponse response) @@ -209,5 +234,6 @@ private static string CreateStatusSignature(GetCompileStatusResponse response) response.IsDomainReloadInProgress, response.Message ?? ""); } +#endif } } diff --git a/Packages/src/Editor/ToolContracts/VibeLogger.cs b/Packages/src/Editor/ToolContracts/VibeLogger.cs index 5ed4465ef2..eb312cd7d7 100644 --- a/Packages/src/Editor/ToolContracts/VibeLogger.cs +++ b/Packages/src/Editor/ToolContracts/VibeLogger.cs @@ -244,10 +244,10 @@ private void Log(string level, string operation, string message, object context, /// private void SaveLogToFile(VibeLogEntry logEntry) { - SaveLogToFile(logEntry, validateIntegrity: true); + SaveLogToFileWithIntegrityOption(logEntry, validateIntegrity: true); } - private void SaveLogToFile(VibeLogEntry logEntry, bool validateIntegrity) + private void SaveLogToFileWithIntegrityOption(VibeLogEntry logEntry, bool validateIntegrity) { if (!Directory.Exists(_logDirectory)) { @@ -265,10 +265,11 @@ private void SaveLogToFile(VibeLogEntry logEntry, bool validateIntegrity) string fileName = $"{LOG_FILE_PREFIX}_{DateTime.UtcNow:yyyyMMdd}.json"; string filePath = Path.Combine(_logDirectory, fileName); RotateLogFileIfNeeded(filePath); - AppendJsonLineWithRetry(filePath, JsonConvert.SerializeObject(logEntry) + "\n"); + string jsonLine = JsonConvert.SerializeObject(logEntry) + "\n"; + (long Offset, int Length) appendedWrite = AppendJsonLineWithRetry(filePath, jsonLine); if (validateIntegrity) { - DetectInterleavingIfNeeded(filePath); + DetectInterleavingIfNeeded(filePath, appendedWrite.Offset, appendedWrite.Length); } } } @@ -292,18 +293,20 @@ private void RotateLogFileIfNeeded(string filePath) CleanupOldLogFiles(); } - private static void AppendJsonLineWithRetry(string filePath, string jsonLine) + private static (long Offset, int Length) AppendJsonLineWithRetry(string filePath, string jsonLine) { byte[] payload = Encoding.UTF8.GetBytes(jsonLine); for (int retry = 0; retry < MAX_WRITE_RETRIES; retry++) { try { - using (FileStream fileStream = new FileStream(filePath, FileMode.Append, FileAccess.Write, FileShare.Read)) + using (FileStream fileStream = new FileStream(filePath, FileMode.OpenOrCreate, FileAccess.ReadWrite, FileShare.Read)) { + long appendOffset = fileStream.Length; + fileStream.Position = appendOffset; fileStream.Write(payload, 0, payload.Length); fileStream.Flush(); - return; + return (appendOffset, payload.Length); } } catch (IOException ex) when (IsFileSharingViolation(ex) && retry < MAX_WRITE_RETRIES - 1) @@ -319,22 +322,21 @@ private static void AppendJsonLineWithRetry(string filePath, string jsonLine) throw new InvalidOperationException($"Failed to write VibeLogger entry after {MAX_WRITE_RETRIES} retries due to file sharing violations"); } - private void DetectInterleavingIfNeeded(string filePath) + private void DetectInterleavingIfNeeded(string filePath, long appendedOffset, int appendedLength) { if (_hasReportedInterleaving) { return; } - (bool HasMalformedLine, int LastValidLineNumber) result = - InspectJsonLines(filePath); - if (!result.HasMalformedLine) + string appendedText = ReadAppendedText(filePath, appendedOffset, appendedLength); + if (!HasMalformedJsonLine(appendedText)) { return; } _hasReportedInterleaving = true; - SaveLogToFile( + SaveLogToFileWithIntegrityOption( CreateDiagnosticLogEntry( "WARNING", "vibe_log_write_interleaving_detected", @@ -345,35 +347,59 @@ private void DetectInterleavingIfNeeded(string filePath) source = "Unity", process_id = Process.GetCurrentProcess().Id, thread_id = Thread.CurrentThread.ManagedThreadId, - last_valid_line_number = result.LastValidLineNumber + appended_offset = appendedOffset, + appended_byte_length = appendedLength }), validateIntegrity: false); } - private static (bool HasMalformedLine, int LastValidLineNumber) InspectJsonLines(string filePath) + private static string ReadAppendedText(string filePath, long appendedOffset, int appendedLength) { - int lineNumber = 0; - int lastValidLineNumber = 0; - foreach (string line in File.ReadLines(filePath)) + UnityEngine.Debug.Assert(appendedOffset >= 0, "appendedOffset must not be negative"); + UnityEngine.Debug.Assert(appendedLength > 0, "appendedLength must be positive"); + + byte[] payload = new byte[appendedLength]; + using (FileStream fileStream = new FileStream(filePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite)) + { + fileStream.Position = appendedOffset; + int totalBytesRead = 0; + while (totalBytesRead < appendedLength) + { + int bytesRead = fileStream.Read(payload, totalBytesRead, appendedLength - totalBytesRead); + if (bytesRead == 0) + { + break; + } + + totalBytesRead += bytesRead; + } + + return Encoding.UTF8.GetString(payload, 0, totalBytesRead); + } + } + + private static bool HasMalformedJsonLine(string jsonLines) + { + string[] lines = jsonLines.Split('\n'); + foreach (string line in lines) { - lineNumber++; - if (string.IsNullOrWhiteSpace(line)) + string candidate = line.TrimEnd('\r'); + if (string.IsNullOrWhiteSpace(candidate)) { continue; } try { - JToken.Parse(line); - lastValidLineNumber = lineNumber; + JToken.Parse(candidate); } catch (JsonReaderException) { - return (true, lastValidLineNumber); + return true; } } - return (false, lastValidLineNumber); + return false; } private void TrySaveFileDiagnosticLog( @@ -383,7 +409,7 @@ private void TrySaveFileDiagnosticLog( { try { - SaveLogToFile( + SaveLogToFileWithIntegrityOption( CreateDiagnosticLogEntry("ERROR", operation, message, context), validateIntegrity: false); }