Reduce CLI diagnostic log noise and improve process logging (#15956)

Author: JamesNK

src/Aspire.Cli/Caching/DiskCache.cs

@@ -60,12 +60,12 @@ private static TimeSpan ReadWindow(IConfiguration configuration, string key, Tim
             var cacheFilePath = ResolveValidCacheFile(keyHash);
             if (cacheFilePath is null)
             {
-                _logger.LogDebug("Disk cache miss for key {RawKey}", key);
+                _logger.LogTrace("Disk cache miss for key {RawKey}", key);
                 return null;
             }
 
             // Assuming here is a hit we attempt to read the file and return the string.
-            _logger.LogDebug("Disk cache hit for key {RawKey} (file: {CacheFilePath})", key, cacheFilePath);
+            _logger.LogTrace("Disk cache hit for key {RawKey} (file: {CacheFilePath})", key, cacheFilePath);
             return await File.ReadAllTextAsync(cacheFilePath, cancellationToken).ConfigureAwait(false);
         }
         catch (Exception ex)
@@ -120,7 +120,7 @@ public async Task SetAsync(string key, string content, CancellationToken cancell
             }
 
             File.Move(tempFile, fullPath);
-            _logger.LogDebug("Stored disk cache entry for key {RawKey} (file: {CacheFilePath})", key, fullPath);
+            _logger.LogTrace("Stored disk cache entry for key {RawKey} (file: {CacheFilePath})", key, fullPath);
         }
         catch (Exception ex)
         {
@@ -270,19 +270,19 @@ private void TryDelete(FileInfo file, bool expired = false, bool old = false, bo
             file.Delete();
             if (expired)
             {
-                _logger.LogDebug("Deleted expired cache file: {CacheFile}", file.FullName);
+                _logger.LogTrace("Deleted expired cache file: {CacheFile}", file.FullName);
             }
             else if (old)
             {
-                _logger.LogDebug("Deleted old cache file during global cleanup: {CacheFile}", file.FullName);
+                _logger.LogTrace("Deleted old cache file during global cleanup: {CacheFile}", file.FullName);
             }
             else if (invalid)
             {
-                _logger.LogDebug("Deleted invalid cache file: {CacheFile}", file.FullName);
+                _logger.LogTrace("Deleted invalid cache file: {CacheFile}", file.FullName);
             }
             else
             {
-                _logger.LogDebug("Deleted cache file: {CacheFile}", file.FullName);
+                _logger.LogTrace("Deleted cache file: {CacheFile}", file.FullName);
             }
         }
         catch (Exception ex)

src/Aspire.Cli/Configuration/Features.cs

@@ -11,20 +11,29 @@ internal sealed class Features(IConfiguration configuration, ILogger<Features> l
     public bool IsFeatureEnabled(string feature, bool defaultValue)
     {
         var configKey = $"features:{feature}";
-        
+
         var value = configuration[configKey];
-        
+
         logger.LogTrace("Feature check: {Feature}, ConfigKey: {ConfigKey}, Value: '{Value}', DefaultValue: {DefaultValue}",
             feature, configKey, value ?? "(null)", defaultValue);
-        
+
         if (string.IsNullOrEmpty(value))
         {
-            logger.LogDebug("Feature {Feature} using default value: {DefaultValue}", feature, defaultValue);
+            logger.LogTrace("Feature {Feature} using default value: {DefaultValue}", feature, defaultValue);
             return defaultValue;
         }
-        
+
         var enabled = bool.TryParse(value, out var parsed) && parsed;
         logger.LogDebug("Feature {Feature} parsed value: {Enabled}", feature, enabled);
         return enabled;
     }
-}
+
+    public void LogFeatureState()
+    {
+        foreach (var metadata in KnownFeatures.GetAllFeatureMetadata())
+        {
+            var value = IsFeatureEnabled(metadata.Name, metadata.DefaultValue);
+            logger.LogDebug("Feature {Feature} = {Value} (default: {DefaultValue})", metadata.Name, value, metadata.DefaultValue);
+        }
+    }
+}

src/Aspire.Cli/Configuration/IFeatures.cs

@@ -6,4 +6,5 @@ namespace Aspire.Cli.Configuration;
 internal interface IFeatures
 {
     bool IsFeatureEnabled(string featureFlag, bool defaultValue);
-}
+    void LogFeatureState();
+}

src/Aspire.Cli/DotNet/ProcessExecution.cs

