diff --git a/.github/workflows/dotnet.yml b/.github/workflows/dotnet.yml index cbee36951c..55808b4602 100644 --- a/.github/workflows/dotnet.yml +++ b/.github/workflows/dotnet.yml @@ -83,3 +83,13 @@ jobs: Codacy__ApiKey: ${{ secrets.CODACY_APIKEY }} CodeCov__Token: ${{ secrets.CODECOV_TOKEN }} EMAIL_PASSWORD: ${{ secrets.EMAIL_PASSWORD }} + + - name: Upload Hang Dumps + if: always() + uses: actions/upload-artifact@v4 + with: + name: hang-dumps-${{ matrix.os }} + path: | + **/*.dmp + if-no-files-found: ignore + retention-days: 7 diff --git a/src/ModularPipelines.Build/Modules/RunUnitTestsModule.cs b/src/ModularPipelines.Build/Modules/RunUnitTestsModule.cs index 13c222b49f..8c4a6a389f 100644 --- a/src/ModularPipelines.Build/Modules/RunUnitTestsModule.cs +++ b/src/ModularPipelines.Build/Modules/RunUnitTestsModule.cs @@ -38,7 +38,7 @@ protected override ModuleConfiguration Configure() => ModuleConfiguration.Create Project = unitTestProjectFile.Path, NoBuild = true, Framework = _pipelineSettings.Value.TestFramework, - Arguments = ["--coverage", "--coverage-output-format", "cobertura"], + Arguments = ["--coverage", "--coverage-output-format", "cobertura", "--hangdump", "--hangdump-timeout", "20m"], Configuration = "Release", Properties = [ diff --git a/src/ModularPipelines/Console/ConsoleCoordinator.cs b/src/ModularPipelines/Console/ConsoleCoordinator.cs index 4bef2c123b..8aa28e9693 100644 --- a/src/ModularPipelines/Console/ConsoleCoordinator.cs +++ b/src/ModularPipelines/Console/ConsoleCoordinator.cs @@ -124,16 +124,17 @@ public void Install() _outputLogger = _loggerFactory.CreateLogger("ModularPipelines.Output"); // Install our intercepting writers + // Buffer output when progress is active AND we're not in the middle of flushing _coordinatedOut = new CoordinatedTextWriter( this, _originalConsoleOut, - () => _isProgressActive, + () => _isProgressActive && !_outputCoordinator.IsFlushing, _secretObfuscator); _coordinatedError = new CoordinatedTextWriter( this, _originalConsoleError, - () => _isProgressActive, + () => _isProgressActive && !_outputCoordinator.IsFlushing, _secretObfuscator); System.Console.SetOut(_coordinatedOut); diff --git a/src/ModularPipelines/Console/CoordinatedTextWriter.cs b/src/ModularPipelines/Console/CoordinatedTextWriter.cs index 944ee646e0..f213148444 100644 --- a/src/ModularPipelines/Console/CoordinatedTextWriter.cs +++ b/src/ModularPipelines/Console/CoordinatedTextWriter.cs @@ -29,7 +29,7 @@ internal class CoordinatedTextWriter : TextWriter { private readonly IConsoleCoordinator _coordinator; private readonly TextWriter _realConsole; - private readonly Func _isProgressActive; + private readonly Func _shouldBuffer; private readonly ISecretObfuscator _secretObfuscator; private readonly StringBuilder _lineBuffer = new(); private readonly object _lineBufferLock = new(); @@ -39,17 +39,17 @@ internal class CoordinatedTextWriter : TextWriter /// /// The console coordinator. /// The real console to write to when not buffering. - /// Function that returns whether progress is active. + /// Function that returns whether output should be buffered. /// Obfuscator for secrets in output. public CoordinatedTextWriter( IConsoleCoordinator coordinator, TextWriter realConsole, - Func isProgressActive, + Func shouldBuffer, ISecretObfuscator secretObfuscator) { _coordinator = coordinator; _realConsole = realConsole; - _isProgressActive = isProgressActive; + _shouldBuffer = shouldBuffer; _secretObfuscator = secretObfuscator; } @@ -62,7 +62,7 @@ public override void WriteLine(string? value) var message = value ?? string.Empty; var obfuscated = _secretObfuscator.Obfuscate(message, null); - if (!_isProgressActive()) + if (!_shouldBuffer()) { // Progress not running - write directly _realConsole.WriteLine(obfuscated); @@ -89,7 +89,7 @@ public override void Write(string? value) var obfuscated = _secretObfuscator.Obfuscate(value, null); - if (!_isProgressActive()) + if (!_shouldBuffer()) { // Progress not running - write directly _realConsole.Write(obfuscated); @@ -159,7 +159,7 @@ public override void Flush() var line = _lineBuffer.ToString(); _lineBuffer.Clear(); - if (_isProgressActive()) + if (_shouldBuffer()) { RouteToBuffer(line); } diff --git a/src/ModularPipelines/Console/IOutputCoordinator.cs b/src/ModularPipelines/Console/IOutputCoordinator.cs index 570d99835b..116b6a61e2 100644 --- a/src/ModularPipelines/Console/IOutputCoordinator.cs +++ b/src/ModularPipelines/Console/IOutputCoordinator.cs @@ -6,6 +6,12 @@ namespace ModularPipelines.Console; /// internal interface IOutputCoordinator { + /// + /// Gets whether output flushing is currently in progress. + /// When true, console writes should bypass buffering and go directly to the real console. + /// + bool IsFlushing { get; } + /// /// Sets the progress controller for pause/resume coordination. /// Must be called before any modules complete. diff --git a/src/ModularPipelines/Console/OutputCoordinator.cs b/src/ModularPipelines/Console/OutputCoordinator.cs index 6a021b8f3f..78860832eb 100644 --- a/src/ModularPipelines/Console/OutputCoordinator.cs +++ b/src/ModularPipelines/Console/OutputCoordinator.cs @@ -21,20 +21,24 @@ internal sealed class OutputCoordinator : IOutputCoordinator private readonly SemaphoreSlim _writeLock = new(1, 1); private IProgressController _progressController = NoOpProgressController.Instance; - private bool _isFlushing; + private bool _isProcessingQueue; + private volatile bool _isFlushingOutput; public OutputCoordinator( IBuildSystemFormatterProvider formatterProvider, ILoggerFactory loggerFactory, IServiceProvider serviceProvider) { - _formatterProvider = formatterProvider; - _loggerFactory = loggerFactory; - _serviceProvider = serviceProvider; + _formatterProvider = formatterProvider ?? throw new ArgumentNullException(nameof(formatterProvider)); + _loggerFactory = loggerFactory ?? throw new ArgumentNullException(nameof(loggerFactory)); + _serviceProvider = serviceProvider ?? throw new ArgumentNullException(nameof(serviceProvider)); _logger = loggerFactory.CreateLogger(); _console = System.Console.Out; } + /// + public bool IsFlushing => _isFlushingOutput; + /// public void SetProgressController(IProgressController controller) { @@ -55,10 +59,10 @@ public async Task EnqueueAndFlushAsync(IModuleOutputBuffer buffer, CancellationT lock (_queueLock) { _pendingQueue.Enqueue(pending); - shouldProcess = !_isFlushing; + shouldProcess = !_isProcessingQueue; if (shouldProcess) { - _isFlushing = true; + _isProcessingQueue = true; } } @@ -85,7 +89,7 @@ private async Task ProcessQueueAsync(CancellationToken cancellationToken) { if (_pendingQueue.Count == 0) { - _isFlushing = false; + _isProcessingQueue = false; return; } @@ -104,12 +108,14 @@ private async Task ProcessQueueAsync(CancellationToken cancellationToken) try { await _progressController.PauseAsync().ConfigureAwait(false); + _isFlushingOutput = true; try { FlushBuffer(pending.Buffer, formatter); } finally { + _isFlushingOutput = false; await _progressController.ResumeAsync().ConfigureAwait(false); } } diff --git a/src/ModularPipelines/Console/ProgressSession.cs b/src/ModularPipelines/Console/ProgressSession.cs index 2dbe4823e7..72212fc3a2 100644 --- a/src/ModularPipelines/Console/ProgressSession.cs +++ b/src/ModularPipelines/Console/ProgressSession.cs @@ -47,9 +47,12 @@ internal class ProgressSession : IProgressSession, IProgressController private int _totalModuleCount; private int _completedModuleCount; - private readonly SemaphoreSlim _pauseLock = new(1, 1); + // Pause coordination - uses signals instead of locks held during slow operations + private readonly object _pauseStateLock = new(); private bool _isPaused; + private bool _inRefresh; // True while ctx.Refresh() is executing private TaskCompletionSource? _resumeSignal; + private TaskCompletionSource? _refreshCompleted; // Signaled when in-flight refresh completes public ProgressSession( ConsoleCoordinator coordinator, @@ -102,57 +105,67 @@ await AnsiConsole.Progress() // Keep alive until all modules complete or cancellation while (!ctx.IsFinished && !_cancellationToken.IsCancellationRequested) { - // Check if we should pause for module output - bool shouldRefresh = true; + // Check pause state and prepare for refresh + bool shouldRefresh; TaskCompletionSource? resumeSignal = null; - await _pauseLock.WaitAsync().ConfigureAwait(false); - try + lock (_pauseStateLock) { if (_isPaused) { + // We're paused - signal that any in-flight refresh is done + _refreshCompleted?.TrySetResult(); resumeSignal = _resumeSignal; shouldRefresh = false; } - } - finally - { - _pauseLock.Release(); + else + { + // Mark that we're about to refresh + _inRefresh = true; + shouldRefresh = true; + } } if (resumeSignal != null) { // Wait for resume signal with timeout to prevent stuck UI - // If output takes longer than 60 seconds, auto-resume to prevent indefinite pause var timeoutTask = Task.Delay(TimeSpan.FromSeconds(60), CancellationToken.None); var completedTask = await Task.WhenAny(resumeSignal.Task, timeoutTask).ConfigureAwait(false); if (completedTask == timeoutTask) { - // Timeout - force resume to prevent stuck state - // Log warning as this indicates a potential issue with output flushing _logger.LogWarning( - "Progress pause timed out after 60 seconds. Forcing resume to prevent stuck UI. " + - "This may indicate slow I/O or a deadlock in output coordination."); + "Progress pause timed out after 60 seconds. Forcing resume to prevent stuck UI."); - await _pauseLock.WaitAsync().ConfigureAwait(false); - try + lock (_pauseStateLock) { _isPaused = false; + _inRefresh = false; // Reset for state consistency _resumeSignal?.TrySetResult(); _resumeSignal = null; - } - finally - { - _pauseLock.Release(); + _refreshCompleted = null; } } } else if (shouldRefresh) { - // Manually refresh when not paused - this prevents rendering glitches - // when module output is being written to the console - ctx.Refresh(); + try + { + ctx.Refresh(); + } + finally + { + // Mark refresh complete and check if pause was requested during refresh + lock (_pauseStateLock) + { + _inRefresh = false; + if (_isPaused) + { + // Pause was requested while we were refreshing - signal completion + _refreshCompleted?.TrySetResult(); + } + } + } } await Task.Delay(100, CancellationToken.None).ConfigureAwait(false); @@ -374,48 +387,52 @@ private void StartProgressTicker(ProgressTask task, TimeSpan estimatedDuration) /// public async Task PauseAsync() { - await _pauseLock.WaitAsync().ConfigureAwait(false); - try + TaskCompletionSource? waitForRefresh = null; + + lock (_pauseStateLock) { if (_isPaused) { + // Already paused - nothing to do. We don't wait on _refreshCompleted here + // because it could be stale (e.g., from a previous pause that timed out), + // which would cause this caller to wait forever. return; } _isPaused = true; _resumeSignal = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - // Signal the progress loop to pause - // The loop will clear progress and wait for resume + if (_inRefresh) + { + // Progress loop is currently in ctx.Refresh() - need to wait for it + _refreshCompleted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + waitForRefresh = _refreshCompleted; + } + // else: Progress loop is not refreshing, pause takes effect immediately } - finally + + // Wait for any in-flight refresh to complete (outside the lock) + if (waitForRefresh != null) { - _pauseLock.Release(); + await waitForRefresh.Task.ConfigureAwait(false); } - // Wait a moment for progress to clear + // Small delay to allow terminal to process any buffered escape sequences await Task.Delay(50).ConfigureAwait(false); } /// - public async Task ResumeAsync() + public Task ResumeAsync() { - await _pauseLock.WaitAsync().ConfigureAwait(false); - try + lock (_pauseStateLock) { - if (!_isPaused) - { - return; - } - _isPaused = false; _resumeSignal?.TrySetResult(); _resumeSignal = null; + _refreshCompleted = null; } - finally - { - _pauseLock.Release(); - } + + return Task.CompletedTask; } #endregion @@ -423,6 +440,16 @@ public async Task ResumeAsync() /// public async ValueTask DisposeAsync() { + // Signal resume in case we're disposed while paused + // Also clear the signals to prevent any concurrent PauseAsync from hanging + lock (_pauseStateLock) + { + _isPaused = false; + _resumeSignal?.TrySetResult(); + _resumeSignal = null; + _refreshCompleted = null; + } + // Signal all tasks to stop lock (_progressLock) { diff --git a/src/ModularPipelines/FileSystem/File.cs b/src/ModularPipelines/FileSystem/File.cs index 0a178dc1ea..5ed277dd20 100644 --- a/src/ModularPipelines/FileSystem/File.cs +++ b/src/ModularPipelines/FileSystem/File.cs @@ -3,7 +3,6 @@ using System.Text.Json.Serialization; using Microsoft.Extensions.Logging; using ModularPipelines.Logging; -using ModularPipelines.Tracing; namespace ModularPipelines.FileSystem; @@ -48,7 +47,7 @@ private File(FileInfo fileInfo, string originalPath, IFileSystemProvider provide /// > public Task ReadAsync(CancellationToken cancellationToken = default) { - LogFileOperation("Reading File: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFileOperation("Reading File: {Path}", this); return _provider.ReadAllTextAsync(Path, cancellationToken); } @@ -56,14 +55,14 @@ public Task ReadAsync(CancellationToken cancellationToken = default) /// public IAsyncEnumerable ReadLinesAsync(CancellationToken cancellationToken = default) { - LogFileOperation("Reading File: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFileOperation("Reading File: {Path}", this); return _provider.ReadLinesAsync(Path, cancellationToken); } public Task ReadBytesAsync(CancellationToken cancellationToken = default) { - LogFileOperation("Reading File: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFileOperation("Reading File: {Path}", this); return _provider.ReadAllBytesAsync(Path, cancellationToken); } @@ -100,28 +99,28 @@ public Stream GetStream(FileAccess fileAccess = FileAccess.ReadWrite) public Task WriteAsync(string contents, CancellationToken cancellationToken = default) { - LogFileOperation("Writing to File: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFileOperation("Writing to File: {Path}", this); return _provider.WriteAllTextAsync(Path, contents, cancellationToken); } public Task WriteAsync(byte[] contents, CancellationToken cancellationToken = default) { - LogFileOperation("Writing to File: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFileOperation("Writing to File: {Path}", this); return _provider.WriteAllBytesAsync(Path, contents, cancellationToken); } public Task WriteAsync(IEnumerable contents, CancellationToken cancellationToken = default) { - LogFileOperation("Writing to File: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFileOperation("Writing to File: {Path}", this); return _provider.WriteAllLinesAsync(Path, contents, cancellationToken); } public async Task WriteAsync(ReadOnlyMemory contents, CancellationToken cancellationToken = default) { - LogFileOperation("Writing to File: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFileOperation("Writing to File: {Path}", this); var fileStream = _provider.Create(Path); await using (fileStream.ConfigureAwait(false)) @@ -132,7 +131,7 @@ public async Task WriteAsync(ReadOnlyMemory contents, CancellationToken ca public async Task WriteAsync(Stream contents, CancellationToken cancellationToken = default) { - LogFileOperation("Writing to File: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFileOperation("Writing to File: {Path}", this); var fileStream = _provider.Create(Path); await using (fileStream.ConfigureAwait(false)) @@ -148,14 +147,14 @@ public async Task WriteAsync(Stream contents, CancellationToken cancellationToke public Task AppendAsync(string contents, CancellationToken cancellationToken = default) { - LogFileOperation("Appending to File: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFileOperation("Appending to File: {Path}", this); return _provider.AppendAllTextAsync(Path, contents, cancellationToken); } public Task AppendAsync(IEnumerable contents, CancellationToken cancellationToken = default) { - LogFileOperation("Appending to File: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFileOperation("Appending to File: {Path}", this); return _provider.AppendAllLinesAsync(Path, contents, cancellationToken); } @@ -188,7 +187,7 @@ public Task AppendAsync(IEnumerable contents, CancellationToken cancella public File Create() { - LogFileOperation("Creating File: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFileOperation("Creating File: {Path}", this); var fileStream = _provider.Create(Path); fileStream.Dispose(); @@ -201,7 +200,7 @@ public File Create() /// This file instance for method chaining. public async Task CreateAsync() { - LogFileOperation("Creating File: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFileOperation("Creating File: {Path}", this); var fileStream = _provider.Create(Path); await fileStream.DisposeAsync().ConfigureAwait(false); @@ -232,7 +231,7 @@ public FileAttributes Attributes /// > public void Delete() { - LogFileOperation("Deleting File: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFileOperation("Deleting File: {Path}", this); _provider.DeleteFile(Path); } @@ -247,7 +246,7 @@ public void Delete() /// Cancellation token. public Task DeleteAsync(CancellationToken cancellationToken = default) { - LogFileOperation("Deleting File: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFileOperation("Deleting File: {Path}", this); return Task.Run(() => _provider.DeleteFile(Path), cancellationToken); } @@ -255,7 +254,7 @@ public Task DeleteAsync(CancellationToken cancellationToken = default) /// > public File MoveTo(string path) { - LogFileOperationWithDestination("Moving File: {Source} > {Destination} (Module: {ModuleName}, Activity: {ActivityId})", this, path); + LogFileOperationWithDestination("Moving File: {Source} > {Destination}", this, path); _provider.MoveFile(Path, path); return new File(path, _provider); @@ -264,7 +263,7 @@ public File MoveTo(string path) /// > public File MoveTo(Folder folder) { - LogFileOperationWithDestination("Moving File: {Source} > {Destination} (Module: {ModuleName}, Activity: {ActivityId})", this, folder); + LogFileOperationWithDestination("Moving File: {Source} > {Destination}", this, folder); folder.Create(); return MoveTo(_provider.Combine(folder.Path, Name)); @@ -281,7 +280,7 @@ public File MoveTo(Folder folder) /// A new File instance at the destination path. public Task MoveToAsync(string path, CancellationToken cancellationToken = default) { - LogFileOperationWithDestination("Moving File: {Source} > {Destination} (Module: {ModuleName}, Activity: {ActivityId})", this, path); + LogFileOperationWithDestination("Moving File: {Source} > {Destination}", this, path); return Task.Run(() => { @@ -301,7 +300,7 @@ public Task MoveToAsync(string path, CancellationToken cancellationToken = /// A new File instance at the destination path. public async Task MoveToAsync(Folder folder, CancellationToken cancellationToken = default) { - LogFileOperationWithDestination("Moving File: {Source} > {Destination} (Module: {ModuleName}, Activity: {ActivityId})", this, folder); + LogFileOperationWithDestination("Moving File: {Source} > {Destination}", this, folder); await folder.CreateAsync().ConfigureAwait(false); return await MoveToAsync(_provider.Combine(folder.Path, Name), cancellationToken).ConfigureAwait(false); @@ -310,7 +309,7 @@ public async Task MoveToAsync(Folder folder, CancellationToken cancellatio /// > public File CopyTo(string path) { - LogFileOperationWithDestination("Copying File: {Source} > {Destination} (Module: {ModuleName}, Activity: {ActivityId})", this, path); + LogFileOperationWithDestination("Copying File: {Source} > {Destination}", this, path); _provider.CopyFile(Path, path, true); return new File(path, _provider); @@ -318,7 +317,7 @@ public File CopyTo(string path) public File CopyTo(Folder folder) { - LogFileOperationWithDestination("Copying File: {Source} > {Destination} (Module: {ModuleName}, Activity: {ActivityId})", this, folder); + LogFileOperationWithDestination("Copying File: {Source} > {Destination}", this, folder); folder.Create(); return CopyTo(_provider.Combine(folder.Path, Name)); @@ -332,7 +331,7 @@ public File CopyTo(Folder folder) /// A new File instance representing the copied file. public async Task CopyToAsync(string path, CancellationToken cancellationToken = default) { - LogFileOperationWithDestination("Copying File: {Source} > {Destination} (Module: {ModuleName}, Activity: {ActivityId})", this, path); + LogFileOperationWithDestination("Copying File: {Source} > {Destination}", this, path); var sourceStream = _provider.OpenRead(Path); await using (sourceStream.ConfigureAwait(false)) @@ -355,7 +354,7 @@ public async Task CopyToAsync(string path, CancellationToken cancellationT /// A new File instance representing the copied file. public async Task CopyToAsync(Folder folder, CancellationToken cancellationToken = default) { - LogFileOperationWithDestination("Copying File: {Source} > {Destination} (Module: {ModuleName}, Activity: {ActivityId})", this, folder); + LogFileOperationWithDestination("Copying File: {Source} > {Destination}", this, folder); await folder.CreateAsync().ConfigureAwait(false); return await CopyToAsync(_provider.Combine(folder.Path, Name), cancellationToken).ConfigureAwait(false); @@ -366,7 +365,7 @@ public static File GetNewTemporaryFilePath() var provider = SystemFileSystemProvider.Instance; var path = provider.Combine(provider.GetTempPath(), provider.GetRandomFileName()); - LogFileOperation("Temporary File Path: {Path} (Module: {ModuleName}, Activity: {ActivityId})", path); + LogFileOperation("Temporary File Path: {Path}", path); return path!; } @@ -457,28 +456,18 @@ public override int GetHashCode() } /// - /// Logs a file operation with Activity context information. + /// Logs a file operation. /// - /// - /// Phase 2: Uses Activity.Current for context alongside AsyncLocal for backward compatibility. - /// The log message includes the current module name and activity ID when available. - /// private static void LogFileOperation(string messageTemplate, object? arg1) { - var moduleName = ModuleActivityTracing.GetCurrentModuleName() ?? "Unknown"; - var activityId = ModuleActivityTracing.GetCurrentActivityId(); - - ModuleLogger.Current.LogInformation(messageTemplate, arg1, moduleName, activityId); + ModuleLogger.Current.LogInformation(messageTemplate, arg1); } /// - /// Logs a file operation with Activity context information for operations with source and destination. + /// Logs a file operation for operations with source and destination. /// private static void LogFileOperationWithDestination(string messageTemplate, object? source, object? destination) { - var moduleName = ModuleActivityTracing.GetCurrentModuleName() ?? "Unknown"; - var activityId = ModuleActivityTracing.GetCurrentActivityId(); - - ModuleLogger.Current.LogInformation(messageTemplate, source, destination, moduleName, activityId); + ModuleLogger.Current.LogInformation(messageTemplate, source, destination); } } diff --git a/src/ModularPipelines/FileSystem/Folder.cs b/src/ModularPipelines/FileSystem/Folder.cs index a428678fe0..f95d45fda4 100644 --- a/src/ModularPipelines/FileSystem/Folder.cs +++ b/src/ModularPipelines/FileSystem/Folder.cs @@ -7,7 +7,6 @@ using Microsoft.Extensions.Logging; using ModularPipelines.JsonUtils; using ModularPipelines.Logging; -using ModularPipelines.Tracing; namespace ModularPipelines.FileSystem; @@ -97,7 +96,7 @@ public Folder Root public Folder Create() { - LogFolderOperation("Creating Folder: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFolderOperation("Creating Folder: {Path}", this); _provider.CreateDirectory(Path); return this; @@ -113,7 +112,7 @@ public Folder Create() /// This folder instance for method chaining. public Task CreateAsync(CancellationToken cancellationToken = default) { - LogFolderOperation("Creating Folder: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFolderOperation("Creating Folder: {Path}", this); return Task.Run(() => { @@ -124,7 +123,7 @@ public Task CreateAsync(CancellationToken cancellationToken = default) public void Delete() { - LogFolderOperation("Deleting Folder: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFolderOperation("Deleting Folder: {Path}", this); _provider.DeleteDirectory(Path, recursive: true); } @@ -138,7 +137,7 @@ public void Delete() /// Cancellation token. public Task DeleteAsync(CancellationToken cancellationToken = default) { - LogFolderOperation("Deleting Folder: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFolderOperation("Deleting Folder: {Path}", this); return Task.Run(() => _provider.DeleteDirectory(Path, recursive: true), cancellationToken); } @@ -185,7 +184,7 @@ public void Clean(bool removeReadOnlyAttribute) /// public void Clean(bool removeReadOnlyAttribute, bool continueOnError) { - LogFolderOperation("Cleaning Folder: {Path} (Module: {ModuleName}, Activity: {ActivityId})", this); + LogFolderOperation("Cleaning Folder: {Path}", this); var errors = new List(); @@ -202,7 +201,7 @@ public void Clean(bool removeReadOnlyAttribute, bool continueOnError) } catch (Exception ex) when (continueOnError) { - LogFolderWarning(ex, "Failed to delete directory: {Path} (Module: {ModuleName}, Activity: {ActivityId})", directory.FullName); + LogFolderWarning(ex, "Failed to delete directory: {Path}", directory.FullName); errors.Add(ex); } } @@ -220,7 +219,7 @@ public void Clean(bool removeReadOnlyAttribute, bool continueOnError) } catch (Exception ex) when (continueOnError) { - LogFolderWarning(ex, "Failed to delete file: {Path} (Module: {ModuleName}, Activity: {ActivityId})", file.FullName); + LogFolderWarning(ex, "Failed to delete file: {Path}", file.FullName); errors.Add(ex); } } @@ -252,7 +251,7 @@ public Folder CopyTo(string targetPath) /// A new instance representing the copied folder. public Folder CopyTo(string targetPath, bool preserveTimestamps) { - LogFolderOperationWithDestination("Copying Folder: {Source} > {Destination} (Module: {ModuleName}, Activity: {ActivityId})", this, targetPath); + LogFolderOperationWithDestination("Copying Folder: {Source} > {Destination}", this, targetPath); _provider.CreateDirectory(targetPath); @@ -335,7 +334,7 @@ public Task CopyToAsync(string targetPath, CancellationToken cancellatio /// A new instance representing the copied folder. public async Task CopyToAsync(string targetPath, bool preserveTimestamps, CancellationToken cancellationToken = default) { - LogFolderOperationWithDestination("Copying Folder: {Source} > {Destination} (Module: {ModuleName}, Activity: {ActivityId})", this, targetPath); + LogFolderOperationWithDestination("Copying Folder: {Source} > {Destination}", this, targetPath); _provider.CreateDirectory(targetPath); @@ -406,7 +405,7 @@ public async Task CopyToAsync(string targetPath, bool preserveTimestamps public Folder MoveTo(string path) { - LogFolderOperationWithDestination("Moving Folder: {Source} > {Destination} (Module: {ModuleName}, Activity: {ActivityId})", this, path); + LogFolderOperationWithDestination("Moving Folder: {Source} > {Destination}", this, path); _provider.MoveDirectory(Path, path); return new Folder(path, _provider); @@ -423,7 +422,7 @@ public Folder MoveTo(string path) /// A new Folder instance at the destination path. public Task MoveToAsync(string path, CancellationToken cancellationToken = default) { - LogFolderOperationWithDestination("Moving Folder: {Source} > {Destination} (Module: {ModuleName}, Activity: {ActivityId})", this, path); + LogFolderOperationWithDestination("Moving Folder: {Source} > {Destination}", this, path); return Task.Run(() => { @@ -436,7 +435,7 @@ public Folder GetFolder(string name) { var combinedPath = _provider.Combine(Path, name); - LogFolderOperation("Getting Folder: {Path} (Module: {ModuleName}, Activity: {ActivityId})", combinedPath); + LogFolderOperation("Getting Folder: {Path}", combinedPath); return new Folder(combinedPath, _provider); } @@ -445,7 +444,7 @@ public Folder CreateFolder(string name) { var folder = GetFolder(name).Create(); - LogFolderOperation("Creating Folder: {Path} (Module: {ModuleName}, Activity: {ActivityId})", folder); + LogFolderOperation("Creating Folder: {Path}", folder); return folder; } @@ -454,7 +453,7 @@ public File GetFile(string name) { var combinedPath = _provider.Combine(Path, name); - LogFolderOperation("Getting File: {Path} (Module: {ModuleName}, Activity: {ActivityId})", combinedPath); + LogFolderOperation("Getting File: {Path}", combinedPath); return new File(combinedPath, _provider); } @@ -470,7 +469,7 @@ public File CreateFile(string name) public IEnumerable GetFolders(Func predicate, Func exclusionFilters, [CallerArgumentExpression("predicate")] string predicateExpression = "") { - LogFolderOperationWithExpression("Searching Folders in: {Path} > {Expression} (Module: {ModuleName}, Activity: {ActivityId})", this, predicateExpression); + LogFolderOperationWithExpression("Searching Folders in: {Path} > {Expression}", this, predicateExpression); return SafeWalk.EnumerateFolders(this, exclusionFilters) .Select(x => new Folder(x)) @@ -480,7 +479,7 @@ public IEnumerable GetFolders(Func predicate, Func GetFiles(Func predicate, Func directoryExclusionFilters, [CallerArgumentExpression("predicate")] string predicateExpression = "") { - LogFolderOperationWithExpression("Searching Files in: {Path} > {Expression} (Module: {ModuleName}, Activity: {ActivityId})", this, predicateExpression); + LogFolderOperationWithExpression("Searching Files in: {Path} > {Expression}", this, predicateExpression); return SafeWalk.EnumerateFiles(this, directoryExclusionFilters) .Select(x => new File(x)) @@ -490,7 +489,7 @@ public IEnumerable GetFiles(Func predicate, Func public IEnumerable GetFiles(string globPattern) { - LogFolderOperationWithExpression("Searching Files in: {Path} > {Glob} (Module: {ModuleName}, Activity: {ActivityId})", this, globPattern); + LogFolderOperationWithExpression("Searching Files in: {Path} > {Glob}", this, globPattern); return new Matcher(StringComparison.OrdinalIgnoreCase) .AddInclude(globPattern) @@ -528,7 +527,7 @@ public static Folder CreateTemporaryFolder() var tempDirectory = provider.Combine(provider.GetTempPath(), provider.GetRandomFileName().Replace(".", string.Empty)); provider.CreateDirectory(tempDirectory); - LogFolderOperation("Creating Temporary Folder: {Path} (Module: {ModuleName}, Activity: {ActivityId})", tempDirectory); + LogFolderOperation("Creating Temporary Folder: {Path}", tempDirectory); return tempDirectory!; } @@ -640,50 +639,34 @@ private static void RemoveReadOnlyAttributeRecursively(DirectoryInfo directory) } /// - /// Logs a folder operation with Activity context information. + /// Logs a folder operation. /// - /// - /// Phase 2: Uses Activity.Current for context alongside AsyncLocal for backward compatibility. - /// The log message includes the current module name and activity ID when available. - /// private static void LogFolderOperation(string messageTemplate, object? arg1) { - var moduleName = ModuleActivityTracing.GetCurrentModuleName() ?? "Unknown"; - var activityId = ModuleActivityTracing.GetCurrentActivityId(); - - ModuleLogger.Current.LogInformation(messageTemplate, arg1, moduleName, activityId); + ModuleLogger.Current.LogInformation(messageTemplate, arg1); } /// - /// Logs a folder operation with Activity context information for operations with source and destination. + /// Logs a folder operation for operations with source and destination. /// private static void LogFolderOperationWithDestination(string messageTemplate, object? source, object? destination) { - var moduleName = ModuleActivityTracing.GetCurrentModuleName() ?? "Unknown"; - var activityId = ModuleActivityTracing.GetCurrentActivityId(); - - ModuleLogger.Current.LogInformation(messageTemplate, source, destination, moduleName, activityId); + ModuleLogger.Current.LogInformation(messageTemplate, source, destination); } /// - /// Logs a folder operation with Activity context information for operations with path and expression/glob. + /// Logs a folder operation for operations with path and expression/glob. /// private static void LogFolderOperationWithExpression(string messageTemplate, object? path, object? expression) { - var moduleName = ModuleActivityTracing.GetCurrentModuleName() ?? "Unknown"; - var activityId = ModuleActivityTracing.GetCurrentActivityId(); - - ModuleLogger.Current.LogInformation(messageTemplate, path, expression, moduleName, activityId); + ModuleLogger.Current.LogInformation(messageTemplate, path, expression); } /// - /// Logs a folder warning with Activity context information. + /// Logs a folder warning. /// private static void LogFolderWarning(Exception ex, string messageTemplate, object? arg1) { - var moduleName = ModuleActivityTracing.GetCurrentModuleName() ?? "Unknown"; - var activityId = ModuleActivityTracing.GetCurrentActivityId(); - - ModuleLogger.Current.LogWarning(ex, messageTemplate, arg1, moduleName, activityId); + ModuleLogger.Current.LogWarning(ex, messageTemplate, arg1); } } diff --git a/src/ModularPipelines/Logging/ModuleLogger.cs b/src/ModularPipelines/Logging/ModuleLogger.cs index 46a2cde2c1..f9eadfa7ba 100644 --- a/src/ModularPipelines/Logging/ModuleLogger.cs +++ b/src/ModularPipelines/Logging/ModuleLogger.cs @@ -16,7 +16,7 @@ namespace ModularPipelines.Logging; /// This allows File/Folder helpers and other utilities to access the logger without explicit parameter passing. /// AsyncLocal is thread-safe and flows with async/await contexts, making it ideal for async module execution. /// -internal abstract class ModuleLogger : IInternalModuleLogger, IConsoleWriter +internal abstract class ModuleLogger : IInternalModuleLogger, IConsoleWriter, IAsyncDisposable { /// /// Ambient context storage for the current module's logger. @@ -54,6 +54,8 @@ internal abstract class ModuleLogger : IInternalModuleLogger, IConsoleWriter public abstract void Dispose(); + public abstract ValueTask DisposeAsync(); + public abstract void LogToConsole(string value); public abstract void Write(IRenderable renderable); @@ -91,11 +93,6 @@ public ModuleLogger( Disposer.RegisterOnShutdown(this); } - ~ModuleLogger() - { - Dispose(disposing: false); - } - public override IDisposable? BeginScope(TState state) { return new NoopDisposable(); @@ -129,12 +126,30 @@ public override void Log(LogLevel logLevel, EventId eventId, TState stat public override void Dispose() { - Dispose(disposing: true); + // Synchronous disposal - just mark as disposed without blocking on flush + // Prefer using DisposeAsync() for proper async output flushing + lock (_disposeLock) + { + if (_isDisposed) + { + return; + } + + _isDisposed = true; + + if (_exception != null) + { + _buffer.SetException(_exception); + } + } + GC.SuppressFinalize(this); } - private void Dispose(bool disposing) + public override async ValueTask DisposeAsync() { + bool shouldFlush; + lock (_disposeLock) { if (_isDisposed) @@ -149,44 +164,32 @@ private void Dispose(bool disposing) _buffer.SetException(_exception); } - // Only perform blocking flush when called from Dispose(), not from finalizer - // Blocking in a finalizer can cause deadlocks and violates .NET best practices - if (disposing) + shouldFlush = true; + } + + if (shouldFlush) + { + // Flush output asynchronously without blocking + try { - // Flush output immediately instead of just marking completed - // This blocks until the output is written, with a timeout to prevent deadlocks - try - { - var flushTask = _outputCoordinator.EnqueueAndFlushAsync(_buffer); - var timeoutTask = Task.Delay(TimeSpan.FromSeconds(30)); - - // Use Task.WhenAny with GetAwaiter().GetResult() instead of Wait() - // to avoid potential deadlocks from synchronization context issues - var completedTask = Task.WhenAny(flushTask, timeoutTask).GetAwaiter().GetResult(); - - if (completedTask == timeoutTask) - { - // Timeout occurred - log warning, output may be lost - _defaultLogger.LogWarning( - "Module output flush timed out after 30 seconds for {ModuleType}. Some output may be lost.", - typeof(T).Name); - } - else - { - // Ensure any exception from the flush task is observed - flushTask.GetAwaiter().GetResult(); - } - } - catch (Exception ex) - { - // Best effort - don't fail disposal, but log the issue - _defaultLogger.LogWarning(ex, "Failed to flush module output during disposal for {ModuleType}", typeof(T).Name); - } + using var cts = new CancellationTokenSource(TimeSpan.FromSeconds(30)); + await _outputCoordinator.EnqueueAndFlushAsync(_buffer, cts.Token).ConfigureAwait(false); + } + catch (OperationCanceledException) + { + // Timeout occurred - log warning, output may be lost + _defaultLogger.LogWarning( + "Module output flush timed out after 30 seconds for {ModuleType}. Some output may be lost.", + typeof(T).Name); + } + catch (Exception ex) + { + // Best effort - don't fail disposal, but log the issue + _defaultLogger.LogWarning(ex, "Failed to flush module output during disposal for {ModuleType}", typeof(T).Name); } - - // If called from finalizer (disposing=false), output may be lost - // but this is acceptable as proper disposal should have been called } + + GC.SuppressFinalize(this); } public override void LogToConsole(string value) diff --git a/test/ModularPipelines.Azure.UnitTests/ModularPipelines.Azure.UnitTests.csproj b/test/ModularPipelines.Azure.UnitTests/ModularPipelines.Azure.UnitTests.csproj index 22b757252f..d177c0c7c3 100644 --- a/test/ModularPipelines.Azure.UnitTests/ModularPipelines.Azure.UnitTests.csproj +++ b/test/ModularPipelines.Azure.UnitTests/ModularPipelines.Azure.UnitTests.csproj @@ -11,6 +11,9 @@ + + + diff --git a/test/ModularPipelines.Development.Analyzers.UnitTests/ModularPipelines.Development.Analyzers.UnitTests.csproj b/test/ModularPipelines.Development.Analyzers.UnitTests/ModularPipelines.Development.Analyzers.UnitTests.csproj index af1f3b8657..b3b2284a5b 100644 --- a/test/ModularPipelines.Development.Analyzers.UnitTests/ModularPipelines.Development.Analyzers.UnitTests.csproj +++ b/test/ModularPipelines.Development.Analyzers.UnitTests/ModularPipelines.Development.Analyzers.UnitTests.csproj @@ -8,10 +8,11 @@ - - + + +