diff --git a/src/Azure.DataApiBuilder.Mcp/Core/McpStdioServer.cs b/src/Azure.DataApiBuilder.Mcp/Core/McpStdioServer.cs index 8ec232981a..e8526df0aa 100644 --- a/src/Azure.DataApiBuilder.Mcp/Core/McpStdioServer.cs +++ b/src/Azure.DataApiBuilder.Mcp/Core/McpStdioServer.cs @@ -261,17 +261,26 @@ private void HandleListTools(JsonElement? id) /// The root JSON element of the incoming JSON-RPC request. /// /// Log level precedence (highest to lowest): - /// 1. CLI --LogLevel flag - cannot be overridden - /// 2. Config runtime.telemetry.log-level - cannot be overridden by MCP - /// 3. MCP logging/setLevel - only works if neither CLI nor Config explicitly set a level - /// 4. Default: None for MCP stdio mode (silent by default to keep stdout clean for JSON-RPC) - /// - /// If CLI or Config set the log level, this method accepts the request but silently ignores it. - /// The client won't get an error, but CLI/Config wins. - /// - /// When MCP sets a level other than "none", this also restores Console.Error to the real stderr - /// stream so that logs become visible (Console may have been redirected to null at startup). - /// It also enables MCP log notifications so logs are sent to the client via notifications/message. + /// 1. MCP logging/setLevel (Agent) - always wins, overrides CLI and Config. + /// 2. CLI --LogLevel flag. + /// 3. Config runtime.telemetry.log-level. + /// 4. Default: None for MCP stdio mode (silent by default to keep stdout clean for JSON-RPC), + /// Error in Production, Debug in Development. + /// + /// Per MCP spec the response is always success (empty result object) even when the input is + /// an unrecognized level — in that case no side effect runs and no state changes. + /// + /// Side effects performed in order on a valid request: + /// 1. Toggle based on the level + /// ("none" disables, anything else enables). This is done BEFORE + /// so the audit log line that + /// UpdateFromMcp emits is forwarded to the agent rather than dropped. + /// 2. Call , which updates the level and + /// flips so subsequent runtime-config + /// hot-reloads do not overwrite the agent's choice. + /// 3. Restore to the real stderr stream when logging is enabled, + /// in case startup redirected it to (default for + /// --mcp-stdio or --LogLevel none). /// private void HandleSetLogLevel(JsonElement? id, JsonElement root) { @@ -299,35 +308,44 @@ private void HandleSetLogLevel(JsonElement? id, JsonElement root) return; } - // Attempt to update the log level - // If CLI or Config overrode, this returns false but we still return success to the client - bool updated = logLevelController.UpdateFromMcp(level); - - // Determine if logging is enabled (level != "none") - // Note: Even if CLI/Config overrode the level, we still enable notifications - // when the client requests logging. They'll get logs at the overridden level. - bool isLoggingEnabled = !string.Equals(level, "none", StringComparison.OrdinalIgnoreCase); - - // Only restore stderr when this MCP call actually changed the effective level. - // If CLI/Config overrode (updated == false), stderr is already in the correct state: - // - CLI/Config level == "none": stderr was redirected to TextWriter.Null at startup - // and must stay that way; restoring it would re-introduce noisy output even - // though the operator explicitly asked for silence. - // - CLI/Config level != "none": stderr was never redirected, so restoring is a no-op. - if (updated && isLoggingEnabled) + // Validate the level BEFORE touching any side-effect (notification writer, stderr). + // "none" is the disable signal and is not a recognized MCP level; everything else + // must round-trip through McpLogLevelConverter so a typo can't silently turn the + // notification stream on while UpdateFromMcp ignores the bad value. + bool isDisableRequest = string.Equals(level, "none", StringComparison.OrdinalIgnoreCase); + bool isValidLevel = isDisableRequest || McpLogLevelConverter.TryConvertFromMcp(level, out _); + if (!isValidLevel) { - RestoreStderrIfNeeded(); + // Unknown level - return success per MCP spec but make no state changes. + WriteResult(id, new { }); + return; } - // Enable or disable MCP log notifications based on the requested level - // When CLI/Config overrode, notifications are still enabled - client asked for logs, - // they just get them at the CLI/Config level instead of the requested level. + bool isLoggingEnabled = !isDisableRequest; + + // Enable or disable MCP log notifications based on the requested level BEFORE updating + // the level. Doing it in this order means the agent-override Information line emitted + // by UpdateFromMcp is forwarded to the agent (otherwise it would be dropped because + // the notification writer was still disabled at the moment of emission). IMcpLogNotificationWriter? notificationWriter = _serviceProvider.GetService(); if (notificationWriter != null) { notificationWriter.IsEnabled = isLoggingEnabled; } + // Update the log level. Validation above guarantees this returns true for non-"none" + // values; for "none" it returns false (no LogLevel mapping) and we just keep + // notifications off without touching the current level. + bool updated = logLevelController.UpdateFromMcp(level); + + // Restore stderr if the agent successfully turned logging on. When `--mcp-stdio` (or + // `--LogLevel none`) was the startup default, stderr was redirected to TextWriter.Null; + // re-enable it now so subsequent logs flow. + if (updated && isLoggingEnabled) + { + RestoreStderrIfNeeded(); + } + // Always return success (empty result object) per MCP spec WriteResult(id, new { }); } diff --git a/src/Cli.Tests/CustomLoggerTests.cs b/src/Cli.Tests/CustomLoggerTests.cs index 449e9bd48e..8c08efc3e6 100644 --- a/src/Cli.Tests/CustomLoggerTests.cs +++ b/src/Cli.Tests/CustomLoggerTests.cs @@ -23,8 +23,8 @@ public class CustomLoggerTests public void ResetMcpStaticState() { Cli.Utils.IsMcpStdioMode = false; - Cli.Utils.IsLogLevelOverriddenByCli = false; - Cli.Utils.IsLogLevelOverriddenByConfig = false; + Cli.Utils.IsCliOverriding = false; + Cli.Utils.IsConfigOverriding = false; Cli.Utils.CliLogLevel = LogLevel.Information; Cli.Utils.ConfigLogLevel = LogLevel.Information; } @@ -114,7 +114,7 @@ public void Mcp_NoOverrides_SuppressesAllOutput() public void Mcp_CliOverride_WritesToStderrAndHonorsCliLevel() { Cli.Utils.IsMcpStdioMode = true; - Cli.Utils.IsLogLevelOverriddenByCli = true; + Cli.Utils.IsCliOverriding = true; Cli.Utils.CliLogLevel = LogLevel.Warning; (string stdout, string stderr) = CaptureConsole(() => @@ -140,7 +140,7 @@ public void Mcp_CliOverride_WritesToStderrAndHonorsCliLevel() public void Mcp_ConfigOverride_WritesToStderrAndHonorsConfigLevel() { Cli.Utils.IsMcpStdioMode = true; - Cli.Utils.IsLogLevelOverriddenByConfig = true; + Cli.Utils.IsConfigOverriding = true; Cli.Utils.ConfigLogLevel = LogLevel.Information; (string stdout, string stderr) = CaptureConsole(() => @@ -163,9 +163,9 @@ public void Mcp_ConfigOverride_WritesToStderrAndHonorsConfigLevel() public void Mcp_CliOverridePrecedesConfigOverride() { Cli.Utils.IsMcpStdioMode = true; - Cli.Utils.IsLogLevelOverriddenByCli = true; + Cli.Utils.IsCliOverriding = true; Cli.Utils.CliLogLevel = LogLevel.Warning; - Cli.Utils.IsLogLevelOverriddenByConfig = true; + Cli.Utils.IsConfigOverriding = true; Cli.Utils.ConfigLogLevel = LogLevel.Information; (_, string stderr) = CaptureConsole(() => diff --git a/src/Cli.Tests/EndToEndTests.cs b/src/Cli.Tests/EndToEndTests.cs index 9173386aea..e1644720b4 100644 --- a/src/Cli.Tests/EndToEndTests.cs +++ b/src/Cli.Tests/EndToEndTests.cs @@ -914,17 +914,17 @@ public async Task TestEngineStartUpWithLogLevelNone(string logLevelOption) Assert.IsTrue(string.IsNullOrEmpty(engineStdOut), $"Expected no output at LogLevel {logLevelOption}, but got: {engineStdOut}"); } - /// Validates that `dab start` correctly sets + /// Validates that `dab start` correctly sets /// based on whether the --LogLevel CLI flag is provided. /// - /// When the --LogLevel flag is provided, IsLogLevelOverriddenByCli should be true. - /// When the --LogLevel flag is omitted (log level comes from the config file), IsLogLevelOverriddenByCli should be false. + /// When the --LogLevel flag is provided, IsCliOverriding should be true. + /// When the --LogLevel flag is omitted (log level comes from the config file), IsCliOverriding should be false. /// /// The --LogLevel CLI flag value, or null to omit the flag. - /// Expected value of Startup.IsLogLevelOverriddenByCli. + /// Expected value of Startup.IsCliOverriding. [DataTestMethod] - [DataRow(null, false, DisplayName = "IsLogLevelOverriddenByCli is false")] - [DataRow(LogLevel.Error, true, DisplayName = "IsLogLevelOverriddenByCli is true")] + [DataRow(null, false, DisplayName = "IsCliOverriding is false")] + [DataRow(LogLevel.Error, true, DisplayName = "IsCliOverriding is true")] public async Task TestStartCommandResolvesLogLevelFromConfigOrFlag( LogLevel? cliLogLevel, bool expectedIsOverridden) @@ -987,7 +987,7 @@ public async Task TestStartCommandResolvesLogLevelFromConfigOrFlag( // Wait for the engine to finish loading the config. await Task.Delay(TimeSpan.FromSeconds(5)); - Assert.AreEqual(expectedIsOverridden, Startup.IsLogLevelOverriddenByCli); + Assert.AreEqual(expectedIsOverridden, Startup.IsCliOverriding); } /// diff --git a/src/Cli/ConfigGenerator.cs b/src/Cli/ConfigGenerator.cs index 76b6ae2cd7..0c5f776978 100644 --- a/src/Cli/ConfigGenerator.cs +++ b/src/Cli/ConfigGenerator.cs @@ -3002,7 +3002,7 @@ public static bool TryStartEngineWithOptions(StartOptions options, FileSystemRun // 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.IsConfigOverriding = false; Utils.ConfigLogLevel = LogLevel.Information; if (options.LogLevel is not null) @@ -3029,7 +3029,7 @@ public static bool TryStartEngineWithOptions(StartOptions options, FileSystemRun // when the user expressed intent via the config file rather than --LogLevel. if (deserializedRuntimeConfig.HasExplicitLogLevel()) { - Utils.IsLogLevelOverriddenByConfig = true; + Utils.IsConfigOverriding = true; Utils.ConfigLogLevel = minimumLogLevel; } } diff --git a/src/Cli/CustomLoggerProvider.cs b/src/Cli/CustomLoggerProvider.cs index e8c49e97ca..80a046a042 100644 --- a/src/Cli/CustomLoggerProvider.cs +++ b/src/Cli/CustomLoggerProvider.cs @@ -34,9 +34,9 @@ public class CustomConsoleLogger : ILogger public CustomConsoleLogger(LogLevel minimumLogLevel = LogLevel.Information) { _minimumLogLevel = Cli.Utils.IsMcpStdioMode - ? (Cli.Utils.IsLogLevelOverriddenByCli + ? (Cli.Utils.IsCliOverriding ? Cli.Utils.CliLogLevel - : Cli.Utils.IsLogLevelOverriddenByConfig + : Cli.Utils.IsConfigOverriding ? Cli.Utils.ConfigLogLevel : LogLevel.None) : minimumLogLevel; @@ -103,7 +103,7 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except // In that case, write to stderr to keep stdout clean for JSON-RPC. if (Cli.Utils.IsMcpStdioMode) { - if (!Cli.Utils.IsLogLevelOverriddenByCli && !Cli.Utils.IsLogLevelOverriddenByConfig) + if (!Cli.Utils.IsCliOverriding && !Cli.Utils.IsConfigOverriding) { return; // Suppress entirely when no explicit log level } diff --git a/src/Cli/Program.cs b/src/Cli/Program.cs index 4783c2292b..6eb89c60d8 100644 --- a/src/Cli/Program.cs +++ b/src/Cli/Program.cs @@ -62,7 +62,7 @@ private static void ParseEarlyFlags(string[] args) } else if (string.Equals(arg, "--LogLevel", StringComparison.OrdinalIgnoreCase) && i + 1 < args.Length) { - Utils.IsLogLevelOverriddenByCli = true; + Utils.IsCliOverriding = true; if (Enum.TryParse(args[i + 1], ignoreCase: true, out LogLevel cliLogLevel)) { Utils.CliLogLevel = cliLogLevel; diff --git a/src/Cli/Utils.cs b/src/Cli/Utils.cs index 817c73b64c..8f309407a8 100644 --- a/src/Cli/Utils.cs +++ b/src/Cli/Utils.cs @@ -29,26 +29,27 @@ public class Utils public static bool IsMcpStdioMode { get; set; } /// - /// When true, user explicitly set --LogLevel via CLI (even in MCP mode). + /// When true, the CLI is the source overriding the log level (i.e., --LogLevel was supplied). /// This allows logs to be written to stderr instead of being completely suppressed. /// - public static bool IsLogLevelOverriddenByCli { get; set; } + public static bool IsCliOverriding { get; set; } /// /// The log level specified via CLI --LogLevel flag. - /// Only valid when IsLogLevelOverriddenByCli is true. + /// Only valid when IsCliOverriding is true. /// public static LogLevel CliLogLevel { get; set; } = LogLevel.Information; /// - /// When true, the runtime config file explicitly set a log-level value. + /// When true, the runtime config is the source overriding the log level + /// (i.e., runtime.telemetry.log-level was explicitly set). /// 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; } + public static bool IsConfigOverriding { get; set; } /// /// The log level specified via runtime config file's log-level setting. - /// Only valid when IsLogLevelOverriddenByConfig is true. + /// Only valid when IsConfigOverriding is true. /// public static LogLevel ConfigLogLevel { get; set; } = LogLevel.Information; diff --git a/src/Core/Telemetry/ILogLevelController.cs b/src/Core/Telemetry/ILogLevelController.cs index f67424b155..8a8ff0d673 100644 --- a/src/Core/Telemetry/ILogLevelController.cs +++ b/src/Core/Telemetry/ILogLevelController.cs @@ -11,27 +11,36 @@ namespace Azure.DataApiBuilder.Core.Telemetry public interface ILogLevelController { /// - /// Gets a value indicating whether the log level was overridden by CLI arguments. - /// When true, MCP and config-based log level changes are ignored. + /// Gets a value indicating whether the CLI is the source overriding the log level + /// (i.e., --LogLevel was supplied). When true, runtime-config (hot-reload) + /// updates are ignored. /// - bool IsCliOverridden { get; } + bool IsCliOverriding { get; } /// - /// Gets a value indicating whether the log level was explicitly set in the config file. - /// When true along with IsCliOverridden being false, MCP log level changes are ignored. + /// Gets a value indicating whether the runtime config is the source overriding the log + /// level (i.e., runtime.telemetry.log-level was explicitly set). /// - bool IsConfigOverridden { get; } + bool IsConfigOverriding { get; } + + /// + /// Gets a value indicating whether the agent is the source overriding the log level via + /// an MCP logging/setLevel request. When true, runtime-config (hot-reload) updates + /// are ignored so the agent's choice remains in effect. + /// + bool IsAgentOverriding { get; } /// /// Updates the log level from an MCP logging/setLevel request. /// The MCP level string is mapped to the appropriate LogLevel. - /// Log level precedence (highest to lowest): - /// 1. CLI --LogLevel flag (IsCliOverridden = true) - /// 2. Config runtime.telemetry.log-level (IsConfigOverridden = true) - /// 3. MCP logging/setLevel (only works if neither CLI nor Config set a level) + /// Log-level precedence (highest to lowest): + /// 1. Agent (MCP logging/setLevel) — always wins. + /// 2. CLI --LogLevel flag. + /// 3. Config runtime.telemetry.log-level. + /// 4. Defaults. /// /// The MCP log level string (e.g., "debug", "info", "warning", "error"). - /// True if the level was changed; false if CLI or Config override prevented the change. + /// True if the level was changed; false if the input was an unrecognized level. bool UpdateFromMcp(string mcpLevel); } } diff --git a/src/Service.Tests/UnitTests/DynamicLogLevelProviderTests.cs b/src/Service.Tests/UnitTests/DynamicLogLevelProviderTests.cs index 779277c2b5..c74963778e 100644 --- a/src/Service.Tests/UnitTests/DynamicLogLevelProviderTests.cs +++ b/src/Service.Tests/UnitTests/DynamicLogLevelProviderTests.cs @@ -3,7 +3,9 @@ #nullable enable +using System.Collections.Generic; using System.Threading.Tasks; +using Azure.DataApiBuilder.Config.ObjectModel; using Azure.DataApiBuilder.Service.Telemetry; using Microsoft.Extensions.Logging; using Microsoft.VisualStudio.TestTools.UnitTesting; @@ -12,27 +14,28 @@ namespace Azure.DataApiBuilder.Service.Tests.UnitTests { /// /// Unit tests for the DynamicLogLevelProvider class. - /// Tests the MCP logging/setLevel support. + /// Locks the runtime log-level precedence: Agent (MCP) > CLI > Config > defaults. /// [TestClass] public class DynamicLogLevelProviderTests { [DataTestMethod] [DataRow(LogLevel.Error, false, false, "debug", true, LogLevel.Debug, DisplayName = "Valid level change succeeds")] - [DataRow(LogLevel.Error, true, false, "debug", false, LogLevel.Error, DisplayName = "CLI override blocks MCP change")] - [DataRow(LogLevel.Warning, false, true, "debug", false, LogLevel.Warning, DisplayName = "Config override blocks MCP change")] - [DataRow(LogLevel.Error, false, false, "invalid", false, LogLevel.Error, DisplayName = "Invalid level returns false")] + [DataRow(LogLevel.Error, true, false, "debug", true, LogLevel.Debug, DisplayName = "Agent overrides CLI")] + [DataRow(LogLevel.Warning, false, true, "debug", true, LogLevel.Debug, DisplayName = "Agent overrides Config")] + [DataRow(LogLevel.Error, true, true, "debug", true, LogLevel.Debug, DisplayName = "Agent overrides CLI + Config")] + [DataRow(LogLevel.Error, false, false, "invalid", false, LogLevel.Error, DisplayName = "Invalid level returns false and leaves level untouched")] public void UpdateFromMcp_ReturnsExpectedResult( LogLevel initialLevel, - bool isCliOverridden, - bool isConfigOverridden, + bool isCliOverriding, + bool isConfigOverriding, string mcpLevel, bool expectedResult, LogLevel expectedFinalLevel) { // Arrange DynamicLogLevelProvider provider = new(); - provider.SetInitialLogLevel(initialLevel, isCliOverridden, isConfigOverridden); + provider.SetInitialLogLevel(initialLevel, isCliOverriding, isConfigOverriding); // Act bool result = provider.UpdateFromMcp(mcpLevel); @@ -40,6 +43,10 @@ public void UpdateFromMcp_ReturnsExpectedResult( // Assert Assert.AreEqual(expectedResult, result); Assert.AreEqual(expectedFinalLevel, provider.CurrentLogLevel); + + // Successful agent updates must flip IsAgentOverriding so hot-reloads of Config + // don't overwrite the agent's choice. + Assert.AreEqual(expectedResult, provider.IsAgentOverriding); } [TestMethod] @@ -47,7 +54,7 @@ public void ShouldLog_ReturnsCorrectResult() { // Arrange DynamicLogLevelProvider provider = new(); - provider.SetInitialLogLevel(LogLevel.Warning, isCliOverridden: false); + provider.SetInitialLogLevel(LogLevel.Warning, isCliOverriding: false); // Assert - logs at or above Warning should pass Assert.IsTrue(provider.ShouldLog(LogLevel.Warning)); @@ -69,7 +76,7 @@ public void UpdateFromMcp_UnderConcurrency_StaysConsistent() { // Arrange DynamicLogLevelProvider provider = new(); - provider.SetInitialLogLevel(LogLevel.Information, isCliOverridden: false, isConfigOverridden: false); + provider.SetInitialLogLevel(LogLevel.Information, isCliOverriding: false, isConfigOverriding: false); const int iterations = 5_000; @@ -113,27 +120,142 @@ public void UpdateFromMcp_UnderConcurrency_StaysConsistent() } /// - /// CLI override is sticky: once the CLI flag pins the level, no number - /// of MCP logging/setLevel requests (even concurrent) may change + /// The agent always wins. Even when the CLI flag has pinned the level, every MCP + /// logging/setLevel call must succeed and update /// . Validates the - /// precedence guarantee under contention. + /// new precedence guarantee under contention. /// [TestMethod] - public void UpdateFromMcp_CliOverride_StaysStickyUnderConcurrency() + public void UpdateFromMcp_AgentAlwaysWins_UnderConcurrency() { // Arrange — CLI pins level to Warning. DynamicLogLevelProvider provider = new(); - provider.SetInitialLogLevel(LogLevel.Warning, isCliOverridden: true, isConfigOverridden: false); + provider.SetInitialLogLevel(LogLevel.Warning, isCliOverriding: true, isConfigOverriding: false); - // Act — flood with MCP setLevel requests trying to flip it. + // Act — flood with MCP setLevel requests; every one must succeed. Parallel.For(0, 2_000, _ => { bool changed = provider.UpdateFromMcp("debug"); - Assert.IsFalse(changed, "CLI override must block all MCP changes."); + Assert.IsTrue(changed, "Agent must override CLI and Config."); }); - // Assert — level never moved off Warning. + // Assert — final level is the agent-set Debug, and the agent flag is set. + Assert.AreEqual(LogLevel.Debug, provider.CurrentLogLevel); + Assert.IsTrue(provider.IsAgentOverriding); + // CLI flag is informational and stays as set by startup; precedence is enforced + // via IsAgentOverriding in UpdateFromRuntimeConfig. + Assert.IsTrue(provider.IsCliOverriding); + } + + /// + /// Hot-reloading the runtime config must not overwrite an agent-set level. After the + /// agent moves the level via , a + /// subsequent with a + /// different config-pinned level must be ignored. + /// + [TestMethod] + public void UpdateFromRuntimeConfig_RespectsAgentOverride() + { + // Arrange — start at Error (no CLI / Config override), agent then asks for Debug. + DynamicLogLevelProvider provider = new(); + provider.SetInitialLogLevel(LogLevel.Error, isCliOverriding: false, isConfigOverriding: false); + Assert.IsTrue(provider.UpdateFromMcp("debug")); + Assert.AreEqual(LogLevel.Debug, provider.CurrentLogLevel); + + // Build a hot-reloaded RuntimeConfig that explicitly pins log-level to Warning. + RuntimeConfig hotReloadedConfig = BuildRuntimeConfigWithLogLevel(LogLevel.Warning); + + // Act — the hot-reload guard must skip applying Warning because the agent already won. + provider.UpdateFromRuntimeConfig(hotReloadedConfig); + + // Assert — agent's Debug survives. + Assert.AreEqual(LogLevel.Debug, provider.CurrentLogLevel); + Assert.IsTrue(provider.IsAgentOverriding); + } + + /// + /// Hot-reloading the runtime config must not overwrite a CLI-set level. The CLI + /// --LogLevel flag is the operator's deliberate startup choice, so a + /// subsequent with a + /// different config-pinned level must be ignored. + /// + [TestMethod] + public void UpdateFromRuntimeConfig_RespectsCliOverride() + { + // Arrange — CLI pins level to Warning at startup; no agent override. + DynamicLogLevelProvider provider = new(); + provider.SetInitialLogLevel(LogLevel.Warning, isCliOverriding: true, isConfigOverriding: false); + + // Build a hot-reloaded RuntimeConfig that explicitly pins log-level to Information. + RuntimeConfig hotReloadedConfig = BuildRuntimeConfigWithLogLevel(LogLevel.Information); + + // Act — the hot-reload guard must skip applying Information because CLI already won. + provider.UpdateFromRuntimeConfig(hotReloadedConfig); + + // Assert — CLI's Warning survives, and IsConfigOverriding is not flipped because + // the hot-reload short-circuited before reading the config's log level. Assert.AreEqual(LogLevel.Warning, provider.CurrentLogLevel); + Assert.IsTrue(provider.IsCliOverriding); + Assert.IsFalse(provider.IsConfigOverriding); + } + + /// + /// Successive agent calls must each succeed and overwrite the previous agent-set level + /// — covering the full range from (most verbose) to + /// (most restrictive). This locks in the sticky + /// behavior of : once the agent + /// has taken control, every subsequent agent call wins, the flag stays set, and no + /// hot-reload of the runtime config can sneak in between calls to silently flip the + /// level back. The MCP spec doesn't define a "none" level, so the strictest valid + /// MCP level "emergency" (which maps to ) is + /// used as the high-end of the range. + /// + [TestMethod] + public void UpdateFromMcp_SuccessiveCalls_OverwriteAndKeepAgentOverriding() + { + // Arrange — start in the "no overrides" state. + DynamicLogLevelProvider provider = new(); + provider.SetInitialLogLevel(LogLevel.Information, isCliOverriding: false, isConfigOverriding: false); + + // Act + Assert — Debug → Critical (verbose to most-restrictive). + Assert.IsTrue(provider.UpdateFromMcp("debug")); + Assert.AreEqual(LogLevel.Debug, provider.CurrentLogLevel); + Assert.IsTrue(provider.IsAgentOverriding); + + Assert.IsTrue(provider.UpdateFromMcp("emergency")); + Assert.AreEqual(LogLevel.Critical, provider.CurrentLogLevel); + Assert.IsTrue(provider.IsAgentOverriding, "Agent override must remain sticky across successive agent calls."); + + // Act + Assert — Critical → Debug (reverse direction). + Assert.IsTrue(provider.UpdateFromMcp("debug")); + Assert.AreEqual(LogLevel.Debug, provider.CurrentLogLevel); + Assert.IsTrue(provider.IsAgentOverriding); + } + + /// + /// Builds a minimal whose + /// runtime.telemetry.log-level dictionary explicitly pins the default level. + /// Used by hot-reload tests; not intended to model a complete production config. + /// + private static RuntimeConfig BuildRuntimeConfigWithLogLevel(LogLevel level) + { + TelemetryOptions telemetry = new( + LoggerLevel: new Dictionary { ["default"] = level }); + + RuntimeOptions runtime = new( + Rest: null, + GraphQL: null, + Mcp: null, + Host: new HostOptions(Cors: null, Authentication: null, Mode: HostMode.Production), + Telemetry: telemetry); + + DataSource dataSource = new(DatabaseType.MSSQL, "Server=tcp:localhost,1433;", Options: null); + + return new RuntimeConfig( + Schema: null, + DataSource: dataSource, + Entities: new RuntimeEntities(new Dictionary()), + Runtime: runtime); } } } diff --git a/src/Service/Program.cs b/src/Service/Program.cs index 2963f5278b..e83dde30c7 100644 --- a/src/Service/Program.cs +++ b/src/Service/Program.cs @@ -98,9 +98,9 @@ public static bool StartEngine(string[] args, bool runMcpStdio, string? mcpRole) // Initialize log level EARLY, before building the host. // This ensures logging filters are effective during the entire host build process. // For MCP mode, we also read the config file early to check for log level override. - LogLevel initialLogLevel = GetLogLevelFromCommandLineArgsOrConfig(args, runMcpStdio, out bool isCliOverridden, out bool isConfigOverridden); + LogLevel initialLogLevel = GetLogLevelFromCommandLineArgsOrConfig(args, runMcpStdio, out bool isCliOverriding, out bool isConfigOverriding); - LogLevelProvider.SetInitialLogLevel(initialLogLevel, isCliOverridden, isConfigOverridden); + LogLevelProvider.SetInitialLogLevel(initialLogLevel, isCliOverriding, isConfigOverriding); // For MCP stdio mode, redirect Console.Out to keep stdout clean for JSON-RPC. // MCP SDK uses Console.OpenStandardOutput() which gets the real stdout, unaffected by this redirect. @@ -212,7 +212,7 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st // LogLevelProvider was already initialized in StartEngine before CreateHostBuilder. // Use the already-set values to avoid re-parsing args. Startup.MinimumLogLevel = LogLevelProvider.CurrentLogLevel; - Startup.IsLogLevelOverriddenByCli = LogLevelProvider.IsCliOverridden; + Startup.IsCliOverriding = LogLevelProvider.IsCliOverriding; ILoggerFactory loggerFactory = GetLoggerFactoryForLogLevel(Startup.MinimumLogLevel, stdio: runMcpStdio); ILogger startupLogger = loggerFactory.CreateLogger(); DisableHttpsRedirectionIfNeeded(args); @@ -229,13 +229,13 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st /// /// Array that may contain log level information. /// Whether running in MCP stdio mode. - /// Sets if log level is found in the args from CLI. - /// Sets if log level is found in the config file (MCP mode only). + /// Set to true if log level is supplied via CLI args. + /// Set to true if log level is supplied via the config file (MCP mode only). /// Appropriate log level. - private static LogLevel GetLogLevelFromCommandLineArgsOrConfig(string[] args, bool runMcpStdio, out bool isLogLevelOverridenByCli, out bool isConfigOverridden) + private static LogLevel GetLogLevelFromCommandLineArgsOrConfig(string[] args, bool runMcpStdio, out bool isCliOverriding, out bool isConfigOverriding) { LogLevel logLevel; - isConfigOverridden = false; + isConfigOverriding = false; // Check if --LogLevel was explicitly specified via CLI (case-insensitive parsing) int logLevelIndex = Array.FindIndex(args, a => string.Equals(a, "--LogLevel", StringComparison.OrdinalIgnoreCase)); @@ -245,12 +245,12 @@ private static LogLevel GetLogLevelFromCommandLineArgsOrConfig(string[] args, bo { // User explicitly set --LogLevel via CLI (highest priority) logLevel = cliLogLevel; - isLogLevelOverridenByCli = true; + isCliOverriding = true; } else if (runMcpStdio) { // MCP stdio mode without explicit --LogLevel: check config for log level (second priority) - isLogLevelOverridenByCli = false; + isCliOverriding = false; logLevel = LogLevel.None; // Default if config doesn't have log level // Find --config or --ConfigFileName argument, or use default dab-config.json @@ -264,7 +264,7 @@ private static LogLevel GetLogLevelFromCommandLineArgsOrConfig(string[] args, bo if (!string.IsNullOrWhiteSpace(configFilePath) && TryGetLogLevelFromConfig(configFilePath, out LogLevel configLogLevel)) { logLevel = configLogLevel; - isConfigOverridden = true; + isConfigOverriding = true; } } else @@ -274,7 +274,7 @@ private static LogLevel GetLogLevelFromCommandLineArgsOrConfig(string[] args, bo // adjust based on config: Debug for Development mode, Error for Production mode. // This initial value is used before config is loaded. logLevel = LogLevel.Error; - isLogLevelOverridenByCli = false; + isCliOverriding = false; } if (logLevel is > LogLevel.None or < LogLevel.Trace) diff --git a/src/Service/Startup.cs b/src/Service/Startup.cs index 1818697e45..14884f47a5 100644 --- a/src/Service/Startup.cs +++ b/src/Service/Startup.cs @@ -80,7 +80,7 @@ public class Startup(IConfiguration configuration, ILogger logger) { public static LogLevel MinimumLogLevel = LogLevel.Error; - public static bool IsLogLevelOverriddenByCli; + public static bool IsCliOverriding; public static AzureLogAnalyticsCustomLogCollector CustomLogCollector = new(); public static ApplicationInsightsOptions AppInsightsOptions = new(); @@ -750,6 +750,17 @@ public void Configure(IApplicationBuilder app, IWebHostEnvironment env, RuntimeC bool isRuntimeReady = false; RuntimeConfig? runtimeConfig = null; + // Wire a logger on the DynamicLogLevelProvider as soon as ILoggerFactory is available + // — ahead of any config-load branch — so an early MCP logging/setLevel call (which can + // arrive before runtime config in the late-configured path) still surfaces its audit + // log line through the standard logging pipeline. + DynamicLogLevelProvider? logLevelProviderForAudit = app.ApplicationServices.GetService(); + ILoggerFactory? earlyLoggerFactory = app.ApplicationServices.GetService(); + if (logLevelProviderForAudit is not null && earlyLoggerFactory is not null) + { + logLevelProviderForAudit.Logger = earlyLoggerFactory.CreateLogger(); + } + try { if (runtimeConfigProvider.TryGetConfig(out runtimeConfig)) @@ -961,7 +972,7 @@ private static void EvictGraphQLSchema(IRequestExecutorManager requestExecutorRe /// public static ILoggerFactory CreateLoggerFactoryForHostedAndNonHostedScenario(IServiceProvider serviceProvider, LogLevelInitializer logLevelInitializer) { - if (!IsLogLevelOverriddenByCli) + if (!IsCliOverriding) { // If the log level is not overridden by command line arguments specified through CLI, // attempt to get the runtime config to determine the loglevel based on host.mode. diff --git a/src/Service/Telemetry/DynamicLogLevelProvider.cs b/src/Service/Telemetry/DynamicLogLevelProvider.cs index 8e29086f52..b405caa7f0 100644 --- a/src/Service/Telemetry/DynamicLogLevelProvider.cs +++ b/src/Service/Telemetry/DynamicLogLevelProvider.cs @@ -6,40 +6,69 @@ namespace Azure.DataApiBuilder.Service.Telemetry { /// /// Provides dynamic log level control with support for CLI override, runtime config, and MCP. + /// Precedence (highest to lowest): Agent (MCP) > CLI > Config > defaults. /// public class DynamicLogLevelProvider : ILogLevelController { + /// + /// Guards mutations of and the override flags so + /// concurrent and + /// calls cannot interleave and break the Agent > CLI > Config precedence. + /// + private readonly object _stateLock = new(); + public LogLevel CurrentLogLevel { get; private set; } - public bool IsCliOverridden { get; private set; } + public bool IsCliOverriding { get; private set; } + + public bool IsConfigOverriding { get; private set; } + + public bool IsAgentOverriding { get; private set; } - public bool IsConfigOverridden { get; private set; } + /// + /// Optional logger used to emit an Information line when the agent successfully overrides + /// the log level. Wired by host startup once the logging pipeline is available; safe to + /// leave unset (e.g. in unit tests). + /// + public ILogger? Logger { get; set; } /// - /// Sets the initial log level, which can be passed from the CLI or the Config file, - /// if not specified, it defaults to None if flag --mcp-stdio, to Error if in Production mode or Debug if in Development mode. - /// Also sets whether the log level was overridden by the CLI, which will prevent updates from runtime config changes. + /// Sets the initial log level from CLI args or the config file. When not specified the level + /// defaults to None for --mcp-stdio, Error in Production, or Debug in Development. + /// The CLI/Config flags drive runtime-config hot-reload behavior; they no longer block + /// agent (MCP) overrides — see . /// /// The initial log level to set. - /// Indicates whether the log level was overridden by the CLI. - /// Indicates whether the log level was overridden by the runtime config. - public void SetInitialLogLevel(LogLevel logLevel = LogLevel.Error, bool isCliOverridden = false, bool isConfigOverridden = false) + /// Indicates whether the CLI is overriding the log level. + /// Indicates whether the runtime config is overriding the log level. + public void SetInitialLogLevel(LogLevel logLevel = LogLevel.Error, bool isCliOverriding = false, bool isConfigOverriding = false) { - CurrentLogLevel = logLevel; - IsCliOverridden = isCliOverridden; - IsConfigOverridden = isConfigOverridden; + lock (_stateLock) + { + CurrentLogLevel = logLevel; + IsCliOverriding = isCliOverriding; + IsConfigOverriding = isConfigOverriding; + } } /// - /// Updates the current log level based on the runtime configuration, unless it was overridden by the CLI. + /// Updates the current log level from a runtime-config (hot-reload) change. + /// Skipped when the CLI or the agent has already overridden, so neither is overwritten. /// /// The runtime configuration to use for updating the log level. /// Optional logger filter to apply when determining the log level. public void UpdateFromRuntimeConfig(RuntimeConfig runtimeConfig, string? loggerFilter = null) { - // Only update if CLI didn't override - if (!IsCliOverridden) + lock (_stateLock) { + // Agent override and CLI override both win over a hot-reloaded Config value. + // The check + assignment must be inside the lock so a concurrent UpdateFromMcp + // cannot slip in between the guard and the write. + if (IsAgentOverriding || IsCliOverriding) + { + return; + } + if (loggerFilter is null) { loggerFilter = string.Empty; @@ -47,47 +76,42 @@ public void UpdateFromRuntimeConfig(RuntimeConfig runtimeConfig, string? loggerF CurrentLogLevel = runtimeConfig.GetConfiguredLogLevel(loggerFilter); - // Track if config explicitly set a non-null log level value. - // This ensures MCP logging/setLevel is only blocked when config - // actually pins a log level, not just when the dictionary exists. - IsConfigOverridden = runtimeConfig.HasExplicitLogLevel(); + // Track if config explicitly set a non-null log level value, so callers can + // distinguish a config-pinned level from defaults. + IsConfigOverriding = runtimeConfig.HasExplicitLogLevel(); } } - /// Updates the log level from an MCP logging/setLevel request. - /// Precedence (highest to lowest): - /// 1. CLI --LogLevel flag (IsCliOverridden = true) - /// 2. Config runtime.telemetry.log-level (IsConfigOverridden = true) - /// 3. MCP logging/setLevel - /// - /// If CLI or Config overrode, this method accepts the request silently but does not change the level. + /// + /// Updates the log level from an MCP logging/setLevel request. + /// The agent always wins over CLI and Config; only an unrecognized level is rejected. /// /// The MCP log level string (e.g., "debug", "info", "warning", "error"). - /// True if the level was changed; false if CLI/Config override prevented the change or level was invalid. + /// True if the level was changed; false only if the input was an unrecognized level. public bool UpdateFromMcp(string mcpLevel) { - // If CLI overrode the log level, accept the request but don't change anything. - // This prevents MCP clients from getting errors, but CLI wins. - if (IsCliOverridden) + if (!McpLogLevelConverter.TryConvertFromMcp(mcpLevel, out LogLevel logLevel)) { + // Unknown level - don't change, but don't fail the MCP call either. return false; } - // If Config explicitly set the log level, accept the request but don't change anything. - // Config has second precedence after CLI. - if (IsConfigOverridden) - { - return false; - } - - if (McpLogLevelConverter.TryConvertFromMcp(mcpLevel, out LogLevel logLevel)) + lock (_stateLock) { CurrentLogLevel = logLevel; - return true; + IsAgentOverriding = true; } - // Unknown level - don't change, but don't fail either - return false; + // Surface the override so operators can see the agent moved the level. + // Logged outside the lock so logger sinks can't deadlock with state mutations. + // Emitted at Information and subject to the operator's configured filter, like + // any other log line — the JSON-RPC request/response itself is the protocol-level + // audit, so there's no need to bypass the filter here. + Logger?.LogInformation( + "Log level updated to {LogLevel} via MCP logging/setLevel (agent override).", + logLevel); + + return true; } ///