@@ -43,41 +43,31 @@ internal ProcessExecution(Process process, ILogger logger, ProcessInvocationOpti
     /// <inheritdoc />
     public bool Start()
     {
-        var suppressLogging = _options.SuppressLogging;
-
         var started = _process.Start();
 
         if (!started)
         {
-            if (!suppressLogging)
-            {
-                _logger.LogDebug("Failed to start process {FileName} with args: {Args}", FileName, string.Join(" ", Arguments));
-            }
+            _logger.LogDebug("{FileName} failed to start with args: {Args}", FileName, string.Join(" ", Arguments));
             return false;
         }
 
-        if (!suppressLogging)
-        {
-            _logger.LogDebug("Started {FileName} with PID: {ProcessId}", FileName, _process.Id);
-        }
+        _logger.LogDebug("{FileName}({ProcessId}) started in {WorkingDirectory}", FileName, _process.Id, _process.StartInfo.WorkingDirectory);
 
         // Start stream forwarders
         _stdoutForwarder = Task.Run(async () =>
         {
             await ForwardStreamToLoggerAsync(
                 _process.StandardOutput,
                 "stdout",
-                _options.StandardOutputCallback,
-                suppressLogging);
+                _options.StandardOutputCallback);
         });
 
         _stderrForwarder = Task.Run(async () =>
         {
             await ForwardStreamToLoggerAsync(
                 _process.StandardError,
                 "stderr",
-                _options.StandardErrorCallback,
-                suppressLogging);
+                _options.StandardErrorCallback);
         });
 
         return true;
@@ -86,36 +76,25 @@ await ForwardStreamToLoggerAsync(
     /// <inheritdoc />
     public async Task<int> WaitForExitAsync(CancellationToken cancellationToken)
     {
-        var suppressLogging = _options.SuppressLogging;
-
-        if (!suppressLogging)
-        {
-            _logger.LogDebug("Waiting for process to exit with PID: {ProcessId}", _process.Id);
-        }
+        _logger.LogDebug("{FileName}({ProcessId}) waiting for exit", FileName, _process.Id);
 
         await _process.WaitForExitAsync(cancellationToken);
 
         if (!_process.HasExited)
         {
-            if (!suppressLogging)
-            {
-                _logger.LogDebug("Process with PID: {ProcessId} has not exited, killing it.", _process.Id);
-            }
+            _logger.LogDebug("{FileName}({ProcessId}) has not exited, killing it", FileName, _process.Id);
             _process.Kill(false);
         }
         else
         {
-            if (!suppressLogging)
-            {
-                _logger.LogDebug("Process with PID: {ProcessId} has exited with code: {ExitCode}", _process.Id, _process.ExitCode);
-            }
+            _logger.LogDebug("{FileName}({ProcessId}) exited with code: {ExitCode}", FileName, _process.Id, _process.ExitCode);
         }
 
         // Explicitly close the streams to unblock any pending ReadLineAsync calls.
         // In some environments (particularly CI containers), the stream handles may not
         // be automatically closed when the process exits, causing ReadLineAsync to block
         // indefinitely. Disposing the streams forces them to close.
-        _logger.LogDebug("Closing stdout/stderr streams for PID: {ProcessId}", _process.Id);
+        _logger.LogDebug("{FileName}({ProcessId}) closing stdout/stderr streams", FileName, _process.Id);
         _process.StandardOutput.Close();
         _process.StandardError.Close();
 
@@ -130,11 +109,11 @@ public async Task<int> WaitForExitAsync(CancellationToken cancellationToken)
             var completedTask = await Task.WhenAny(forwardersCompleted, forwarderTimeout);
             if (completedTask == forwarderTimeout)
             {
-                _logger.LogWarning("Stream forwarders for PID {ProcessId} did not complete within timeout after stream close. Continuing anyway.", _process.Id);
+                _logger.LogWarning("{FileName}({ProcessId}) stream forwarders did not complete within timeout after stream close", FileName, _process.Id);
             }
             else
             {
-                _logger.LogDebug("Pending forwarders for PID completed: {ProcessId}", _process.Id);
+                _logger.LogDebug("{FileName}({ProcessId}) forwarders completed", FileName, _process.Id);
             }
         }
 
@@ -153,23 +132,21 @@ public void Dispose()
         _process.Dispose();
     }
 
