diff --git a/src/Cli.Tests/CustomLoggerTests.cs b/src/Cli.Tests/CustomLoggerTests.cs index 951cbc6a77..449e9bd48e 100644 --- a/src/Cli.Tests/CustomLoggerTests.cs +++ b/src/Cli.Tests/CustomLoggerTests.cs @@ -4,78 +4,179 @@ namespace Cli.Tests; /// -/// Tests for CustomLoggerProvider and CustomConsoleLogger, verifying -/// that log level labels use ASP.NET Core abbreviated format. +/// Tests for covering both the standard CLI +/// path (writes to stdout/stderr with abbreviated labels) and the MCP stdio path +/// (suppressed by default, opt-in via either CLI --LogLevel or the +/// runtime config's log-level, always routed to stderr to keep the +/// JSON-RPC channel on stdout uncorrupted). /// [TestClass] public class CustomLoggerTests { /// - /// Validates that each enabled log level produces the correct abbreviated label - /// matching ASP.NET Core's default console formatter convention. - /// Trace and Debug are below the logger's minimum level and produce no output. + /// The CustomConsoleLogger reads several static flags from . + /// Reset them around every test so cases cannot leak into each other and so the + /// rest of the test suite continues to see the default (non-MCP) behavior. /// - [DataTestMethod] - [DataRow(LogLevel.Information, "info:")] - [DataRow(LogLevel.Warning, "warn:")] - public void LogOutput_UsesAbbreviatedLogLevelLabels(LogLevel logLevel, string expectedPrefix) + [TestInitialize] + [TestCleanup] + public void ResetMcpStaticState() { - CustomLoggerProvider provider = new(); - ILogger logger = provider.CreateLogger("TestCategory"); + Cli.Utils.IsMcpStdioMode = false; + Cli.Utils.IsLogLevelOverriddenByCli = false; + Cli.Utils.IsLogLevelOverriddenByConfig = false; + Cli.Utils.CliLogLevel = LogLevel.Information; + Cli.Utils.ConfigLogLevel = LogLevel.Information; + } + /// + /// Redirects Console.Out and Console.Error around + /// and returns whatever was written to each. Restores the original writers + /// on exit. + /// + private static (string Stdout, string Stderr) CaptureConsole(Action action) + { TextWriter originalOut = Console.Out; + TextWriter originalError = Console.Error; + StringWriter stdout = new(); + StringWriter stderr = new(); try { - StringWriter writer = new(); - Console.SetOut(writer); - - logger.Log(logLevel, "test message"); - - string output = writer.ToString(); - Assert.IsTrue( - output.StartsWith(expectedPrefix), - $"Expected output to start with '{expectedPrefix}' but got: '{output}'"); - Assert.IsTrue( - output.Contains("test message"), - $"Expected output to contain 'test message' but got: '{output}'"); + Console.SetOut(stdout); + Console.SetError(stderr); + action(); } finally { Console.SetOut(originalOut); + Console.SetError(originalError); } + + return (stdout.ToString(), stderr.ToString()); } + private static ILogger NewLogger() => + new CustomLoggerProvider().CreateLogger("TestCategory"); + /// - /// Validates that each log level error and above produces the correct abbreviated - /// label matching ASP.NET Core's default console formatter convention. - /// Error and Critical logs should go to the stderr stream. + /// Standard (non-MCP) path: each log level produces the correct abbreviated + /// label matching ASP.NET Core's default console formatter and is routed to + /// stdout for Information/Warning and stderr for Error/Critical. /// [DataTestMethod] - [DataRow(LogLevel.Error, "fail:")] - [DataRow(LogLevel.Critical, "crit:")] - public void LogError_UsesAbbreviatedLogLevelLabels(LogLevel logLevel, string expectedPrefix) + [DataRow(LogLevel.Information, "info:", false)] + [DataRow(LogLevel.Warning, "warn:", false)] + [DataRow(LogLevel.Error, "fail:", true)] + [DataRow(LogLevel.Critical, "crit:", true)] + public void LogOutput_UsesAbbreviatedLogLevelLabels(LogLevel logLevel, string expectedPrefix, bool expectStderr) { - CustomLoggerProvider provider = new(); - ILogger logger = provider.CreateLogger("TestCategory"); + const string Message = "test message"; - TextWriter originalError = Console.Error; - try + (string stdout, string stderr) = CaptureConsole(() => NewLogger().Log(logLevel, Message)); + + string actual = expectStderr ? stderr : stdout; + string other = expectStderr ? stdout : stderr; + + Assert.IsTrue(actual.StartsWith(expectedPrefix), + $"Expected output to start with '{expectedPrefix}' but got: '{actual}'"); + StringAssert.Contains(actual, Message); + Assert.AreEqual(string.Empty, other, + $"Did not expect output on the other stream but got: '{other}'"); + } + + /// + /// MCP stdio mode with no overrides (neither CLI --LogLevel nor + /// config log-level): all output must be suppressed so the JSON-RPC + /// channel stays clean. + /// + [TestMethod] + public void Mcp_NoOverrides_SuppressesAllOutput() + { + Cli.Utils.IsMcpStdioMode = true; + + (string stdout, string stderr) = CaptureConsole(() => { - StringWriter writer = new(); - Console.SetError(writer); - logger.Log(logLevel, "test message"); - - string output = writer.ToString(); - Assert.IsTrue( - output.StartsWith(expectedPrefix), - $"Expected output to start with '{expectedPrefix}' but got: '{output}'"); - Assert.IsTrue( - output.Contains("test message"), - $"Expected output to contain 'test message' but got: '{output}'"); - } - finally + ILogger logger = NewLogger(); + logger.Log(LogLevel.Information, "info should not appear"); + logger.Log(LogLevel.Error, "error should not appear"); + }); + + Assert.AreEqual(string.Empty, stdout, "MCP mode without overrides must not write to stdout."); + Assert.AreEqual(string.Empty, stderr, "MCP mode without overrides must not write to stderr."); + } + + /// + /// MCP stdio mode with a CLI-supplied --LogLevel: logs must always + /// go to stderr (never stdout) and the level threshold from + /// must be honored. + /// + [TestMethod] + public void Mcp_CliOverride_WritesToStderrAndHonorsCliLevel() + { + Cli.Utils.IsMcpStdioMode = true; + Cli.Utils.IsLogLevelOverriddenByCli = true; + Cli.Utils.CliLogLevel = LogLevel.Warning; + + (string stdout, string stderr) = CaptureConsole(() => { - Console.SetError(originalError); - } + ILogger logger = NewLogger(); + logger.Log(LogLevel.Information, "filtered info"); // below threshold + logger.Log(LogLevel.Warning, "visible warn"); // at threshold + logger.Log(LogLevel.Error, "visible error"); // above threshold + }); + + Assert.AreEqual(string.Empty, stdout, "MCP mode must never write to stdout."); + Assert.IsFalse(stderr.Contains("filtered info"), $"Below-threshold log should be filtered. Got: '{stderr}'"); + StringAssert.Contains(stderr, "warn: visible warn"); + StringAssert.Contains(stderr, "fail: visible error"); + } + + /// + /// Bug fix: MCP stdio mode where only the runtime config (no CLI flag) + /// supplied the log level. Previously suppressed; must now emit to stderr + /// using . + /// + [TestMethod] + public void Mcp_ConfigOverride_WritesToStderrAndHonorsConfigLevel() + { + Cli.Utils.IsMcpStdioMode = true; + Cli.Utils.IsLogLevelOverriddenByConfig = true; + Cli.Utils.ConfigLogLevel = LogLevel.Information; + + (string stdout, string stderr) = CaptureConsole(() => + { + ILogger logger = NewLogger(); + logger.Log(LogLevel.Debug, "filtered debug"); // below threshold + logger.Log(LogLevel.Information, "visible info"); // at threshold + }); + + Assert.AreEqual(string.Empty, stdout, "MCP mode must never write to stdout."); + Assert.IsFalse(stderr.Contains("filtered debug"), $"Below-threshold log should be filtered. Got: '{stderr}'"); + StringAssert.Contains(stderr, "info: visible info"); + } + + /// + /// Precedence: when both CLI and config supply a log level, the CLI value + /// wins (CLI > Config > None). + /// + [TestMethod] + public void Mcp_CliOverridePrecedesConfigOverride() + { + Cli.Utils.IsMcpStdioMode = true; + Cli.Utils.IsLogLevelOverriddenByCli = true; + Cli.Utils.CliLogLevel = LogLevel.Warning; + Cli.Utils.IsLogLevelOverriddenByConfig = true; + Cli.Utils.ConfigLogLevel = LogLevel.Information; + + (_, string stderr) = CaptureConsole(() => + { + ILogger logger = NewLogger(); + logger.Log(LogLevel.Information, "filtered by CLI Warning"); + logger.Log(LogLevel.Warning, "passes CLI Warning"); + }); + + Assert.IsFalse(stderr.Contains("filtered by CLI Warning"), + $"CLI level should override config and filter Information. Got: '{stderr}'"); + StringAssert.Contains(stderr, "warn: passes CLI Warning"); } } diff --git a/src/Cli/ConfigGenerator.cs b/src/Cli/ConfigGenerator.cs index 8a416e26ca..7e4416db2b 100644 --- a/src/Cli/ConfigGenerator.cs +++ b/src/Cli/ConfigGenerator.cs @@ -2752,6 +2752,12 @@ public static bool TryStartEngineWithOptions(StartOptions options, FileSystemRun /// - MCP stdio mode: Service defaults to None for clean stdout output /// - Non-MCP mode: Service defaults to Debug (Development) or Error (Production) based on config LogLevel minimumLogLevel; + + // Reset the config-based override flag so stale state from a prior call + // (these are static) cannot leak into the current run. + Utils.IsLogLevelOverriddenByConfig = false; + Utils.ConfigLogLevel = LogLevel.Information; + if (options.LogLevel is not null) { if (options.LogLevel is < LogLevel.Trace or > LogLevel.None) @@ -2770,6 +2776,15 @@ public static bool TryStartEngineWithOptions(StartOptions options, FileSystemRun else { minimumLogLevel = deserializedRuntimeConfig.GetConfiguredLogLevel(); + + // Track whether config explicitly set a log level. In MCP stdio mode this + // allows CLI logs to be emitted to stderr (instead of being suppressed) + // when the user expressed intent via the config file rather than --LogLevel. + if (deserializedRuntimeConfig.HasExplicitLogLevel()) + { + Utils.IsLogLevelOverriddenByConfig = true; + Utils.ConfigLogLevel = minimumLogLevel; + } } options.CliBuffer.BufferLog(LogLevel.Information, $"Setting minimum LogLevel: {minimumLogLevel}."); diff --git a/src/Cli/CustomLoggerProvider.cs b/src/Cli/CustomLoggerProvider.cs index b99f2597cd..64b8dbf580 100644 --- a/src/Cli/CustomLoggerProvider.cs +++ b/src/Cli/CustomLoggerProvider.cs @@ -28,14 +28,18 @@ public class CustomConsoleLogger : ILogger private readonly LogLevel _minimumLogLevel; // Minimum LogLevel for CLI output. - // For MCP mode: use CLI's --LogLevel if specified, otherwise suppress all. - // For non-MCP mode: always use Information. + // For MCP mode: prefer CLI's --LogLevel, fall back to config's log-level, otherwise suppress all. + // For non-MCP mode: always use the level passed to the constructor. // Note: --LogLevel is meant for the ENGINE's log level, not CLI's output. public CustomConsoleLogger(LogLevel minimumLogLevel = LogLevel.Information) { _minimumLogLevel = Cli.Utils.IsMcpStdioMode - ? (Cli.Utils.IsLogLevelOverriddenByCli ? Cli.Utils.CliLogLevel : LogLevel.None) - : minimumLogLevel; + ? (Cli.Utils.IsLogLevelOverriddenByCli + ? Cli.Utils.CliLogLevel + : Cli.Utils.IsLogLevelOverriddenByConfig + ? Cli.Utils.ConfigLogLevel + : LogLevel.None) + : minimumLogLevel; } // Color values based on LogLevel @@ -89,16 +93,17 @@ public CustomConsoleLogger(LogLevel minimumLogLevel = LogLevel.Information) /// /// Creates Log message by setting console message color based on LogLevel. /// In MCP stdio mode: - /// - If user explicitly set --LogLevel: write to stderr (colored output) + /// - If user explicitly set --LogLevel (CLI) or log-level (config): write to stderr (colored output) /// - Otherwise: suppress entirely to keep stdout clean for JSON-RPC protocol. /// public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) { - // In MCP stdio mode, only output logs if user explicitly requested a log level. + // In MCP stdio mode, only output logs if user explicitly requested a log level + // via either the CLI --LogLevel flag or the runtime config file's log-level. // In that case, write to stderr to keep stdout clean for JSON-RPC. if (Cli.Utils.IsMcpStdioMode) { - if (!Cli.Utils.IsLogLevelOverriddenByCli) + if (!Cli.Utils.IsLogLevelOverriddenByCli && !Cli.Utils.IsLogLevelOverriddenByConfig) { return; // Suppress entirely when no explicit log level } @@ -116,7 +121,15 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except // In MCP stdio mode, stdout is reserved for JSON-RPC protocol messages. // Logs must go to stderr to avoid corrupting the MCP communication channel. - Console.Error.WriteLine($"{mcpAbbreviation}: {formatter(state, exception)}"); + // Apply colors so the abbreviation matches the visual style of engine logs. + ConsoleColor mcpOriginalForeGroundColor = Console.ForegroundColor; + ConsoleColor mcpOriginalBackGroundColor = Console.BackgroundColor; + Console.ForegroundColor = _logLevelToForeGroundConsoleColorMap.GetValueOrDefault(logLevel, ConsoleColor.White); + Console.BackgroundColor = _logLevelToBackGroundConsoleColorMap.GetValueOrDefault(logLevel, ConsoleColor.Black); + Console.Error.Write($"{mcpAbbreviation}:"); + Console.ForegroundColor = mcpOriginalForeGroundColor; + Console.BackgroundColor = mcpOriginalBackGroundColor; + Console.Error.WriteLine($" {formatter(state, exception)}"); return; } diff --git a/src/Cli/Utils.cs b/src/Cli/Utils.cs index 1f9ef6d282..817c73b64c 100644 --- a/src/Cli/Utils.cs +++ b/src/Cli/Utils.cs @@ -40,6 +40,18 @@ public class Utils /// public static LogLevel CliLogLevel { get; set; } = LogLevel.Information; + /// + /// When true, the runtime config file explicitly set a log-level value. + /// This allows CLI logs to be written to stderr in MCP mode even when no --LogLevel flag was provided. + /// + public static bool IsLogLevelOverriddenByConfig { get; set; } + + /// + /// The log level specified via runtime config file's log-level setting. + /// Only valid when IsLogLevelOverriddenByConfig is true. + /// + public static LogLevel ConfigLogLevel { get; set; } = LogLevel.Information; + #pragma warning disable CS8618 // Non-nullable field must contain a non-null value when exiting constructor. Consider declaring as nullable. private static ILogger _logger; #pragma warning restore CS8618