-    private async Task ForwardStreamToLoggerAsync(StreamReader reader, string identifier, Action<string>? lineCallback, bool suppressLogging)
+    private async Task ForwardStreamToLoggerAsync(StreamReader reader, string identifier, Action<string>? lineCallback)
     {
-        if (!suppressLogging)
-        {
-            _logger.LogDebug(
-                "Starting to forward stream with identifier '{Identifier}' on process '{ProcessId}' to logger",
-                identifier,
-                _process.Id
-                );
-        }
+        _logger.LogDebug(
+            "{FileName}({ProcessId}) starting to forward {Identifier} stream",
+            FileName,
+            _process.Id,
+            identifier
+            );
 
         try
         {
             string? line;
             while ((line = await reader.ReadLineAsync()) is not null)
             {
-                if (!suppressLogging)
+                if (_logger.IsEnabled(LogLevel.Trace))
                 {
                     _logger.LogTrace(
                         "{FileName}({ProcessId}) {Identifier}: {Line}",
@@ -185,7 +162,7 @@ private async Task ForwardStreamToLoggerAsync(StreamReader reader, string identi
         catch (ObjectDisposedException)
         {
             // Stream was closed externally (e.g., after process exit). This is expected.
-            _logger.LogDebug("Stream forwarder completed for {Identifier} - stream was closed", identifier);
+            _logger.LogDebug("{FileName}({ProcessId}) {Identifier} stream forwarder completed - stream was closed", FileName, _process.Id, identifier);
         }
     }
 }

src/Aspire.Cli/DotNet/ProcessExecutionFactory.cs

@@ -3,6 +3,7 @@
 
 using System.Diagnostics;
 using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
 
 namespace Aspire.Cli.DotNet;
 
@@ -14,18 +15,15 @@ internal sealed class ProcessExecutionFactory(
 {
     public IProcessExecution CreateExecution(string fileName, string[] args, IDictionary<string, string>? env, DirectoryInfo workingDirectory, ProcessInvocationOptions options)
     {
-        var suppressLogging = options.SuppressLogging;
+        var effectiveLogger = options.SuppressLogging ? (ILogger)NullLogger.Instance : logger;
 
-        if (!suppressLogging)
-        {
-            logger.LogDebug("Running {FullName} with args: {Args}", workingDirectory.FullName, string.Join(" ", args));
+        effectiveLogger.LogDebug("Running {FileName} in {WorkingDirectory} with args: {Args}", fileName, workingDirectory.FullName, string.Join(" ", args));
 
-            if (env is not null)
+        if (env is not null)
+        {
+            foreach (var envKvp in env)
             {
-                foreach (var envKvp in env)
-                {
-                    logger.LogDebug("Running {FullName} with env: {EnvKey}={EnvValue}", workingDirectory.FullName, envKvp.Key, envKvp.Value);
-                }
+                effectiveLogger.LogDebug("{FileName} env: {EnvKey}={EnvValue}", fileName, envKvp.Key, envKvp.Value);
             }
         }
 
@@ -53,6 +51,6 @@ public IProcessExecution CreateExecution(string fileName, string[] args, IDictio
         }
 
         var process = new Process { StartInfo = startInfo };
-        return new ProcessExecution(process, logger, options);
+        return new ProcessExecution(process, effectiveLogger, options);
     }
 }

src/Aspire.Cli/NuGet/BundleNuGetPackageCache.cs

@@ -211,6 +211,7 @@ private async Task<IEnumerable<NuGetPackage>> SearchPackagesInternalAsync(
 
     private IEnumerable<NuGetPackage> FilterPackages(IEnumerable<NuGetPackage> packages, Func<string, bool>? filter)
     {
+        var showDeprecatedPackages = _features.IsFeatureEnabled(KnownFeatures.ShowDeprecatedPackages, defaultValue: false);
         var effectiveFilter = (NuGetPackage p) =>
         {
             if (filter is not null)
@@ -221,7 +222,7 @@ private IEnumerable<NuGetPackage> FilterPackages(IEnumerable<NuGetPackage> packa
             var isOfficialPackage = IsOfficialOrCommunityToolkitPackage(p.Id);
 
             // Apply deprecated package filter unless the user wants to show deprecated packages
-            if (isOfficialPackage && !_features.IsFeatureEnabled(KnownFeatures.ShowDeprecatedPackages, defaultValue: false))
+            if (isOfficialPackage && !showDeprecatedPackages)
             {
                 return !DeprecatedPackages.IsDeprecated(p.Id);
             }

src/Aspire.Cli/NuGet/NuGetPackageCache.cs

@@ -130,6 +130,7 @@ public async Task<IEnumerable<NuGetPackage>> GetPackagesAsync(DirectoryInfo work
 
         // If no specific filter is specified we use the fallback filter which is useful in most circumstances
         // other that aspire update which really needs to see all the packages to work effectively.
+        var showDeprecatedPackages = features.IsFeatureEnabled(KnownFeatures.ShowDeprecatedPackages, defaultValue: false);
         var effectiveFilter = (NuGetPackage p) => 
         {
             if (filter is not null)
@@ -140,7 +141,7 @@ public async Task<IEnumerable<NuGetPackage>> GetPackagesAsync(DirectoryInfo work
             var isOfficialPackage = IsOfficialOrCommunityToolkitPackage(p.Id);
 
             // Apply deprecated package filter unless the user wants to show deprecated packages
-            if (isOfficialPackage && !features.IsFeatureEnabled(KnownFeatures.ShowDeprecatedPackages, defaultValue: false))
+            if (isOfficialPackage && !showDeprecatedPackages)
             {
                 return !DeprecatedPackages.IsDeprecated(p.Id);
             }

src/Aspire.Cli/Program.cs

@@ -718,6 +718,9 @@ public static async Task<int> Main(string[] args)
         var telemetry = app.Services.GetRequiredService<AspireCliTelemetry>();
         var telemetryManager = app.Services.GetRequiredService<TelemetryManager>();
 
+        // Log feature state at startup for diagnostics
+        app.Services.GetRequiredService<IFeatures>().LogFeatureState();
+
         // Display first run experience if this is the first time the CLI is run on this machine
         await DisplayFirstTimeUseNoticeIfNeededAsync(app.Services, args, cts.Token);
 

tests/Aspire.Cli.Tests/Commands/NewCommandTests.cs

@@ -944,7 +944,7 @@ public void NewCommandTemplateSubcommandsListTechnicalNamesForNonInteractiveFlow
         using var workspace = TemporaryWorkspace.Create(outputHelper);
         var services = CliTestHelper.CreateServiceCollection(workspace, outputHelper, options =>
         {
-            options.FeatureFlagsFactory = _ => new NewCommandTestFeatures(showAllTemplates: true);
+            options.FeatureFlagsFactory = _ => new TestFeatures().SetFeature(KnownFeatures.ShowAllTemplates, true);
         });
 
         var provider = services.BuildServiceProvider();
@@ -2131,18 +2131,6 @@ public Task<bool> ScaffoldAsync(ScaffoldContext context, CancellationToken cance
     }
 }
 
-internal sealed class NewCommandTestFeatures(bool showAllTemplates = false) : IFeatures
-{
-    public bool IsFeatureEnabled(string featureFlag, bool defaultValue)
-    {
-        return featureFlag switch
-        {
-            "showAllTemplates" => showAllTemplates,
-            _ => defaultValue
-        };
-    }
-}
-
 internal sealed class TestTypeScriptStarterProjectFactory(Func<DirectoryInfo, CancellationToken, Task<bool>> buildAndGenerateSdkAsync) : IAppHostProjectFactory
 {
     private readonly TestTypeScriptStarterProject _project = new(buildAndGenerateSdkAsync);

tests/Aspire.Cli.Tests/Commands/RunCommandTests.cs

@@ -5,7 +5,6 @@
 using System.Text.Json;
 using Aspire.Cli.Backchannel;
 using Aspire.Cli.Commands;
-using Aspire.Cli.Configuration;
 using Aspire.Cli.Diagnostics;
 using Aspire.Cli.DotNet;
 using Aspire.Cli.Projects;
@@ -1481,22 +1480,6 @@ public void RunCommand_ForwardsUnmatchedTokensToAppHost()
         Assert.Contains("value", result.UnmatchedTokens);
     }
 
-    private sealed class TestFeatures : IFeatures
-    {
-        private readonly Dictionary<string, bool> _features = new();
-
-        public TestFeatures SetFeature(string featureName, bool value)
-        {
-            _features[featureName] = value;
-            return this;
-        }
-
-        public bool IsFeatureEnabled(string featureName, bool defaultValue = false)
-        {
-            return _features.TryGetValue(featureName, out var value) ? value : defaultValue;
-        }
-    }
-
     [Fact]
     public async Task CaptureAppHostLogsAsync_WritesCategoryWithAppHostPrefix()
     {