From 70d79ce4fba3440ccafe2f553b9b43f39910f5bb Mon Sep 17 00:00:00 2001 From: RubenCerna2079 <32799214+RubenCerna2079@users.noreply.github.com> Date: Mon, 4 May 2026 20:24:43 -0700 Subject: [PATCH 1/3] Fix logs still appearing even when LogLevel is set to `none` bug (#3318) - Closes issue #3262 The logger for the Startup class is not initialized properly, since this logger is special due to the nature of the Startup class it needs to be continuously updated as DAB initializes. This causes two problems: - Some logs appear even when LogLevel is set to some value that would impede those logs to appear. - Some logs don't appear at all, even when LogLevel is set to a value that should allow them to be logged. - Closes issue #3256 & #3255 The CLI logger still outputs some logs even when the LogLevel is set to `none`. It is expected that if the LogLevel set is `none` or some other level that shouldn't output the `information` level, the logs will not appear. Important Note: These changes currently only allow us to change the LogLevel from the CLI with the `default` namespace in the config file. An task was created to solve this issue: https://github.com/Azure/data-api-builder/issues/3451 In order to solve issue #3262: - We removed the LogBuffer from the services inside of `Startup.cs`, this is necessary since we wanted each class to have its own LogBuffer so that we are able to tell from which logger the logs are being outputted. - Then, we also correctly initialized the `Startup` logger by changing the method that it was using to initialize the logger, it now uses `CreateLoggerFactoryForHostedAndNonHostedScenario` which checks if there are any LogLevel namespaces from the config file that can be applicable for the specific logger. It is important to note that there are multiple places where the logs are flushed in order to cover for the cases in which an exception is found and causes DAB to end abruptly, and when we there is an IsLateConfigured scenario. - We also changed the logger for the LogBuffer in all the missing places where it creates logs before the logger is able to properly initialize to add those logs to the LogBuffer and only flush them after the loggers are initialized. In order to solve issue #3256 & #3255: - We changed the CLI so that we add all the logs go to a single global LogBuffer that is created inside the `StartOptions.cs` until it is able to deserialize the RuntimeConfig and find which level to set the `LogLevel` in order to flush all the logs. - This is something that we only want to happen when we use the `dab start` command, which is why we only make this change in the `StartOptions.cs` file, on the function `TryStartEngineWithOptions` inside of `ConfigGenerator.cs`, and a few functions from `Utils.cs` and `ConfigMerger.cs` that are used inside the `TryStartEngine` function. - [ ] Integration Tests - [x] Unit Tests - dab start --LogLevel none - dab start --LogLevel error --------- Co-authored-by: Aniruddh Munde --- src/Cli.Tests/CustomLoggerTests.cs | 36 ++- src/Cli.Tests/EndToEndTests.cs | 79 +++++- src/Cli.Tests/EnvironmentTests.cs | 6 +- src/Cli.Tests/UtilsTests.cs | 7 +- src/Cli.Tests/ValidateConfigTests.cs | 4 +- src/Cli/Commands/StartOptions.cs | 12 +- src/Cli/ConfigGenerator.cs | 68 ++++- src/Cli/ConfigMerger.cs | 34 ++- src/Cli/CustomLoggerProvider.cs | 30 ++- src/Cli/Exporter.cs | 2 +- src/Cli/Utils.cs | 30 ++- src/Config/FileSystemRuntimeConfigLoader.cs | 17 +- .../{StartupLogBuffer.cs => LogBuffer.cs} | 16 +- src/Config/RuntimeConfigLoader.cs | 2 + .../Configuration/ConfigurationTests.cs | 4 +- .../Configuration/RuntimeConfigLoaderTests.cs | 20 +- src/Service.Tests/TestHelper.cs | 33 +++ .../UnitTests/SqlMetadataProviderUnitTests.cs | 8 +- src/Service/Program.cs | 2 + src/Service/Startup.cs | 246 +++++++++++------- .../Telemetry/DynamicLogLevelProvider.cs | 29 ++- 21 files changed, 511 insertions(+), 174 deletions(-) rename src/Config/{StartupLogBuffer.cs => LogBuffer.cs} (68%) diff --git a/src/Cli.Tests/CustomLoggerTests.cs b/src/Cli.Tests/CustomLoggerTests.cs index c7989f4f8a..951cbc6a77 100644 --- a/src/Cli.Tests/CustomLoggerTests.cs +++ b/src/Cli.Tests/CustomLoggerTests.cs @@ -18,8 +18,6 @@ public class CustomLoggerTests [DataTestMethod] [DataRow(LogLevel.Information, "info:")] [DataRow(LogLevel.Warning, "warn:")] - [DataRow(LogLevel.Error, "fail:")] - [DataRow(LogLevel.Critical, "crit:")] public void LogOutput_UsesAbbreviatedLogLevelLabels(LogLevel logLevel, string expectedPrefix) { CustomLoggerProvider provider = new(); @@ -46,4 +44,38 @@ public void LogOutput_UsesAbbreviatedLogLevelLabels(LogLevel logLevel, string ex Console.SetOut(originalOut); } } + + /// + /// 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. + /// + [DataTestMethod] + [DataRow(LogLevel.Error, "fail:")] + [DataRow(LogLevel.Critical, "crit:")] + public void LogError_UsesAbbreviatedLogLevelLabels(LogLevel logLevel, string expectedPrefix) + { + CustomLoggerProvider provider = new(); + ILogger logger = provider.CreateLogger("TestCategory"); + + TextWriter originalError = Console.Error; + try + { + 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 + { + Console.SetError(originalError); + } + } } diff --git a/src/Cli.Tests/EndToEndTests.cs b/src/Cli.Tests/EndToEndTests.cs index 0f0622516d..c1e4f214f5 100644 --- a/src/Cli.Tests/EndToEndTests.cs +++ b/src/Cli.Tests/EndToEndTests.cs @@ -48,6 +48,9 @@ public void TestCleanup() _fileSystem = null; _runtimeConfigLoader = null; _cliLogger = null; + + // Reset the LoggerFactoryForCli to avoid impacting other tests. + Utils.LoggerFactoryForCli = Utils.GetLoggerFactoryForCli(); } /// @@ -822,24 +825,12 @@ public Task TestUpdatingStoredProcedureWithRestMethods() [DataRow("--LogLevel 0", DisplayName = "LogLevel 0 from command line.")] [DataRow("--LogLevel 1", DisplayName = "LogLevel 1 from command line.")] [DataRow("--LogLevel 2", DisplayName = "LogLevel 2 from command line.")] - [DataRow("--LogLevel 3", DisplayName = "LogLevel 3 from command line.")] - [DataRow("--LogLevel 4", DisplayName = "LogLevel 4 from command line.")] - [DataRow("--LogLevel 5", DisplayName = "LogLevel 5 from command line.")] - [DataRow("--LogLevel 6", DisplayName = "LogLevel 6 from command line.")] [DataRow("--LogLevel Trace", DisplayName = "LogLevel Trace from command line.")] [DataRow("--LogLevel Debug", DisplayName = "LogLevel Debug from command line.")] [DataRow("--LogLevel Information", DisplayName = "LogLevel Information from command line.")] - [DataRow("--LogLevel Warning", DisplayName = "LogLevel Warning from command line.")] - [DataRow("--LogLevel Error", DisplayName = "LogLevel Error from command line.")] - [DataRow("--LogLevel Critical", DisplayName = "LogLevel Critical from command line.")] - [DataRow("--LogLevel None", DisplayName = "LogLevel None from command line.")] [DataRow("--LogLevel tRace", DisplayName = "Case sensitivity: LogLevel Trace from command line.")] [DataRow("--LogLevel DebUG", DisplayName = "Case sensitivity: LogLevel Debug from command line.")] [DataRow("--LogLevel information", DisplayName = "Case sensitivity: LogLevel Information from command line.")] - [DataRow("--LogLevel waRNing", DisplayName = "Case sensitivity: LogLevel Warning from command line.")] - [DataRow("--LogLevel eRROR", DisplayName = "Case sensitivity: LogLevel Error from command line.")] - [DataRow("--LogLevel CrItIcal", DisplayName = "Case sensitivity: LogLevel Critical from command line.")] - [DataRow("--LogLevel NONE", DisplayName = "Case sensitivity: LogLevel None from command line.")] public void TestEngineStartUpWithVerboseAndLogLevelOptions(string logLevelOption) { _fileSystem!.File.WriteAllText(TEST_RUNTIME_CONFIG_FILE, INITIAL_CONFIG); @@ -859,6 +850,70 @@ public void TestEngineStartUpWithVerboseAndLogLevelOptions(string logLevelOption } /// + /// Test to validate that the engine starts successfully when --LogLevel is set to Warning + /// or above. At these levels, CLI phase messages (logged at Information) are suppressed, + /// so no stdout output with message 'info' is expected during the CLI phase. + /// + /// Log level options + [DataTestMethod] + [DataRow("3", DisplayName = "LogLevel 3 from command line.")] + [DataRow("4", DisplayName = "LogLevel 4 from command line.")] + [DataRow("5", DisplayName = "LogLevel 5 from command line.")] + [DataRow("Warning", DisplayName = "LogLevel Warning from command line.")] + [DataRow("Error", DisplayName = "LogLevel Error from command line.")] + [DataRow("Critical", DisplayName = "LogLevel Critical from command line.")] + [DataRow("waRNing", DisplayName = "Case sensitivity: LogLevel Warning from command line.")] + [DataRow("eRROR", DisplayName = "Case sensitivity: LogLevel Error from command line.")] + [DataRow("CrItIcal", DisplayName = "Case sensitivity: LogLevel Critical from command line.")] + public async Task TestEngineStartUpWithHighLogLevelOptions(string logLevelOption) + { + StringLogger logger = new(); + StringWriter consoleOutput = new(); + Console.SetOut(consoleOutput); + + string[] args = { "start", "--config", TEST_RUNTIME_CONFIG_FILE, "--LogLevel", logLevelOption }; + _fileSystem!.File.WriteAllText(TEST_RUNTIME_CONFIG_FILE, INITIAL_CONFIG); + + // Run Program.Execute on a background task because StartEngine blocks until the host shuts down. + Task engineTask = Task.Run(() => Program.Execute(args, logger, _fileSystem!, _runtimeConfigLoader!)); + + // Wait for the CLI to set up the proper LogLevel. + await Task.Delay(TimeSpan.FromSeconds(5)); + + string engineStdOut = consoleOutput.ToString(); + Assert.IsNotNull(engineStdOut); + Assert.IsFalse(engineStdOut.Contains("info"), $"Expected no 'info' outputs at LogLevel {logLevelOption}, but got: {engineStdOut}"); + } + + /// + /// Test to validate that the engine starts successfully when --LogLevel is set to None. + /// At these levels, CLI phase messages (logged at Information) are suppressed, + /// so no stdout output is expected during the CLI phase. + /// + /// Log level options + [DataTestMethod] + [DataRow("6", DisplayName = "LogLevel 6 from command line.")] + [DataRow("None", DisplayName = "LogLevel None from command line.")] + [DataRow("NONE", DisplayName = "Case sensitivity: LogLevel None from command line.")] + public async Task TestEngineStartUpWithLogLevelNone(string logLevelOption) + { + StringLogger logger = new(); + StringWriter consoleOutput = new(); + Console.SetOut(consoleOutput); + + string[] args = { "start", "--config", TEST_RUNTIME_CONFIG_FILE, "--LogLevel", logLevelOption }; + _fileSystem!.File.WriteAllText(TEST_RUNTIME_CONFIG_FILE, INITIAL_CONFIG); + + // Run Program.Execute on a background task because StartEngine blocks until the host shuts down. + Task engineTask = Task.Run(() => Program.Execute(args, logger, _fileSystem!, _runtimeConfigLoader!)); + + // Wait for the CLI to set up the proper LogLevel. + await Task.Delay(TimeSpan.FromSeconds(5)); + + string engineStdOut = consoleOutput.ToString(); + Assert.IsTrue(string.IsNullOrEmpty(engineStdOut), $"Expected no output at LogLevel {logLevelOption}, but got: {engineStdOut}"); + } + /// Validates that `dab start` correctly sets /// based on whether the --LogLevel CLI flag is provided. /// diff --git a/src/Cli.Tests/EnvironmentTests.cs b/src/Cli.Tests/EnvironmentTests.cs index d7b359783a..1b17dacf03 100644 --- a/src/Cli.Tests/EnvironmentTests.cs +++ b/src/Cli.Tests/EnvironmentTests.cs @@ -162,9 +162,9 @@ public async Task FailureToStartEngineWhenEnvVarNamedWrong() $"-c {TEST_RUNTIME_CONFIG_FILE}" ); - string? output = await process.StandardError.ReadLineAsync(); - Assert.AreEqual("Deserialization of the configuration file failed during a post-processing step.", output); - output = await process.StandardError.ReadToEndAsync(); + string? output = await process.StandardError.ReadToEndAsync(); + Assert.IsNotNull(output); + // Clean error message on stderr with no stack trace. StringAssert.Contains(output, "A valid Connection String should be provided.", StringComparison.Ordinal); process.Kill(); } diff --git a/src/Cli.Tests/UtilsTests.cs b/src/Cli.Tests/UtilsTests.cs index 3b7a108867..28241e2c85 100644 --- a/src/Cli.Tests/UtilsTests.cs +++ b/src/Cli.Tests/UtilsTests.cs @@ -253,9 +253,11 @@ public void TestMergeConfig() FileSystemRuntimeConfigLoader loader = new(fileSystem); + LogBuffer logBuffer = new(); + Environment.SetEnvironmentVariable(RUNTIME_ENVIRONMENT_VAR_NAME, "Test"); - Assert.IsTrue(ConfigMerger.TryMergeConfigsIfAvailable(fileSystem, loader, new StringLogger(), out string? mergedConfig), "Failed to merge config files"); + Assert.IsTrue(ConfigMerger.TryMergeConfigsIfAvailable(fileSystem, loader, new StringLogger(), logBuffer, out string? mergedConfig), "Failed to merge config files"); Assert.AreEqual(mergedConfig, "dab-config.Test.merged.json"); Assert.IsTrue(fileSystem.File.Exists(mergedConfig)); Assert.IsTrue(JToken.DeepEquals(JObject.Parse(MERGED_CONFIG), JObject.Parse(fileSystem.File.ReadAllText(mergedConfig)))); @@ -306,10 +308,11 @@ public void TestMergeConfigAvailability( } FileSystemRuntimeConfigLoader loader = new(fileSystem); + LogBuffer logBuffer = new(); Assert.AreEqual( expectedIsMergedConfigAvailable, - ConfigMerger.TryMergeConfigsIfAvailable(fileSystem, loader, new StringLogger(), out string? mergedConfigFile), + ConfigMerger.TryMergeConfigsIfAvailable(fileSystem, loader, new StringLogger(), logBuffer, out string? mergedConfigFile), "Availability of merge config should match"); Assert.AreEqual(expectedMergedConfigFileName, mergedConfigFile, "Merge config file name should match expected"); diff --git a/src/Cli.Tests/ValidateConfigTests.cs b/src/Cli.Tests/ValidateConfigTests.cs index e40a32e291..3849335b0e 100644 --- a/src/Cli.Tests/ValidateConfigTests.cs +++ b/src/Cli.Tests/ValidateConfigTests.cs @@ -70,8 +70,9 @@ public void TestErrorHandlingForRelationshipValidationWithNonWorkingConnectionSt ((MockFileSystem)_fileSystem!).AddFile(TEST_RUNTIME_CONFIG_FILE, COMPLETE_CONFIG_WITH_RELATIONSHIPS_NON_WORKING_CONN_STRING); ValidateOptions validateOptions = new(TEST_RUNTIME_CONFIG_FILE); StringWriter writer = new(); + // Capture console output to get error messaging. - Console.SetOut(writer); + Console.SetError(writer); // Act ConfigGenerator.IsConfigValid(validateOptions, _runtimeConfigLoader!, _fileSystem!); @@ -264,6 +265,7 @@ public void ValidateConfigSchemaWhereConfigReferencesEnvironmentVariables() ValidateOptions validateOptions = new(TEST_RUNTIME_CONFIG_FILE); // Act + Utils.LoggerFactoryForCli = Utils.GetLoggerFactoryForCli(); ConfigGenerator.IsConfigValid(validateOptions, _runtimeConfigLoader!, _fileSystem!); // Assert diff --git a/src/Cli/Commands/StartOptions.cs b/src/Cli/Commands/StartOptions.cs index 050f410801..5857786790 100644 --- a/src/Cli/Commands/StartOptions.cs +++ b/src/Cli/Commands/StartOptions.cs @@ -19,6 +19,8 @@ public class StartOptions : Options { private const string LOGLEVEL_HELPTEXT = "Specifies logging level as provided value. For possible values, see: https://go.microsoft.com/fwlink/?linkid=2263106"; + public LogBuffer CliBuffer { get; } + public StartOptions(bool verbose, LogLevel? logLevel, bool isHttpsRedirectionDisabled, bool mcpStdio, string? mcpRole, string config) : base(config) { @@ -27,6 +29,7 @@ public StartOptions(bool verbose, LogLevel? logLevel, bool isHttpsRedirectionDis IsHttpsRedirectionDisabled = isHttpsRedirectionDisabled; McpStdio = mcpStdio; McpRole = mcpRole; + CliBuffer = new LogBuffer(); } // SetName defines mutually exclusive sets, ie: can not have @@ -48,11 +51,18 @@ public StartOptions(bool verbose, LogLevel? logLevel, bool isHttpsRedirectionDis public int Handler(ILogger logger, FileSystemRuntimeConfigLoader loader, IFileSystem fileSystem) { - logger.LogInformation("{productName} {version}", PRODUCT_NAME, ProductInfo.GetProductVersion()); + CliBuffer.BufferLog(Microsoft.Extensions.Logging.LogLevel.Information, $"{PRODUCT_NAME} {ProductInfo.GetProductVersion()}"); bool isSuccess = ConfigGenerator.TryStartEngineWithOptions(this, loader, fileSystem); if (!isSuccess) { + // Update loggers and flush buffers to ensure that all the logs are printed if the TryStartEngineWithOptions fails. + logger = Utils.LoggerFactoryForCli.CreateLogger(); + loader.SetLogger(Utils.LoggerFactoryForCli.CreateLogger()); + + CliBuffer.FlushToLogger(logger); + loader.FlushLogBuffer(); + logger.LogError("Failed to start the engine{mode}.", McpStdio ? " in MCP stdio mode" : string.Empty); } diff --git a/src/Cli/ConfigGenerator.cs b/src/Cli/ConfigGenerator.cs index a1c212ed8c..a9e4b90962 100644 --- a/src/Cli/ConfigGenerator.cs +++ b/src/Cli/ConfigGenerator.cs @@ -2684,7 +2684,7 @@ public static bool VerifyCanUpdateRelationship(RuntimeConfig runtimeConfig, stri /// public static bool TryStartEngineWithOptions(StartOptions options, FileSystemRuntimeConfigLoader loader, IFileSystem fileSystem) { - if (!TryGetConfigForRuntimeEngine(options.Config, loader, fileSystem, out string runtimeConfigFile)) + if (!TryGetConfigForRuntimeEngine(options.Config, loader, fileSystem, out string runtimeConfigFile, options.CliBuffer)) { return false; } @@ -2693,17 +2693,24 @@ public static bool TryStartEngineWithOptions(StartOptions options, FileSystemRun // Replaces all the environment variables while deserializing when starting DAB. if (!loader.TryLoadKnownConfig(out RuntimeConfig? deserializedRuntimeConfig, replaceEnvVar: true)) { - _logger.LogError("Failed to parse the config file: {runtimeConfigFile}.", runtimeConfigFile); + // When IsParseErrorEmitted is true, TryLoadConfig already emitted the + // detailed error to Console.Error. Only log a generic message to avoid + // duplicate output (stderr + stdout). + if (!loader.IsParseErrorEmitted) + { + options.CliBuffer.BufferLog(LogLevel.Error, $"Failed to parse the config file: {runtimeConfigFile}."); + } + return false; } else { - _logger.LogInformation("Loaded config file: {runtimeConfigFile}", runtimeConfigFile); + options.CliBuffer.BufferLog(LogLevel.Information, $"Loaded config file: {runtimeConfigFile}"); } if (string.IsNullOrWhiteSpace(deserializedRuntimeConfig.DataSource.ConnectionString)) { - _logger.LogError("Invalid connection-string provided in the config."); + options.CliBuffer.BufferLog(LogLevel.Error, "Invalid connection-string provided in the config."); return false; } @@ -2722,9 +2729,8 @@ public static bool TryStartEngineWithOptions(StartOptions options, FileSystemRun { if (options.LogLevel is < LogLevel.Trace or > LogLevel.None) { - _logger.LogError( - "LogLevel's valid range is 0 to 6, your value: {logLevel}, see: https://learn.microsoft.com/dotnet/api/microsoft.extensions.logging.loglevel", - options.LogLevel); + options.CliBuffer.BufferLog(LogLevel.Error, + $"LogLevel's valid range is 0 to 6, your value: {options.LogLevel}, see: https://learn.microsoft.com/dotnet/api/microsoft.extensions.logging.loglevel"); return false; } @@ -2733,8 +2739,28 @@ public static bool TryStartEngineWithOptions(StartOptions options, FileSystemRun // This allows MCP logging/setLevel to work when no CLI override is present. args.Add("--LogLevel"); args.Add(minimumLogLevel.ToString()); - _logger.LogInformation("Setting minimum LogLevel: {minimumLogLevel}.", minimumLogLevel); } + else + { + minimumLogLevel = deserializedRuntimeConfig.GetConfiguredLogLevel(); + } + + options.CliBuffer.BufferLog(LogLevel.Information, $"Setting minimum LogLevel: {minimumLogLevel}."); + + Utils.LoggerFactoryForCli = Utils.GetLoggerFactoryForCli(minimumLogLevel); + + // Update logger for StartOptions and + // flush all current logs saved in LogBuffer + ILogger programLogger = Utils.LoggerFactoryForCli.CreateLogger(); + options.CliBuffer.FlushToLogger(programLogger); + + // Update logger for Utils + ILogger utilsLogger = Utils.LoggerFactoryForCli.CreateLogger(); + Utils.SetCliUtilsLogger(utilsLogger); + + // Update logger for ConfigGenerator + ILogger configGeneratorLogger = Utils.LoggerFactoryForCli.CreateLogger(); + SetLoggerForCliConfigGenerator(configGeneratorLogger); // This will add args to disable automatic redirects to https if specified by user if (options.IsHttpsRedirectionDisabled) @@ -2823,16 +2849,32 @@ public static bool TryGetConfigForRuntimeEngine( string? configToBeUsed, FileSystemRuntimeConfigLoader loader, IFileSystem fileSystem, - out string runtimeConfigFile) + out string runtimeConfigFile, + LogBuffer? logBuffer = null) { - if (string.IsNullOrEmpty(configToBeUsed) && ConfigMerger.TryMergeConfigsIfAvailable(fileSystem, loader, _logger, out configToBeUsed)) + if (string.IsNullOrEmpty(configToBeUsed) && ConfigMerger.TryMergeConfigsIfAvailable(fileSystem, loader, _logger, logBuffer, out configToBeUsed)) { - _logger.LogInformation("Using merged config file based on environment: {configToBeUsed}.", configToBeUsed); + if (logBuffer is null) + { + _logger.LogInformation("Using merged config file based on environment: {configToBeUsed}.", configToBeUsed); + } + else + { + logBuffer.BufferLog(LogLevel.Information, $"Using merged config file based on environment: {configToBeUsed}."); + } } - if (!TryGetConfigFileBasedOnCliPrecedence(loader, configToBeUsed, out runtimeConfigFile)) + if (!TryGetConfigFileBasedOnCliPrecedence(loader, configToBeUsed, out runtimeConfigFile, logBuffer)) { - _logger.LogError("Config not provided and default config file doesn't exist."); + if (logBuffer is null) + { + _logger.LogError("Config not provided and default config file doesn't exist."); + } + else + { + logBuffer.BufferLog(LogLevel.Error, "Config not provided and default config file doesn't exist."); + } + return false; } diff --git a/src/Cli/ConfigMerger.cs b/src/Cli/ConfigMerger.cs index 55a9ae6ad2..496292df5a 100644 --- a/src/Cli/ConfigMerger.cs +++ b/src/Cli/ConfigMerger.cs @@ -15,7 +15,7 @@ public static class ConfigMerger /// and create a merged file called dab-config.{DAB_ENVIRONMENT}.merged.json /// /// Returns the name of the merged Config if successful. - public static bool TryMergeConfigsIfAvailable(IFileSystem fileSystem, FileSystemRuntimeConfigLoader loader, ILogger logger, out string? mergedConfigFile) + public static bool TryMergeConfigsIfAvailable(IFileSystem fileSystem, FileSystemRuntimeConfigLoader loader, ILogger logger, LogBuffer? cliBuffer, out string? mergedConfigFile) { string? environmentValue = Environment.GetEnvironmentVariable(FileSystemRuntimeConfigLoader.RUNTIME_ENVIRONMENT_VAR_NAME); mergedConfigFile = null; @@ -32,16 +32,42 @@ public static bool TryMergeConfigsIfAvailable(IFileSystem fileSystem, FileSystem string overrideConfigJson = fileSystem.File.ReadAllText(environmentBasedConfigFile); string currentDir = fileSystem.Directory.GetCurrentDirectory(); - logger.LogInformation("Merging {baseFilePath} and {envFilePath}", Path.Combine(currentDir, baseConfigFile), Path.Combine(currentDir, environmentBasedConfigFile)); + + if (cliBuffer is null) + { + logger.LogInformation("Merging {baseFilePath} and {envFilePath}", Path.Combine(currentDir, baseConfigFile), Path.Combine(currentDir, environmentBasedConfigFile)); + } + else + { + cliBuffer.BufferLog(LogLevel.Information, $"Merging {Path.Combine(currentDir, baseConfigFile)} and {Path.Combine(currentDir, environmentBasedConfigFile)}"); + } + string mergedConfigJson = MergeJsonProvider.Merge(baseConfigJson, overrideConfigJson); mergedConfigFile = FileSystemRuntimeConfigLoader.GetMergedFileNameForEnvironment(FileSystemRuntimeConfigLoader.CONFIGFILE_NAME, environmentValue); fileSystem.File.WriteAllText(mergedConfigFile, mergedConfigJson); - logger.LogInformation("Generated merged config file: {mergedFile}", Path.Combine(currentDir, mergedConfigFile)); + + if (cliBuffer is null) + { + logger.LogInformation("Generated merged config file: {mergedFile}", Path.Combine(currentDir, mergedConfigFile)); + } + else + { + cliBuffer.BufferLog(LogLevel.Information, $"Generated merged config file: {Path.Combine(currentDir, mergedConfigFile)}"); + } + return true; } catch (Exception ex) { - logger.LogError(ex, "Failed to merge the config files."); + if (cliBuffer is null) + { + logger.LogError(ex, "Failed to merge the config files."); + } + else + { + cliBuffer.BufferLog(LogLevel.Error, "Failed to merge the config files.", ex); + } + mergedConfigFile = null; return false; } diff --git a/src/Cli/CustomLoggerProvider.cs b/src/Cli/CustomLoggerProvider.cs index e489dd8df3..b99f2597cd 100644 --- a/src/Cli/CustomLoggerProvider.cs +++ b/src/Cli/CustomLoggerProvider.cs @@ -8,23 +8,35 @@ /// public class CustomLoggerProvider : ILoggerProvider { + private readonly LogLevel _minimumLogLevel; + + public CustomLoggerProvider(LogLevel minimumLogLevel = LogLevel.Information) + { + _minimumLogLevel = minimumLogLevel; + } + public void Dispose() { } /// public ILogger CreateLogger(string categoryName) { - return new CustomConsoleLogger(); + return new CustomConsoleLogger(_minimumLogLevel); } 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. // Note: --LogLevel is meant for the ENGINE's log level, not CLI's output. - private static LogLevel MinimumLogLevel => Cli.Utils.IsMcpStdioMode + public CustomConsoleLogger(LogLevel minimumLogLevel = LogLevel.Information) + { + _minimumLogLevel = Cli.Utils.IsMcpStdioMode ? (Cli.Utils.IsLogLevelOverriddenByCli ? Cli.Utils.CliLogLevel : LogLevel.None) - : LogLevel.Information; + : minimumLogLevel; + } // Color values based on LogLevel // LogLevel Foreground Background @@ -92,7 +104,7 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except } // User wants logs in MCP mode - write to stderr - if (!IsEnabled(logLevel) || logLevel < MinimumLogLevel) + if (!IsEnabled(logLevel) || logLevel < _minimumLogLevel) { return; } @@ -108,7 +120,7 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except return; } - if (!IsEnabled(logLevel) || logLevel < MinimumLogLevel) + if (!IsEnabled(logLevel) || logLevel < _minimumLogLevel) { return; } @@ -118,21 +130,23 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except return; } + TextWriter writer = logLevel >= LogLevel.Error ? Console.Error : Console.Out; ConsoleColor originalForeGroundColor = Console.ForegroundColor; ConsoleColor originalBackGroundColor = Console.BackgroundColor; Console.ForegroundColor = _logLevelToForeGroundConsoleColorMap.GetValueOrDefault(logLevel, ConsoleColor.White); Console.BackgroundColor = _logLevelToBackGroundConsoleColorMap.GetValueOrDefault(logLevel, ConsoleColor.Black); - Console.Write($"{abbreviation}:"); + writer.Write($"{abbreviation}:"); Console.ForegroundColor = originalForeGroundColor; Console.BackgroundColor = originalBackGroundColor; - Console.WriteLine($" {formatter(state, exception)}"); + writer.WriteLine($" {formatter(state, exception)}"); } /// public bool IsEnabled(LogLevel logLevel) { - return true; + return logLevel != LogLevel.None && logLevel >= _minimumLogLevel; } + public IDisposable? BeginScope(TState state) where TState : notnull { throw new NotImplementedException(); diff --git a/src/Cli/Exporter.cs b/src/Cli/Exporter.cs index e694317cd4..1a209e9e27 100644 --- a/src/Cli/Exporter.cs +++ b/src/Cli/Exporter.cs @@ -37,7 +37,7 @@ internal class Exporter public static bool Export(ExportOptions options, ILogger logger, FileSystemRuntimeConfigLoader loader, IFileSystem fileSystem) { // Attempt to locate the runtime configuration file based on CLI options - if (!TryGetConfigFileBasedOnCliPrecedence(loader, options.Config, out string runtimeConfigFile)) + if (!TryGetConfigFileBasedOnCliPrecedence(loader: loader, userProvidedConfigFile: options.Config, runtimeConfigFile: out string runtimeConfigFile)) { logger.LogError("Failed to find the config file provided, check your options and try again."); return false; diff --git a/src/Cli/Utils.cs b/src/Cli/Utils.cs index 14096eb969..f9cd45572e 100644 --- a/src/Cli/Utils.cs +++ b/src/Cli/Utils.cs @@ -326,19 +326,37 @@ public static bool TryGetRoleAndOperationFromPermission(IEnumerable perm public static bool TryGetConfigFileBasedOnCliPrecedence( FileSystemRuntimeConfigLoader loader, string? userProvidedConfigFile, - out string runtimeConfigFile) + out string runtimeConfigFile, + LogBuffer? logBuffer = null) { if (!string.IsNullOrEmpty(userProvidedConfigFile)) { /// The existence of user provided config file is not checked here. - _logger.LogInformation("User provided config file: {userProvidedConfigFile}", userProvidedConfigFile); + if (logBuffer is null) + { + _logger.LogInformation("User provided config file: {userProvidedConfigFile}", userProvidedConfigFile); + } + else + { + logBuffer.BufferLog(LogLevel.Information, $"User provided config file: {userProvidedConfigFile}"); + } + runtimeConfigFile = userProvidedConfigFile; return true; } else { - _logger.LogInformation("Config not provided. Trying to get default config based on DAB_ENVIRONMENT..."); - _logger.LogInformation("Environment variable DAB_ENVIRONMENT is {environment}", Environment.GetEnvironmentVariable("DAB_ENVIRONMENT")); + if (logBuffer is null) + { + _logger.LogInformation("Config not provided. Trying to get default config based on DAB_ENVIRONMENT..."); + _logger.LogInformation("Environment variable DAB_ENVIRONMENT is {environment}", Environment.GetEnvironmentVariable("DAB_ENVIRONMENT")); + } + else + { + logBuffer.BufferLog(LogLevel.Information, "Config not provided. Trying to get default config based on DAB_ENVIRONMENT..."); + logBuffer.BufferLog(LogLevel.Information, $"Environment variable DAB_ENVIRONMENT is {Environment.GetEnvironmentVariable("DAB_ENVIRONMENT")}"); + } + runtimeConfigFile = loader.GetFileNameForEnvironment(null, considerOverrides: false); } @@ -993,10 +1011,10 @@ public static bool IsEntityProvided(string? entity, ILogger cliLogger, string co /// /// Returns ILoggerFactory with CLI custom logger provider. /// - public static ILoggerFactory GetLoggerFactoryForCli() + public static ILoggerFactory GetLoggerFactoryForCli(LogLevel minimumLogLevel = LogLevel.Information) { ILoggerFactory loggerFactory = new LoggerFactory(); - loggerFactory.AddProvider(new CustomLoggerProvider()); + loggerFactory.AddProvider(new CustomLoggerProvider(minimumLogLevel)); return loggerFactory; } } diff --git a/src/Config/FileSystemRuntimeConfigLoader.cs b/src/Config/FileSystemRuntimeConfigLoader.cs index 7b888a82bf..7262454914 100644 --- a/src/Config/FileSystemRuntimeConfigLoader.cs +++ b/src/Config/FileSystemRuntimeConfigLoader.cs @@ -65,8 +65,6 @@ public class FileSystemRuntimeConfigLoader : RuntimeConfigLoader, IDisposable /// private ILogger? _logger; - private StartupLogBuffer? _logBuffer; - public const string CONFIGFILE_NAME = "dab-config"; public const string CONFIG_EXTENSION = ".json"; public const string ENVIRONMENT_PREFIX = "DAB_"; @@ -91,8 +89,7 @@ public FileSystemRuntimeConfigLoader( string baseConfigFilePath = DEFAULT_CONFIG_FILE_NAME, string? connectionString = null, bool isCliLoader = false, - ILogger? logger = null, - StartupLogBuffer? logBuffer = null) + ILogger? logger = null) : base(handler, connectionString) { _fileSystem = fileSystem; @@ -100,7 +97,6 @@ public FileSystemRuntimeConfigLoader( ConfigFilePath = GetFinalConfigFilePath(); _isCliLoader = isCliLoader; _logger = logger; - _logBuffer = logBuffer; } /// @@ -303,6 +299,12 @@ public bool TryLoadConfig( RuntimeConfig = LastValidRuntimeConfig; } + if (parseError is not null) + { + SendLogToBufferOrLogger(LogLevel.Error, parseError); + IsParseErrorEmitted = true; + } + config = null; return false; } @@ -542,10 +544,11 @@ public void SetLogger(ILogger logger) /// /// Flush all logs from the buffer after the log level is set from the RuntimeConfig. + /// Logger needs to be present, or else the logs will be lost. /// public void FlushLogBuffer() { - _logBuffer?.FlushToLogger(_logger); + _logBuffer.FlushToLogger(_logger!); } /// @@ -558,7 +561,7 @@ private void SendLogToBufferOrLogger(LogLevel logLevel, string message) { if (_logger is null) { - _logBuffer?.BufferLog(logLevel, message); + _logBuffer.BufferLog(logLevel, message); } else { diff --git a/src/Config/StartupLogBuffer.cs b/src/Config/LogBuffer.cs similarity index 68% rename from src/Config/StartupLogBuffer.cs rename to src/Config/LogBuffer.cs index 4a01ee7617..f014f012ed 100644 --- a/src/Config/StartupLogBuffer.cs +++ b/src/Config/LogBuffer.cs @@ -10,12 +10,12 @@ namespace Azure.DataApiBuilder.Config /// A general-purpose log buffer that stores log entries before the final log level is determined. /// Can be used across different components during startup to capture important early logs. /// - public class StartupLogBuffer + public class LogBuffer { - private readonly ConcurrentQueue<(LogLevel LogLevel, string Message)> _logBuffer; + private readonly ConcurrentQueue<(LogLevel LogLevel, string Message, Exception? Exception)> _logBuffer; private readonly object _flushLock = new(); - public StartupLogBuffer() + public LogBuffer() { _logBuffer = new(); } @@ -23,21 +23,21 @@ public StartupLogBuffer() /// /// Buffers a log entry with a specific category name. /// - public void BufferLog(LogLevel logLevel, string message) + public void BufferLog(LogLevel logLevel, string message, Exception? exception = null) { - _logBuffer.Enqueue((logLevel, message)); + _logBuffer.Enqueue((logLevel, message, exception)); } /// /// Flushes all buffered logs to a single target logger. /// - public void FlushToLogger(ILogger? targetLogger) + public void FlushToLogger(ILogger targetLogger) { lock (_flushLock) { - while (_logBuffer.TryDequeue(out (LogLevel LogLevel, string Message) entry)) + while (_logBuffer.TryDequeue(out (LogLevel LogLevel, string Message, Exception? Exception) entry)) { - targetLogger?.Log(entry.LogLevel, message: entry.Message); + targetLogger.Log(entry.LogLevel, message: entry.Message, exception: entry.Exception); } } } diff --git a/src/Config/RuntimeConfigLoader.cs b/src/Config/RuntimeConfigLoader.cs index ae5c2dde95..76815e3521 100644 --- a/src/Config/RuntimeConfigLoader.cs +++ b/src/Config/RuntimeConfigLoader.cs @@ -27,6 +27,8 @@ public abstract class RuntimeConfigLoader private HotReloadEventHandler? _handler; protected readonly string? _connectionString; + protected static LogBuffer _logBuffer = new(); + // Public to allow the RuntimeProvider and other users of class to set via out param. // May be candidate to refactor by changing all of the Parse/Load functions to save // state in place of using out params. diff --git a/src/Service.Tests/Configuration/ConfigurationTests.cs b/src/Service.Tests/Configuration/ConfigurationTests.cs index fbd8b759a9..58dfbb3478 100644 --- a/src/Service.Tests/Configuration/ConfigurationTests.cs +++ b/src/Service.Tests/Configuration/ConfigurationTests.cs @@ -77,8 +77,8 @@ public class ConfigurationTests private const string BROWSER_USER_AGENT_HEADER = "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36"; private const string BROWSER_ACCEPT_HEADER = "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9"; - private const int RETRY_COUNT = 5; - private const int RETRY_WAIT_SECONDS = 2; + public const int RETRY_COUNT = 5; + public const int RETRY_WAIT_SECONDS = 2; /// /// diff --git a/src/Service.Tests/Configuration/RuntimeConfigLoaderTests.cs b/src/Service.Tests/Configuration/RuntimeConfigLoaderTests.cs index d6f19ec65f..1604728bd6 100644 --- a/src/Service.Tests/Configuration/RuntimeConfigLoaderTests.cs +++ b/src/Service.Tests/Configuration/RuntimeConfigLoaderTests.cs @@ -10,6 +10,7 @@ using System.Threading.Tasks; using Azure.DataApiBuilder.Config; using Azure.DataApiBuilder.Config.ObjectModel; +using Microsoft.Extensions.Logging; using Microsoft.VisualStudio.TestTools.UnitTesting; using Newtonsoft.Json.Linq; @@ -95,11 +96,26 @@ public async Task FailLoadMultiDataSourceConfigDuplicateEntities(string configPa StringWriter sw = new(); Console.SetError(sw); + ILoggerFactory loggerFactory = LoggerFactory.Create(builder => + { + builder.SetMinimumLevel(LogLevel.Trace); + builder.AddConsole(options => + { + options.LogToStandardErrorThreshold = LogLevel.Error; + }); + }); + ILogger logger = loggerFactory.CreateLogger(); + + loader.SetLogger(logger); loader.TryLoadConfig("dab-config.json", out RuntimeConfig _); string error = sw.ToString(); - Assert.IsTrue(error.StartsWith("Deserialization of the configuration file failed during a post-processing step.")); - Assert.IsTrue(error.Contains("An item with the same key has already been added.")); + await TestHelper.DelayTask(() => string.IsNullOrWhiteSpace(sw.ToString())); + + Assert.IsTrue(loader.IsParseErrorEmitted, + "IsParseErrorEmitted should be true when config parsing fails."); + Assert.IsFalse(string.IsNullOrWhiteSpace(sw.ToString()), + "An error message should have been emitted to Console.Error."); } /// diff --git a/src/Service.Tests/TestHelper.cs b/src/Service.Tests/TestHelper.cs index 035ee3e6ee..bb83f6243f 100644 --- a/src/Service.Tests/TestHelper.cs +++ b/src/Service.Tests/TestHelper.cs @@ -6,9 +6,11 @@ using System.IO; using System.IO.Abstractions; using System.IO.Abstractions.TestingHelpers; +using System.Threading.Tasks; using Azure.DataApiBuilder.Config; using Azure.DataApiBuilder.Config.ObjectModel; using Azure.DataApiBuilder.Core.Configurations; +using Azure.DataApiBuilder.Service.Tests.Configuration; using Humanizer; using Microsoft.Extensions.Logging; using Newtonsoft.Json.Linq; @@ -317,7 +319,19 @@ public static RuntimeConfigProvider GenerateInMemoryRuntimeConfigProvider(Runtim { MockFileSystem fileSystem = new(); fileSystem.AddFile(FileSystemRuntimeConfigLoader.DEFAULT_CONFIG_FILE_NAME, runtimeConfig.ToJson()); + + ILoggerFactory loggerFactory = LoggerFactory.Create(builder => + { + builder.SetMinimumLevel(LogLevel.Trace); + builder.AddConsole(options => + { + options.LogToStandardErrorThreshold = LogLevel.Error; + }); + }); + + ILogger logger = loggerFactory.CreateLogger(); FileSystemRuntimeConfigLoader loader = new(fileSystem); + loader.SetLogger(logger); RuntimeConfigProvider runtimeConfigProvider = new(loader); return runtimeConfigProvider; } @@ -381,5 +395,24 @@ public static string AddPropertiesToJson(string configuration, string entityProp }); return configurationJson.ToString(); } + + /// + /// Helper function to add retry logic with delay when there is a function + /// that requires the to wait some time for a condition to be met. + /// + /// Boolean condition that needs to be met + /// + public static async Task DelayTask(Func condition) + { + int retryCount = 0; + while (retryCount < ConfigurationTests.RETRY_COUNT && condition()) + { + retryCount++; + if (condition()) + { + await Task.Delay(TimeSpan.FromSeconds(Math.Pow(ConfigurationTests.RETRY_WAIT_SECONDS, retryCount))); + } + } + } } } diff --git a/src/Service.Tests/UnitTests/SqlMetadataProviderUnitTests.cs b/src/Service.Tests/UnitTests/SqlMetadataProviderUnitTests.cs index 7242716847..dd6ad7d27e 100644 --- a/src/Service.Tests/UnitTests/SqlMetadataProviderUnitTests.cs +++ b/src/Service.Tests/UnitTests/SqlMetadataProviderUnitTests.cs @@ -239,9 +239,15 @@ private static async Task CheckExceptionForBadConnectionStringHelperAsync(string { // Combine both the console and exception messages because they both // may contain the connection string errors this function expects to exist. + if (sw is not null) + { + await TestHelper.DelayTask(() => string.IsNullOrWhiteSpace(sw.ToString())); + } + string consoleMessages = sw is not null ? sw.ToString() : string.Empty; string allErrorMessages = ex.Message + " " + consoleMessages; - Assert.IsTrue(allErrorMessages.Contains(DataApiBuilderException.CONNECTION_STRING_ERROR_MESSAGE)); + Assert.IsTrue(allErrorMessages.Contains(DataApiBuilderException.CONNECTION_STRING_ERROR_MESSAGE), + $"Current message does not contain the expected connection string error message: {allErrorMessages}"); Assert.AreEqual(DataApiBuilderException.SubStatusCodes.ErrorInInitialization, ex.SubStatusCode); Assert.AreEqual(HttpStatusCode.ServiceUnavailable, ex.StatusCode); } diff --git a/src/Service/Program.cs b/src/Service/Program.cs index 02719ac13a..11fb9f5cc7 100644 --- a/src/Service/Program.cs +++ b/src/Service/Program.cs @@ -157,6 +157,8 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st // Add filter for dynamic log level changes (e.g., via MCP logging/setLevel) logging.AddFilter(logLevel => LogLevelProvider.ShouldLog(logLevel)); + logging.AddFilter("Microsoft", logLevel => LogLevelProvider.ShouldLog(logLevel)); + logging.AddFilter("Microsoft.Hosting.Lifetime", logLevel => LogLevelProvider.ShouldLog(logLevel)); }) .ConfigureWebHostDefaults(webBuilder => { diff --git a/src/Service/Startup.cs b/src/Service/Startup.cs index 618feef454..841a34483c 100644 --- a/src/Service/Startup.cs +++ b/src/Service/Startup.cs @@ -86,10 +86,10 @@ public class Startup(IConfiguration configuration, ILogger logger) public static AzureLogAnalyticsOptions AzureLogAnalyticsOptions = new(); public static FileSinkOptions FileSinkOptions = new(); public const string NO_HTTPS_REDIRECT_FLAG = "--no-https-redirect"; - private StartupLogBuffer _logBuffer = new(); private readonly HotReloadEventHandler _hotReloadEventHandler = new(); private RuntimeConfigProvider? _configProvider; private ILogger _logger = logger; + private LogBuffer _logBuffer = new(); public IConfiguration Configuration { get; } = configuration; @@ -106,7 +106,6 @@ public class Startup(IConfiguration configuration, ILogger logger) public void ConfigureServices(IServiceCollection services) { Startup.AddValidFilters(); - services.AddSingleton(_logBuffer); services.AddSingleton(Program.LogLevelProvider); services.AddSingleton(_hotReloadEventHandler); string configFileName = Configuration.GetValue("ConfigFileName") ?? FileSystemRuntimeConfigLoader.DEFAULT_CONFIG_FILE_NAME; @@ -114,7 +113,7 @@ public void ConfigureServices(IServiceCollection services) FileSystemRuntimeConfigLoader.RUNTIME_ENV_CONNECTION_STRING.Replace(FileSystemRuntimeConfigLoader.ENVIRONMENT_PREFIX, ""), null); IFileSystem fileSystem = new FileSystem(); - FileSystemRuntimeConfigLoader configLoader = new(fileSystem, _hotReloadEventHandler, configFileName, connectionString, logBuffer: _logBuffer); + FileSystemRuntimeConfigLoader configLoader = new(fileSystem, _hotReloadEventHandler, configFileName, connectionString); RuntimeConfigProvider configProvider = new(configLoader); _configProvider = configProvider; @@ -160,32 +159,32 @@ public void ConfigureServices(IServiceCollection services) .WithMetrics(metrics => { metrics.SetResourceBuilder(ResourceBuilder.CreateDefault().AddService(runtimeConfig.Runtime.Telemetry.OpenTelemetry.ServiceName!)) - // TODO: should we also add FusionCache metrics? - // To do so we just need to add the package ZiggyCreatures.FusionCache.OpenTelemetry and call - // .AddFusionCacheInstrumentation() - .AddOtlpExporter(configure => - { - configure.Endpoint = otlpEndpoint; - configure.Headers = runtimeConfig.Runtime.Telemetry.OpenTelemetry.Headers; - configure.Protocol = OtlpExportProtocol.Grpc; - }) - .AddMeter(TelemetryMetricsHelper.MeterName); + // TODO: should we also add FusionCache metrics? + // To do so we just need to add the package ZiggyCreatures.FusionCache.OpenTelemetry and call + // .AddFusionCacheInstrumentation() + .AddOtlpExporter(configure => + { + configure.Endpoint = otlpEndpoint; + configure.Headers = runtimeConfig.Runtime.Telemetry.OpenTelemetry.Headers; + configure.Protocol = OtlpExportProtocol.Grpc; + }) + .AddMeter(TelemetryMetricsHelper.MeterName); }) .WithTracing(tracing => { tracing.SetResourceBuilder(ResourceBuilder.CreateDefault().AddService(runtimeConfig.Runtime.Telemetry.OpenTelemetry.ServiceName!)) - .AddHttpClientInstrumentation() - // TODO: should we also add FusionCache traces? - // To do so we just need to add the package ZiggyCreatures.FusionCache.OpenTelemetry and call - // .AddFusionCacheInstrumentation() - .AddHotChocolateInstrumentation() - .AddOtlpExporter(configure => - { - configure.Endpoint = otlpEndpoint; - configure.Headers = runtimeConfig.Runtime.Telemetry.OpenTelemetry.Headers; - configure.Protocol = OtlpExportProtocol.Grpc; - }) - .AddSource(TelemetryTracesHelper.DABActivitySource.Name); + .AddHttpClientInstrumentation() + // TODO: should we also add FusionCache traces? + // To do so we just need to add the package ZiggyCreatures.FusionCache.OpenTelemetry and call + // .AddFusionCacheInstrumentation() + .AddHotChocolateInstrumentation() + .AddOtlpExporter(configure => + { + configure.Endpoint = otlpEndpoint; + configure.Headers = runtimeConfig.Runtime.Telemetry.OpenTelemetry.Headers; + configure.Protocol = OtlpExportProtocol.Grpc; + }) + .AddSource(TelemetryTracesHelper.DABActivitySource.Name); }); } @@ -600,7 +599,7 @@ private void ConfigureResponseCompression(IServiceCollection services, RuntimeCo options.Level = systemCompressionLevel; }); - _logger.LogDebug("Response compression enabled with level '{compressionLevel}' for REST, GraphQL, and MCP endpoints.", compressionLevel); + _logBuffer.BufferLog(LogLevel.Information, $"Response compression enabled with level '{compressionLevel}' for REST, GraphQL, and MCP endpoints."); } /// @@ -649,42 +648,42 @@ private void AddGraphQLService(IServiceCollection services, GraphQLRuntimeOption { if (error.Exception is not null) { - _logger.LogError(exception: error.Exception, message: "A GraphQL request execution error occurred."); + _logger.LogError(error.Exception, "A GraphQL request execution error occurred."); return error.WithMessage(error.Exception.Message); } if (error.Code is not null) { - _logger.LogError(message: "Error code: {errorCode}\nError message: {errorMessage}", error.Code, error.Message); + _logger.LogError($"Error code: {error.Code}\nError message: {error.Message}"); return error.WithMessage(error.Message); } return error; }) - .AddErrorFilter(error => + .AddErrorFilter(error => + { + if (error.Exception is DataApiBuilderException thrownException) { - if (error.Exception is DataApiBuilderException thrownException) - { - error = error - .WithException(null) - .WithMessage(thrownException.Message) - .WithCode($"{thrownException.SubStatusCode}"); + error = error + .WithException(null) + .WithMessage(thrownException.Message) + .WithCode($"{thrownException.SubStatusCode}"); - // If user error i.e. validation error or conflict error with datasource, then retain location/path - if (!thrownException.StatusCode.IsClientError()) - { - error = error.WithLocations(Array.Empty()); - } + // If user error i.e. validation error or conflict error with datasource, then retain location/path + if (!thrownException.StatusCode.IsClientError()) + { + error = error.WithLocations(Array.Empty()); } + } - return error; - }) - // Allows DAB to override the HTTP error code set by HotChocolate. - // This is used to ensure HTTP code 4XX is set when the datatbase - // returns a "bad request" error such as stored procedure params missing. - .UseRequest() - .UseRequest() - .UseDefaultPipeline(); + return error; + }) + // Allows DAB to override the HTTP error code set by HotChocolate. + // This is used to ensure HTTP code 4XX is set when the datatbase + // returns a "bad request" error such as stored procedure params missing. + .UseRequest() + .UseRequest() + .UseDefaultPipeline(); } /// @@ -702,44 +701,70 @@ private void RefreshGraphQLSchema(IServiceCollection services) public void Configure(IApplicationBuilder app, IWebHostEnvironment env, RuntimeConfigProvider runtimeConfigProvider, IHostApplicationLifetime hostLifetime) { bool isRuntimeReady = false; + RuntimeConfig? runtimeConfig = null; - if (runtimeConfigProvider.TryGetConfig(out RuntimeConfig? runtimeConfig)) + try { - // Set LogLevel based on RuntimeConfig - DynamicLogLevelProvider logLevelProvider = app.ApplicationServices.GetRequiredService(); - logLevelProvider.UpdateFromRuntimeConfig(runtimeConfig); - FileSystemRuntimeConfigLoader configLoader = app.ApplicationServices.GetRequiredService(); + if (runtimeConfigProvider.TryGetConfig(out runtimeConfig)) + { + // Create log level initializer for Startup, which allows it to respond to runtime config changes and update the log level accordingly. + LogLevelInitializer logLevelInit = new(MinimumLogLevel, typeof(Startup).FullName, runtimeConfigProvider, _hotReloadEventHandler); - //Flush all logs that were buffered before setting the LogLevel - configLoader.SetLogger(app.ApplicationServices.GetRequiredService>()); - configLoader.FlushLogBuffer(); + // Set LogLevel based on RuntimeConfig + DynamicLogLevelProvider logLevelProvider = app.ApplicationServices.GetRequiredService(); + logLevelProvider.UpdateFromRuntimeConfig(runtimeConfig); + + // Configure Telemetry + // TODO: Issue #3239. Refactor this methods so that they are all called before creating the new logger factory. + ConfigureApplicationInsightsTelemetry(app, runtimeConfig, logLevelInit); + ConfigureOpenTelemetry(app, runtimeConfig, logLevelInit); + ConfigureAzureLogAnalytics(app, runtimeConfig, logLevelInit); + ConfigureFileSink(app, runtimeConfig, logLevelInit); - // Configure Telemetry - ConfigureApplicationInsightsTelemetry(app, runtimeConfig); - ConfigureOpenTelemetry(runtimeConfig); - ConfigureAzureLogAnalytics(runtimeConfig); - ConfigureFileSink(app, runtimeConfig); + //Flush all logs that were buffered before setting the LogLevel. + // Important: All logs set before this point should use _logBuffer. + FlushAllLogs(app); - // Config provided before starting the engine. - isRuntimeReady = PerformOnConfigChangeAsync(app).Result; + // Config provided before starting the engine. + isRuntimeReady = PerformOnConfigChangeAsync(app).Result; - if (!isRuntimeReady) + if (!isRuntimeReady) + { + _logger.LogError( + message: "Could not initialize the engine with the runtime config file: {configFilePath}", + runtimeConfigProvider.ConfigFilePath); + hostLifetime.StopApplication(); + } + } + else { - _logger.LogError( - message: "Could not initialize the engine with the runtime config file: {configFilePath}", - runtimeConfigProvider.ConfigFilePath); - hostLifetime.StopApplication(); + // Config provided during runtime. + runtimeConfigProvider.IsLateConfigured = true; + runtimeConfigProvider.RuntimeConfigLoadedHandlers.Add(async (_, _) => + { + // This section will only run if the runtime config is provided during runtime. E.g. IsLateConfigured is true. + // Set LogLevel based on RuntimeConfig + RuntimeConfigProvider runtimeConfigProvider = app.ApplicationServices.GetService()!; + RuntimeConfig runtimeConfig = runtimeConfigProvider.GetConfig(); + DynamicLogLevelProvider logLevelProvider = app.ApplicationServices.GetRequiredService(); + logLevelProvider.UpdateFromRuntimeConfig(runtimeConfig); + + //Flush all logs that were buffered before setting the LogLevel. + // Important: All logs set before this point should use _logBuffer. + // This flush ensures that no logs are lost in the case of an IsLateConfigured scenario. + FlushAllLogs(app); + + isRuntimeReady = await PerformOnConfigChangeAsync(app); + + return isRuntimeReady; + }); } } - else + finally { - // Config provided during runtime. - runtimeConfigProvider.IsLateConfigured = true; - runtimeConfigProvider.RuntimeConfigLoadedHandlers.Add(async (_, _) => - { - isRuntimeReady = await PerformOnConfigChangeAsync(app); - return isRuntimeReady; - }); + // Attempt one final flush in case there was any exception that caused the + // previous section to throw an error before flushing the logs. + FlushAllLogs(app); } if (env.IsDevelopment()) @@ -945,7 +970,7 @@ private void ConfigureAuthentication(IServiceCollection services, RuntimeConfigP if (easyAuthType == EasyAuthType.AppService && !appServiceEnvironmentDetected) { - _logger.LogWarning(AppServiceAuthenticationInfo.APPSERVICE_DEV_MISSING_ENV_CONFIG); + _logBuffer.BufferLog(LogLevel.Warning, AppServiceAuthenticationInfo.APPSERVICE_DEV_MISSING_ENV_CONFIG); } string defaultScheme = easyAuthType == EasyAuthType.AppService @@ -955,7 +980,7 @@ private void ConfigureAuthentication(IServiceCollection services, RuntimeConfigP services.AddAuthentication(defaultScheme) .AddEnvDetectedEasyAuth(); - _logger.LogInformation("Registered EasyAuth scheme: {Scheme}", defaultScheme); + _logBuffer.BufferLog(LogLevel.Information, $"Registered EasyAuth scheme: {defaultScheme}"); } else if (authOptions.IsUnauthenticatedAuthenticationProvider()) @@ -1015,7 +1040,7 @@ private static void ConfigureAuthenticationV2(IServiceCollection services, Runti /// The application builder. /// The provider used to load runtime configuration. /// - private void ConfigureApplicationInsightsTelemetry(IApplicationBuilder app, RuntimeConfig runtimeConfig) + private void ConfigureApplicationInsightsTelemetry(IApplicationBuilder app, RuntimeConfig runtimeConfig, LogLevelInitializer logLevelInit) { if (runtimeConfig?.Runtime?.Telemetry is not null && runtimeConfig.Runtime.Telemetry.ApplicationInsights is not null) @@ -1024,13 +1049,13 @@ private void ConfigureApplicationInsightsTelemetry(IApplicationBuilder app, Runt if (!AppInsightsOptions.Enabled) { - _logger.LogInformation("Application Insights are disabled."); + _logBuffer.BufferLog(LogLevel.Information, "Application Insights are disabled."); return; } if (string.IsNullOrWhiteSpace(AppInsightsOptions.ConnectionString)) { - _logger.LogWarning("Logs won't be sent to Application Insights because an Application Insights connection string is not available in the runtime config."); + _logBuffer.BufferLog(LogLevel.Warning, "Logs won't be sent to Application Insights because an Application Insights connection string is not available in the runtime config."); return; } @@ -1038,7 +1063,7 @@ private void ConfigureApplicationInsightsTelemetry(IApplicationBuilder app, Runt if (appTelemetryClient is null) { - _logger.LogError("Telemetry client is not initialized."); + _logBuffer.BufferLog(LogLevel.Error, "Telemetry client is not initialized."); return; } @@ -1053,7 +1078,7 @@ private void ConfigureApplicationInsightsTelemetry(IApplicationBuilder app, Runt } // Updating Startup Logger to Log from Startup Class. - ILoggerFactory loggerFactory = Program.GetLoggerFactoryForLogLevel(MinimumLogLevel, appTelemetryClient); + ILoggerFactory? loggerFactory = CreateLoggerFactoryForHostedAndNonHostedScenario(app.ApplicationServices, logLevelInit); _logger = loggerFactory.CreateLogger(); } } @@ -1063,7 +1088,7 @@ private void ConfigureApplicationInsightsTelemetry(IApplicationBuilder app, Runt /// is enabled, we can track different events and metrics. /// /// The provider used to load runtime configuration. - private void ConfigureOpenTelemetry(RuntimeConfig runtimeConfig) + private void ConfigureOpenTelemetry(IApplicationBuilder app, RuntimeConfig runtimeConfig, LogLevelInitializer logLevelInit) { if (runtimeConfig?.Runtime?.Telemetry is not null && runtimeConfig.Runtime.Telemetry.OpenTelemetry is not null) @@ -1072,19 +1097,19 @@ private void ConfigureOpenTelemetry(RuntimeConfig runtimeConfig) if (!OpenTelemetryOptions.Enabled) { - _logger.LogInformation("Open Telemetry is disabled."); + _logBuffer.BufferLog(LogLevel.Information, "Open Telemetry is disabled."); return; } if (string.IsNullOrWhiteSpace(OpenTelemetryOptions?.Endpoint) || !Uri.TryCreate(OpenTelemetryOptions.Endpoint, UriKind.Absolute, out _)) { - _logger.LogWarning("Logs won't be sent to Open Telemetry because a valid Open Telemetry endpoint URI is not available in the runtime config."); + _logBuffer.BufferLog(LogLevel.Warning, "Logs won't be sent to Open Telemetry because a valid Open Telemetry endpoint URI is not available in the runtime config."); return; } // Updating Startup Logger to Log from Startup Class. - ILoggerFactory? loggerFactory = Program.GetLoggerFactoryForLogLevel(MinimumLogLevel); + ILoggerFactory? loggerFactory = CreateLoggerFactoryForHostedAndNonHostedScenario(app.ApplicationServices, logLevelInit); _logger = loggerFactory.CreateLogger(); } } @@ -1094,7 +1119,7 @@ private void ConfigureOpenTelemetry(RuntimeConfig runtimeConfig) /// is enabled, we can track different events and metrics. /// /// The provider used to load runtime configuration. - private void ConfigureAzureLogAnalytics(RuntimeConfig runtimeConfig) + private void ConfigureAzureLogAnalytics(IApplicationBuilder app, RuntimeConfig runtimeConfig, LogLevelInitializer logLevelInit) { if (runtimeConfig?.Runtime?.Telemetry is not null && runtimeConfig.Runtime.Telemetry.AzureLogAnalytics is not null) @@ -1103,26 +1128,26 @@ private void ConfigureAzureLogAnalytics(RuntimeConfig runtimeConfig) if (!AzureLogAnalyticsOptions.Enabled) { - _logger.LogInformation("Azure Log Analytics is disabled."); + _logBuffer.BufferLog(LogLevel.Information, "Azure Log Analytics is disabled."); return; } bool isAuthIncomplete = false; if (string.IsNullOrEmpty(AzureLogAnalyticsOptions.Auth?.CustomTableName)) { - _logger.LogError("Logs won't be sent to Azure Log Analytics because the Custom Table Name is not available in the config file."); + _logBuffer.BufferLog(LogLevel.Error, "Logs won't be sent to Azure Log Analytics because the Custom Table Name is not available in the config file."); isAuthIncomplete = true; } if (string.IsNullOrEmpty(AzureLogAnalyticsOptions.Auth?.DcrImmutableId)) { - _logger.LogError("Logs won't be sent to Azure Log Analytics because the DCR Immutable Id is not available in the config file."); + _logBuffer.BufferLog(LogLevel.Error, "Logs won't be sent to Azure Log Analytics because the DCR Immutable Id is not available in the config file."); isAuthIncomplete = true; } if (string.IsNullOrEmpty(AzureLogAnalyticsOptions.Auth?.DceEndpoint)) { - _logger.LogError("Logs won't be sent to Azure Log Analytics because the DCE Endpoint is not available in the config file."); + _logBuffer.BufferLog(LogLevel.Error, "Logs won't be sent to Azure Log Analytics because the DCE Endpoint is not available in the config file."); isAuthIncomplete = true; } @@ -1132,7 +1157,7 @@ private void ConfigureAzureLogAnalytics(RuntimeConfig runtimeConfig) } // Updating Startup Logger to Log from Startup Class. - ILoggerFactory? loggerFactory = Program.GetLoggerFactoryForLogLevel(MinimumLogLevel); + ILoggerFactory? loggerFactory = CreateLoggerFactoryForHostedAndNonHostedScenario(app.ApplicationServices, logLevelInit); _logger = loggerFactory.CreateLogger(); } } @@ -1143,7 +1168,7 @@ private void ConfigureAzureLogAnalytics(RuntimeConfig runtimeConfig) /// /// The application builder. /// The provider used to load runtime configuration. - private void ConfigureFileSink(IApplicationBuilder app, RuntimeConfig runtimeConfig) + private void ConfigureFileSink(IApplicationBuilder app, RuntimeConfig runtimeConfig, LogLevelInitializer logLevelInit) { if (runtimeConfig?.Runtime?.Telemetry is not null && runtimeConfig.Runtime.Telemetry.File is not null) @@ -1152,25 +1177,25 @@ private void ConfigureFileSink(IApplicationBuilder app, RuntimeConfig runtimeCon if (!FileSinkOptions.Enabled) { - _logger.LogInformation("File is disabled."); + _logBuffer.BufferLog(LogLevel.Information, "File is disabled."); return; } if (string.IsNullOrWhiteSpace(FileSinkOptions.Path)) { - _logger.LogError("Logs won't be sent to File because the Path is not available in the config file."); + _logBuffer.BufferLog(LogLevel.Error, "Logs won't be sent to File because the Path is not available in the config file."); return; } Logger? serilogLogger = app.ApplicationServices.GetService(); if (serilogLogger is null) { - _logger.LogError("Serilog Logger Configuration is not set."); + _logBuffer.BufferLog(LogLevel.Error, "Serilog Logger Configuration is not set."); return; } // Updating Startup Logger to Log from Startup Class. - ILoggerFactory? loggerFactory = Program.GetLoggerFactoryForLogLevel(logLevel: MinimumLogLevel, serilogLogger: serilogLogger); + ILoggerFactory? loggerFactory = CreateLoggerFactoryForHostedAndNonHostedScenario(app.ApplicationServices, logLevelInit); _logger = loggerFactory.CreateLogger(); } } @@ -1338,6 +1363,7 @@ private bool IsOboConfigured() /// public static void AddValidFilters() { + LoggerFilters.AddFilter(typeof(Startup).FullName); LoggerFilters.AddFilter(typeof(RuntimeConfigValidator).FullName); LoggerFilters.AddFilter(typeof(SqlQueryEngine).FullName); LoggerFilters.AddFilter(typeof(IQueryExecutor).FullName); @@ -1349,6 +1375,7 @@ public static void AddValidFilters() LoggerFilters.AddFilter(typeof(ConfigurationController).FullName); LoggerFilters.AddFilter(typeof(IAuthorizationHandler).FullName); LoggerFilters.AddFilter(typeof(IAuthorizationResolver).FullName); + LoggerFilters.AddFilter(typeof(FileSystemRuntimeConfigLoader).FullName); LoggerFilters.AddFilter("default"); } @@ -1363,5 +1390,28 @@ public static bool IsAzureLogAnalyticsAvailable(AzureLogAnalyticsOptions azureLo && !string.IsNullOrWhiteSpace(azureLogAnalyticsOptions.Auth.DcrImmutableId) && !string.IsNullOrWhiteSpace(azureLogAnalyticsOptions.Auth.DceEndpoint); } + + /// + /// Helper function that sets the logger for FileSystemRuntimeConfigLoader and flushes the buffered logs to the logger. + /// + /// Contains all the services needed to set the logger. + private void FlushAllLogs(IApplicationBuilder app) + { + try + { + FileSystemRuntimeConfigLoader configLoader = app.ApplicationServices.GetRequiredService(); + configLoader.SetLogger(app.ApplicationServices.GetRequiredService>()); + + _logBuffer.FlushToLogger(_logger); + configLoader.FlushLogBuffer(); + } + catch (Exception ex) + { + throw new DataApiBuilderException( + message: ex.Message, + statusCode: System.Net.HttpStatusCode.ServiceUnavailable, + subStatusCode: DataApiBuilderException.SubStatusCodes.ErrorInInitialization); + } + } } } diff --git a/src/Service/Telemetry/DynamicLogLevelProvider.cs b/src/Service/Telemetry/DynamicLogLevelProvider.cs index ec8c08ca9b..517f901546 100644 --- a/src/Service/Telemetry/DynamicLogLevelProvider.cs +++ b/src/Service/Telemetry/DynamicLogLevelProvider.cs @@ -33,6 +33,14 @@ public class DynamicLogLevelProvider : ILogLevelController public bool IsConfigOverridden { get; private 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. + /// + /// 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) { CurrentLogLevel = logLevel; @@ -40,12 +48,22 @@ public void SetInitialLogLevel(LogLevel logLevel = LogLevel.Error, bool isCliOve IsConfigOverridden = isConfigOverridden; } - public void UpdateFromRuntimeConfig(RuntimeConfig runtimeConfig) + /// + /// Updates the current log level based on the runtime configuration, unless it was overridden by the CLI. + /// + /// 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) { - CurrentLogLevel = runtimeConfig.GetConfiguredLogLevel(); + if (loggerFilter is null) + { + loggerFilter = string.Empty; + } + + 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 @@ -54,7 +72,6 @@ public void UpdateFromRuntimeConfig(RuntimeConfig runtimeConfig) } } - /// /// Updates the log level from an MCP logging/setLevel request. /// Precedence (highest to lowest): /// 1. CLI --LogLevel flag (IsCliOverridden = true) @@ -96,6 +113,12 @@ public bool UpdateFromMcp(string mcpLevel) return false; } + /// + /// Used to dynamically determine whether a log should be emitted based on the current log level. + /// This allows for dynamic log level changes at runtime without needing to restart the application. + /// + /// The log level of the log that wants to be emitted. + /// True if the log should be emitted, false otherwise. public bool ShouldLog(LogLevel logLevel) { return logLevel >= CurrentLogLevel; From ee75c86bb6098392d2017358af4cb9cc106b6ee6 Mon Sep 17 00:00:00 2001 From: Anusha Kolan Date: Wed, 6 May 2026 10:43:05 -0700 Subject: [PATCH 2/3] Add MCP notifications/message for log streaming to clients (#3484) ## Why make this change? Enables MCP clients (like MCP Inspector, Claude Desktop, VS Code Copilot) to receive real-time log output via MCP `notifications/message`. Related: #3274 (depends on PR #3419) ## What is this change? When `logging/setLevel` is called with a level other than "none", logs are sent to MCP clients as JSON-RPC notifications: ```json { "jsonrpc": "2.0", "method": "notifications/message", "params": { "level": "info", "logger": "Azure.DataApiBuilder.Service.Startup", "data": "Starting Data API builder..." } } ``` ### New files: - `McpLogNotificationWriter.cs` - Writes logs as MCP notifications to stdout - `McpLogger.cs` / `McpLoggerProvider.cs` - ILogger implementation for .NET logging pipeline - `McpLogNotificationTests.cs` - Unit tests (8 tests) ### Modified files: - `Program.cs` - Registers `McpNotificationWriter` and `McpLoggerProvider` for MCP mode - `McpStdioServer.cs` - Enables notifications when `logging/setLevel` is called ## How was this tested? - Unit tests: 6 tests covering level mapping, enable/disable, JSON format - Manual testing with MCP Inspector: verified notifications appear when `logging/setLevel` is sent ## Note This PR targets `dev/anushakolan/set-log-level` (PR #3419) as it depends on the `logging/setLevel` implementation. --- .../Core/McpStdioServer.cs | 56 +++-- .../Core/McpStdoutWriter.cs | 101 ++++++++ .../Model/McpStdioJsonRpcErrorCodes.cs | 5 + .../Telemetry/McpLogNotificationWriter.cs | 114 +++++++++ .../Telemetry/McpLogger.cs | 126 ++++++++++ .../Telemetry/McpLoggerProvider.cs | 58 +++++ src/Core/Telemetry/McpLogLevelConverter.cs | 70 ++++++ .../UnitTests/DynamicLogLevelProviderTests.cs | 82 +++++++ .../UnitTests/McpLogNotificationTests.cs | 232 ++++++++++++++++++ .../UnitTests/McpStdoutWriterTests.cs | 229 +++++++++++++++++ src/Service/Program.cs | 47 ++++ .../Telemetry/DynamicLogLevelProvider.cs | 25 +- 12 files changed, 1104 insertions(+), 41 deletions(-) create mode 100644 src/Azure.DataApiBuilder.Mcp/Core/McpStdoutWriter.cs create mode 100644 src/Azure.DataApiBuilder.Mcp/Telemetry/McpLogNotificationWriter.cs create mode 100644 src/Azure.DataApiBuilder.Mcp/Telemetry/McpLogger.cs create mode 100644 src/Azure.DataApiBuilder.Mcp/Telemetry/McpLoggerProvider.cs create mode 100644 src/Core/Telemetry/McpLogLevelConverter.cs create mode 100644 src/Service.Tests/UnitTests/McpLogNotificationTests.cs create mode 100644 src/Service.Tests/UnitTests/McpStdoutWriterTests.cs diff --git a/src/Azure.DataApiBuilder.Mcp/Core/McpStdioServer.cs b/src/Azure.DataApiBuilder.Mcp/Core/McpStdioServer.cs index 0588050fb0..8ec232981a 100644 --- a/src/Azure.DataApiBuilder.Mcp/Core/McpStdioServer.cs +++ b/src/Azure.DataApiBuilder.Mcp/Core/McpStdioServer.cs @@ -8,6 +8,7 @@ using Azure.DataApiBuilder.Core.Configurations; using Azure.DataApiBuilder.Core.Telemetry; using Azure.DataApiBuilder.Mcp.Model; +using Azure.DataApiBuilder.Mcp.Telemetry; using Azure.DataApiBuilder.Mcp.Utils; using Microsoft.AspNetCore.Http; using Microsoft.Extensions.Configuration; @@ -26,6 +27,7 @@ public class McpStdioServer : IMcpStdioServer { private readonly McpToolRegistry _toolRegistry; private readonly IServiceProvider _serviceProvider; + private readonly McpStdoutWriter _stdoutWriter; private readonly string _protocolVersion; private const int MAX_LINE_LENGTH = 1024 * 1024; // 1 MB limit for incoming JSON-RPC requests @@ -35,6 +37,11 @@ public McpStdioServer(McpToolRegistry toolRegistry, IServiceProvider serviceProv _toolRegistry = toolRegistry ?? throw new ArgumentNullException(nameof(toolRegistry)); _serviceProvider = serviceProvider ?? throw new ArgumentNullException(nameof(serviceProvider)); + // Resolve the shared stdout writer so JSON-RPC responses and + // notifications/message frames are serialized through one lock. + // Falls back to a fresh instance if DI didn't register one (defensive). + _stdoutWriter = _serviceProvider.GetService() ?? new McpStdoutWriter(); + // Allow protocol version to be configured via IConfiguration, using centralized defaults. IConfiguration? configuration = _serviceProvider.GetService(); _protocolVersion = McpProtocolDefaults.ResolveProtocolVersion(configuration); @@ -47,16 +54,14 @@ public McpStdioServer(McpToolRegistry toolRegistry, IServiceProvider serviceProv /// A task representing the asynchronous operation. public async Task RunAsync(CancellationToken cancellationToken) { - // Use UTF-8 WITHOUT BOM + // Use UTF-8 WITHOUT BOM for stdin. Stdout is owned by McpStdoutWriter, + // which serializes all writes from McpStdioServer and the MCP logging + // pipeline so JSON-RPC frames cannot interleave at the byte level. UTF8Encoding utf8NoBom = new(encoderShouldEmitUTF8Identifier: false); using Stream stdin = Console.OpenStandardInput(); - using Stream stdout = Console.OpenStandardOutput(); using StreamReader reader = new(stdin, utf8NoBom); - using StreamWriter writer = new(stdout, utf8NoBom) { AutoFlush = true }; - // Redirect Console.Out to use our writer - Console.SetOut(writer); while (!cancellationToken.IsCancellationRequested) { string? line = await reader.ReadLineAsync(cancellationToken); @@ -298,16 +303,31 @@ private void HandleSetLogLevel(JsonElement? id, JsonElement root) // If CLI or Config overrode, this returns false but we still return success to the client bool updated = logLevelController.UpdateFromMcp(level); - // If MCP successfully changed the log level to something other than "none", - // ensure Console.Error is pointing to the real stderr (not TextWriter.Null). - // This handles the case where MCP stdio mode started with LogLevel.None (quiet startup) - // and the client later enables logging via logging/setLevel. + // 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) { RestoreStderrIfNeeded(); } + // 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. + IMcpLogNotificationWriter? notificationWriter = _serviceProvider.GetService(); + if (notificationWriter != null) + { + notificationWriter.IsEnabled = isLoggingEnabled; + } + // Always return success (empty result object) per MCP spec WriteResult(id, new { }); } @@ -539,39 +559,41 @@ private static string SafeToString(object obj) /// /// Writes a JSON-RPC result response to the standard output. + /// Routed through so the write is serialized + /// with notifications/message frames from the logging pipeline. /// /// The request identifier extracted from the incoming JSON-RPC request. Used to correlate the response with the request. /// The result object to include in the response. - private static void WriteResult(JsonElement? id, object resultObject) + private void WriteResult(JsonElement? id, object resultObject) { var response = new { - jsonrpc = "2.0", + jsonrpc = McpStdioJsonRpcErrorCodes.JSON_RPC_VERSION, id = id.HasValue ? GetIdValue(id.Value) : null, result = resultObject }; - string json = JsonSerializer.Serialize(response); - Console.Out.WriteLine(json); + _stdoutWriter.WriteLine(JsonSerializer.Serialize(response)); } /// /// Writes a JSON-RPC error response to the standard output. + /// Routed through so the write is serialized + /// with notifications/message frames from the logging pipeline. /// /// The request identifier extracted from the incoming JSON-RPC request. Used to correlate the response with the request. /// The error code. /// The error message. - private static void WriteError(JsonElement? id, int code, string message) + private void WriteError(JsonElement? id, int code, string message) { var errorObj = new { - jsonrpc = "2.0", + jsonrpc = McpStdioJsonRpcErrorCodes.JSON_RPC_VERSION, id = id.HasValue ? GetIdValue(id.Value) : null, error = new { code, message } }; - string json = JsonSerializer.Serialize(errorObj); - Console.Out.WriteLine(json); + _stdoutWriter.WriteLine(JsonSerializer.Serialize(errorObj)); } /// diff --git a/src/Azure.DataApiBuilder.Mcp/Core/McpStdoutWriter.cs b/src/Azure.DataApiBuilder.Mcp/Core/McpStdoutWriter.cs new file mode 100644 index 0000000000..7a30fccec3 --- /dev/null +++ b/src/Azure.DataApiBuilder.Mcp/Core/McpStdoutWriter.cs @@ -0,0 +1,101 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System.Text; + +namespace Azure.DataApiBuilder.Mcp.Core +{ + /// + /// Process-wide owner of the MCP stdio server's stdout stream. + /// + /// In MCP stdio mode, stdout is the JSON-RPC channel and is shared by + /// multiple writers — JSON-RPC responses from + /// and asynchronous notifications/message frames from the logging + /// pipeline. Without coordination, two writers calling WriteLine + /// concurrently can interleave at the byte level and corrupt the channel. + /// + /// This class wraps the underlying and serializes + /// every write through a single lock so JSON-RPC frames stay intact. + /// Registered as a singleton in DI for MCP stdio mode; instantiated lazily + /// (the underlying stream is opened on the first write) so non-MCP code + /// paths and unit tests can construct the type without side effects. + /// + public sealed class McpStdoutWriter : IDisposable + { + private readonly object _lock = new(); + private TextWriter? _writer; + private bool _disposed; + + /// + /// Production constructor. The underlying stdout stream is opened + /// lazily on the first call. + /// + public McpStdoutWriter() + { + } + + /// + /// Test-only constructor that injects a pre-built writer so unit tests + /// can verify lock behavior, disposal semantics, and notification + /// framing without touching the real stdout stream. + /// + internal McpStdoutWriter(TextWriter writer) + { + _writer = writer ?? throw new ArgumentNullException(nameof(writer)); + } + + /// + /// Writes a single line to stdout under a process-wide lock so + /// concurrent JSON-RPC responses and notifications cannot interleave. + /// No-op after . + /// + public void WriteLine(string line) + { + lock (_lock) + { + if (_disposed) + { + return; + } + + EnsureInitialized(); + _writer!.WriteLine(line); + } + } + + public void Dispose() + { + lock (_lock) + { + if (_disposed) + { + return; + } + + _disposed = true; + _writer?.Dispose(); + _writer = null; + } + } + + private void EnsureInitialized() + { + if (_writer is not null) + { + return; + } + + // Opening the raw stdout stream bypasses any Console.SetOut(...) + // redirection. This is intentional: in MCP stdio mode, Program.cs + // redirects Console.Out to a sink (TextWriter.Null or stderr) so + // stray Console.WriteLine calls from third-party code cannot + // corrupt the JSON-RPC channel. Only this class - and only via + // WriteLine() - is allowed to write to the real stdout. + Stream stdout = Console.OpenStandardOutput(); + _writer = new StreamWriter(stdout, new UTF8Encoding(encoderShouldEmitUTF8Identifier: false)) + { + AutoFlush = true + }; + } + } +} diff --git a/src/Azure.DataApiBuilder.Mcp/Model/McpStdioJsonRpcErrorCodes.cs b/src/Azure.DataApiBuilder.Mcp/Model/McpStdioJsonRpcErrorCodes.cs index 3bac194068..07e5c2c9b5 100644 --- a/src/Azure.DataApiBuilder.Mcp/Model/McpStdioJsonRpcErrorCodes.cs +++ b/src/Azure.DataApiBuilder.Mcp/Model/McpStdioJsonRpcErrorCodes.cs @@ -7,6 +7,11 @@ namespace Azure.DataApiBuilder.Mcp.Model /// internal static class McpStdioJsonRpcErrorCodes { + /// + /// JSON-RPC protocol version. + /// + public const string JSON_RPC_VERSION = "2.0"; + /// /// Invalid JSON was received by the server. /// An error occurred on the server while parsing the JSON text. diff --git a/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLogNotificationWriter.cs b/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLogNotificationWriter.cs new file mode 100644 index 0000000000..1a2ba3cb9a --- /dev/null +++ b/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLogNotificationWriter.cs @@ -0,0 +1,114 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System.Text.Json; +using Azure.DataApiBuilder.Core.Telemetry; +using Azure.DataApiBuilder.Mcp.Core; +using Azure.DataApiBuilder.Mcp.Model; +using Microsoft.Extensions.Logging; + +namespace Azure.DataApiBuilder.Mcp.Telemetry; + +/// +/// Writes log messages as MCP `notifications/message` JSON-RPC notifications. +/// This allows MCP clients (like MCP Inspector) to receive log output in real-time. +/// +/// +/// MCP spec: https://modelcontextprotocol.io/specification/2025-11-05/server/utilities/logging +/// The notification format is: +/// +/// { +/// "jsonrpc": "2.0", +/// "method": "notifications/message", +/// "params": { +/// "level": "info", +/// "logger": "CategoryName", +/// "data": "The log message" +/// } +/// } +/// +/// All writes are routed through the shared so +/// notifications cannot interleave with JSON-RPC responses written by +/// . +/// +public class McpLogNotificationWriter : IMcpLogNotificationWriter +{ + private readonly McpStdoutWriter? _stdoutWriter; + + /// + /// Creates a notification writer that writes through the shared stdout + /// writer. The shared writer serializes notifications with JSON-RPC + /// responses so concurrent writes do not interleave on the wire. + /// + /// + /// Shared stdout writer. May be null for unit tests that do not + /// exercise the write path; in that case + /// becomes a no-op. + /// + public McpLogNotificationWriter(McpStdoutWriter? stdoutWriter = null) + { + _stdoutWriter = stdoutWriter; + } + + /// + /// Gets or sets whether MCP log notifications are enabled. This is the + /// single source of truth for whether notifications flow to the client; + /// it is consulted by so that + /// the gate is enforced once, at log time, before any formatter work runs. + /// intentionally does not re-check this + /// flag — callers must gate via . + /// + public bool IsEnabled { get; set; } + + /// + /// Writes a log message as an MCP notification. The caller is responsible + /// for gating on ; already + /// does this in its override. + /// + /// The .NET log level. + /// The logger category (typically class name). + /// The formatted log message. + public void WriteNotification(LogLevel logLevel, string categoryName, string message) + { + // No IsEnabled check here: the gate lives in McpLogger.IsEnabled so + // that we have a single source of truth and a single check site. + // The _stdoutWriter null check remains as a defensive guard for unit + // tests that construct the writer without a backing stdout. + if (_stdoutWriter is null) + { + return; + } + + string mcpLevel = McpLogLevelConverter.ConvertToMcp(logLevel); + + var notification = new + { + jsonrpc = McpStdioJsonRpcErrorCodes.JSON_RPC_VERSION, + method = "notifications/message", + @params = new + { + level = mcpLevel, + logger = categoryName, + data = message + } + }; + + _stdoutWriter.WriteLine(JsonSerializer.Serialize(notification)); + } +} + +/// +/// Interface for MCP log notification writing. +/// +public interface IMcpLogNotificationWriter +{ + /// + /// Gets or sets whether MCP log notifications are enabled. + /// + bool IsEnabled { get; set; } + + /// + /// Writes a log message as an MCP notification. + /// + void WriteNotification(LogLevel logLevel, string categoryName, string message); +} diff --git a/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLogger.cs b/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLogger.cs new file mode 100644 index 0000000000..0338431a1d --- /dev/null +++ b/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLogger.cs @@ -0,0 +1,126 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using Microsoft.Extensions.Logging; + +namespace Azure.DataApiBuilder.Mcp.Telemetry; + +/// +/// ILogger implementation that sends log messages as MCP notifications. +/// +public class McpLogger : ILogger +{ + private readonly string _categoryName; + private readonly IMcpLogNotificationWriter _writer; + + /// + /// Creates a new . + /// + /// + /// No level-filter delegate is accepted here. Level filtering is the job + /// of the logging framework's filter chain (configured via + /// ILoggingBuilder.AddFilter(...) in Program.cs); by the time the + /// framework calls , those filters have already passed. + /// Re-running the same delegate against the same shared + /// LogLevelProvider state would produce the same answer and only + /// add a maintenance trap (a future contributor could mistake the per- + /// logger filter for an independent gate). + /// + public McpLogger(string categoryName, IMcpLogNotificationWriter writer) + { + _categoryName = categoryName ?? throw new ArgumentNullException(nameof(categoryName)); + _writer = writer ?? throw new ArgumentNullException(nameof(writer)); + } + + /// + /// + /// Scopes are intentionally not supported in this implementation. The MCP + /// notifications/message frame has no first-class structured field + /// for scope state, and we currently emit a plain string in params.data. + /// + /// TODO: Consider implementing + /// on so scope state can be flowed through + /// from the host (e.g. ASP.NET Core request scopes, activity correlation + /// IDs). When done, this method should return a real scope tied to an + /// , and + /// should walk + /// + /// to append (or attach as a structured field on the JSON-RPC notification) + /// the active scope chain. See aaronburtle's review on PR for context. + /// + public IDisposable? BeginScope(TState state) where TState : notnull + { + // Scopes are not supported for MCP notifications. See remarks above + // for the path to add ISupportExternalScope support in the future. + return NullScope.Instance; + } + + /// + /// + /// Returns true when the writer is enabled (the MCP client has issued + /// logging/setLevel with a non-"none" value) and the requested + /// level is not . Per-level filtering is + /// applied upstream by the framework's filter chain in Program.cs. + /// + public bool IsEnabled(LogLevel logLevel) + { + return _writer.IsEnabled && logLevel != LogLevel.None; + } + + /// + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) + { + if (!IsEnabled(logLevel)) + { + return; + } + + if (formatter == null) + { + throw new ArgumentNullException(nameof(formatter)); + } + + string message = formatter(state, exception); + + if (string.IsNullOrEmpty(message) && exception == null) + { + return; + } + + // Append the full exception details (type, message, stack trace, and + // any inner exceptions) using Exception.ToString(). This matches the + // behavior of the built-in console/Serilog formatters and is what MCP + // clients (e.g. MCP Inspector) render for log notifications. Dropping + // the stack trace would make production triage from a remote client + // effectively impossible. ToString() walks InnerException chains and + // flattens AggregateException, so no manual recursion is needed. + if (exception != null) + { + string separator = string.IsNullOrEmpty(message) ? string.Empty : Environment.NewLine; + message = $"{message}{separator}{exception}"; + } + + _writer.WriteNotification(logLevel, _categoryName, message); + } + + /// + /// Null scope implementation for when scopes are not supported. + /// + private sealed class NullScope : IDisposable + { + public static NullScope Instance { get; } = new NullScope(); + + private NullScope() + { + } + + public void Dispose() + { + } + } +} diff --git a/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLoggerProvider.cs b/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLoggerProvider.cs new file mode 100644 index 0000000000..e86120462c --- /dev/null +++ b/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLoggerProvider.cs @@ -0,0 +1,58 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System.Collections.Concurrent; +using Microsoft.Extensions.Logging; + +namespace Azure.DataApiBuilder.Mcp.Telemetry; + +/// +/// Logger provider that creates McpLogger instances for sending logs as MCP notifications. +/// +public class McpLoggerProvider : ILoggerProvider +{ + private readonly IMcpLogNotificationWriter _writer; + private readonly ConcurrentDictionary _loggers = new(); + private bool _disposed; + + /// + /// Creates a new . + /// + /// The notification writer used to send log messages to the MCP client. + /// + /// No level-filter delegate is accepted here. Level filtering is owned + /// by the logging framework's filter chain configured in Program.cs + /// (logging.AddFilter(logLevel => LogLevelProvider.ShouldLog(logLevel))), + /// which runs before any provider's logger is invoked. Threading the + /// same delegate through this provider would just call the same shared + /// state twice and obscure where filtering actually happens. + /// + public McpLoggerProvider(IMcpLogNotificationWriter writer) + { + _writer = writer ?? throw new ArgumentNullException(nameof(writer)); + } + + /// + /// + /// Thrown when the provider has already been disposed. Returning a fresh + /// after disposal would hand the caller a stale + /// reference to and bypass any teardown the host + /// performed (e.g. flushing the underlying stdout writer). This matches + /// the behavior of the framework ConsoleLoggerProvider. + /// + public ILogger CreateLogger(string categoryName) + { + ObjectDisposedException.ThrowIf(_disposed, this); + return _loggers.GetOrAdd(categoryName, name => new McpLogger(name, _writer)); + } + + /// + public void Dispose() + { + if (!_disposed) + { + _loggers.Clear(); + _disposed = true; + } + } +} diff --git a/src/Core/Telemetry/McpLogLevelConverter.cs b/src/Core/Telemetry/McpLogLevelConverter.cs new file mode 100644 index 0000000000..f8c4484e2c --- /dev/null +++ b/src/Core/Telemetry/McpLogLevelConverter.cs @@ -0,0 +1,70 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using Microsoft.Extensions.Logging; + +namespace Azure.DataApiBuilder.Core.Telemetry +{ + /// + /// Provides conversion between .NET LogLevel and MCP log level strings. + /// MCP log levels: debug, info, notice, warning, error, critical, alert, emergency. + /// + /// + /// This class centralizes the mapping between MCP and .NET log levels, + /// avoiding duplication across DynamicLogLevelProvider and McpLogNotificationWriter. + /// + public static class McpLogLevelConverter + { + /// + /// Maps MCP log level strings to Microsoft.Extensions.Logging.LogLevel. + /// + private static readonly Dictionary _mcpToLogLevel = new(StringComparer.OrdinalIgnoreCase) + { + ["debug"] = LogLevel.Debug, + ["info"] = LogLevel.Information, + ["notice"] = LogLevel.Information, // MCP "notice" maps to Information (no direct equivalent) + ["warning"] = LogLevel.Warning, + ["error"] = LogLevel.Error, + ["critical"] = LogLevel.Critical, + ["alert"] = LogLevel.Critical, // MCP "alert" maps to Critical + ["emergency"] = LogLevel.Critical // MCP "emergency" maps to Critical + }; + + /// + /// Converts an MCP log level string to a .NET LogLevel. + /// + /// The MCP log level string (e.g., "debug", "info", "warning"). + /// The converted LogLevel if successful. + /// True if the conversion was successful; false if the MCP level was not recognized. + public static bool TryConvertFromMcp(string mcpLevel, out LogLevel logLevel) + { + if (string.IsNullOrWhiteSpace(mcpLevel)) + { + logLevel = LogLevel.None; + return false; + } + + return _mcpToLogLevel.TryGetValue(mcpLevel, out logLevel); + } + + /// + /// Converts a .NET LogLevel to an MCP log level string. + /// + /// The .NET LogLevel to convert. + /// The MCP log level string. + public static string ConvertToMcp(LogLevel logLevel) + { + return logLevel switch + { + LogLevel.Trace => "debug", + LogLevel.Debug => "debug", + LogLevel.Information => "info", + LogLevel.Warning => "warning", + LogLevel.Error => "error", + LogLevel.Critical => "critical", + LogLevel.None => "debug", // Default to debug for None + _ => "info" + }; + } + } +} diff --git a/src/Service.Tests/UnitTests/DynamicLogLevelProviderTests.cs b/src/Service.Tests/UnitTests/DynamicLogLevelProviderTests.cs index 131155c171..779277c2b5 100644 --- a/src/Service.Tests/UnitTests/DynamicLogLevelProviderTests.cs +++ b/src/Service.Tests/UnitTests/DynamicLogLevelProviderTests.cs @@ -3,6 +3,7 @@ #nullable enable +using System.Threading.Tasks; using Azure.DataApiBuilder.Service.Telemetry; using Microsoft.Extensions.Logging; using Microsoft.VisualStudio.TestTools.UnitTesting; @@ -53,5 +54,86 @@ public void ShouldLog_ReturnsCorrectResult() Assert.IsTrue(provider.ShouldLog(LogLevel.Error)); Assert.IsFalse(provider.ShouldLog(LogLevel.Debug)); } + + /// + /// Concurrency safety: many threads racing on + /// and + /// must not + /// produce torn reads, exceptions, or corrupted state. The provider + /// stores state in atomic-sized fields (enum + bools), so reads/writes + /// are inherently safe; this test guards against future regressions + /// (e.g., introducing a non-atomic field) by exercising the contract. + /// + [TestMethod] + public void UpdateFromMcp_UnderConcurrency_StaysConsistent() + { + // Arrange + DynamicLogLevelProvider provider = new(); + provider.SetInitialLogLevel(LogLevel.Information, isCliOverridden: false, isConfigOverridden: false); + + const int iterations = 5_000; + + // Act — alternating writers + readers in parallel. + Task writers = Task.Run(() => + { + string[] levels = new[] { "debug", "info", "warning", "error" }; + for (int i = 0; i < iterations; i++) + { + provider.UpdateFromMcp(levels[i % levels.Length]); + } + }); + + Task readers = Task.Run(() => + { + for (int i = 0; i < iterations; i++) + { + // Read every property — must never throw or read + // an enum value outside the LogLevel range. + LogLevel current = provider.CurrentLogLevel; + bool _ = provider.ShouldLog(LogLevel.Information); + Assert.IsTrue( + current >= LogLevel.Trace && current <= LogLevel.None, + $"CurrentLogLevel out of range: {(int)current}"); + } + }); + + // Assert — both tasks complete cleanly. + Task.WaitAll(new[] { writers, readers }, millisecondsTimeout: 5_000); + Assert.IsTrue(writers.IsCompletedSuccessfully, $"Writers task failed: {writers.Exception?.Message}"); + Assert.IsTrue(readers.IsCompletedSuccessfully, $"Readers task failed: {readers.Exception?.Message}"); + + // Final state is one of the four levels — exact value is + // race-dependent but it must be a valid level. + Assert.IsTrue( + provider.CurrentLogLevel == LogLevel.Debug || + provider.CurrentLogLevel == LogLevel.Information || + provider.CurrentLogLevel == LogLevel.Warning || + provider.CurrentLogLevel == LogLevel.Error, + $"Unexpected final level: {provider.CurrentLogLevel}"); + } + + /// + /// CLI override is sticky: once the CLI flag pins the level, no number + /// of MCP logging/setLevel requests (even concurrent) may change + /// . Validates the + /// precedence guarantee under contention. + /// + [TestMethod] + public void UpdateFromMcp_CliOverride_StaysStickyUnderConcurrency() + { + // Arrange — CLI pins level to Warning. + DynamicLogLevelProvider provider = new(); + provider.SetInitialLogLevel(LogLevel.Warning, isCliOverridden: true, isConfigOverridden: false); + + // Act — flood with MCP setLevel requests trying to flip it. + Parallel.For(0, 2_000, _ => + { + bool changed = provider.UpdateFromMcp("debug"); + Assert.IsFalse(changed, "CLI override must block all MCP changes."); + }); + + // Assert — level never moved off Warning. + Assert.AreEqual(LogLevel.Warning, provider.CurrentLogLevel); + } } } diff --git a/src/Service.Tests/UnitTests/McpLogNotificationTests.cs b/src/Service.Tests/UnitTests/McpLogNotificationTests.cs new file mode 100644 index 0000000000..7f38def9c3 --- /dev/null +++ b/src/Service.Tests/UnitTests/McpLogNotificationTests.cs @@ -0,0 +1,232 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +#nullable enable + +using System.IO; +using System.Text; +using System.Text.Json; +using Azure.DataApiBuilder.Mcp.Core; +using Azure.DataApiBuilder.Mcp.Telemetry; +using Microsoft.Extensions.Logging; +using Microsoft.VisualStudio.TestTools.UnitTesting; + +namespace Azure.DataApiBuilder.Service.Tests.UnitTests +{ + /// + /// Unit tests for the MCP logging notification components. + /// + [TestClass] + public class McpLogNotificationTests + { + [TestMethod] + public void McpLogNotificationWriter_IsEnabledFalseByDefault() + { + // Arrange & Act + McpLogNotificationWriter writer = new(); + + // Assert + Assert.IsFalse(writer.IsEnabled); + } + + [TestMethod] + public void McpLogNotificationWriter_CanBeEnabled() + { + // Arrange + McpLogNotificationWriter writer = new() + { + // Act + IsEnabled = true + }; + + // Assert + Assert.IsTrue(writer.IsEnabled); + } + + [TestMethod] + public void McpLogger_IsEnabledReturnsFalse_WhenWriterDisabled() + { + // Arrange + McpLogNotificationWriter writer = new() + { + IsEnabled = false + }; + McpLogger logger = new("TestCategory", writer); + + // Act & Assert + Assert.IsFalse(logger.IsEnabled(LogLevel.Information)); + Assert.IsFalse(logger.IsEnabled(LogLevel.Error)); + } + + [TestMethod] + public void McpLogger_IsEnabledReturnsTrue_WhenWriterEnabled() + { + // Arrange + McpLogNotificationWriter writer = new() + { + IsEnabled = true + }; + McpLogger logger = new("TestCategory", writer); + + // Act & Assert + Assert.IsTrue(logger.IsEnabled(LogLevel.Information)); + Assert.IsTrue(logger.IsEnabled(LogLevel.Error)); + } + + [TestMethod] + public void McpLogger_NoneLevel_AlwaysReturnsFalse() + { + // Arrange + McpLogNotificationWriter writer = new() + { + IsEnabled = true + }; + McpLogger logger = new("TestCategory", writer); + + // Act & Assert - LogLevel.None should always be disabled + Assert.IsFalse(logger.IsEnabled(LogLevel.None)); + } + + [TestMethod] + public void McpLoggerProvider_CreatesSameLoggerForSameCategory() + { + // Arrange + McpLogNotificationWriter writer = new(); + McpLoggerProvider provider = new(writer); + + // Act + ILogger logger1 = provider.CreateLogger("TestCategory"); + ILogger logger2 = provider.CreateLogger("TestCategory"); + ILogger logger3 = provider.CreateLogger("OtherCategory"); + + // Assert - same category should return same logger instance + Assert.AreSame(logger1, logger2); + Assert.AreNotSame(logger1, logger3); + } + + /// + /// When constructed without a backing + /// (the unit-test default), + /// must be a silent no-op rather than throwing a NullReferenceException. + /// This guards the safety net for tests and any non-stdio host that + /// constructs the type without a stdout sink. + /// + [TestMethod] + public void WriteNotification_DoesNotThrow_WhenStdoutWriterIsNull() + { + // Arrange — null stdout writer is the default ctor path. + McpLogNotificationWriter writer = new() + { + IsEnabled = true + }; + + // Act & Assert — must not throw. + writer.WriteNotification(LogLevel.Information, "TestCategory", "hello"); + } + + /// + /// End-to-end of the notification pipeline: when wired to a real + /// , + /// must emit a single, well-formed MCP notifications/message + /// frame (jsonrpc + method + params { level, logger, data }). + /// Verifies framing contract + exact JSON structure. + /// + [TestMethod] + public void WriteNotification_EmitsValidMcpFrame() + { + // Arrange — back the stdout writer with an in-memory stream so we + // can inspect the exact bytes emitted. + using MemoryStream ms = new(); + StreamWriter inner = new( + ms, + new UTF8Encoding(encoderShouldEmitUTF8Identifier: false), + bufferSize: -1, + leaveOpen: true) + { + AutoFlush = true + }; + using McpStdoutWriter stdout = new(inner); + McpLogNotificationWriter writer = new(stdout) + { + IsEnabled = true + }; + + // Act + writer.WriteNotification(LogLevel.Warning, "MyApp.SomeService", "uh oh"); + + // Assert — single line, valid JSON, correct shape. + ms.Position = 0; + string content = new StreamReader(ms).ReadToEnd().TrimEnd(); + Assert.IsFalse(string.IsNullOrEmpty(content), "No frame written."); + + using JsonDocument doc = JsonDocument.Parse(content); + JsonElement root = doc.RootElement; + + Assert.AreEqual("2.0", root.GetProperty("jsonrpc").GetString()); + Assert.AreEqual("notifications/message", root.GetProperty("method").GetString()); + + JsonElement paramsElem = root.GetProperty("params"); + Assert.AreEqual("warning", paramsElem.GetProperty("level").GetString(), + "MCP level should be lowercase per spec."); + Assert.AreEqual("MyApp.SomeService", paramsElem.GetProperty("logger").GetString()); + Assert.AreEqual("uh oh", paramsElem.GetProperty("data").GetString()); + } + + /// + /// Single-source-of-truth gate: when the writer's IsEnabled is + /// false, must return false + /// for any non-None level so the logging framework never invokes the + /// formatter. This protects callers from doing unnecessary string work. + /// + [TestMethod] + public void McpLogger_GateBlocksAllLevels_WhenWriterDisabled() + { + // Arrange + McpLogNotificationWriter writer = new() + { + IsEnabled = false + }; + McpLogger logger = new("Cat", writer); + + // Act & Assert — every non-None level is blocked when writer is off. + foreach (LogLevel level in new[] + { + LogLevel.Trace, LogLevel.Debug, LogLevel.Information, + LogLevel.Warning, LogLevel.Error, LogLevel.Critical + }) + { + Assert.IsFalse(logger.IsEnabled(level), + $"Level {level} should be disabled when writer.IsEnabled=false."); + } + } + + /// + /// Flipping at runtime + /// (which is what MCP logging/setLevel does indirectly) must + /// take immediate effect on subsequent + /// calls. Confirms the property is the live single source of truth and + /// not cached anywhere downstream. + /// + [TestMethod] + public void McpLogger_RespectsRuntimeIsEnabledFlip() + { + // Arrange — start disabled. + McpLogNotificationWriter writer = new() + { + IsEnabled = false + }; + McpLogger logger = new("Cat", writer); + Assert.IsFalse(logger.IsEnabled(LogLevel.Information)); + + // Act — flip the gate on. + writer.IsEnabled = true; + + // Assert — logger reflects the new state immediately. + Assert.IsTrue(logger.IsEnabled(LogLevel.Information)); + + // Flip back off — must propagate again. + writer.IsEnabled = false; + Assert.IsFalse(logger.IsEnabled(LogLevel.Information)); + } + } +} diff --git a/src/Service.Tests/UnitTests/McpStdoutWriterTests.cs b/src/Service.Tests/UnitTests/McpStdoutWriterTests.cs new file mode 100644 index 0000000000..420b6842a6 --- /dev/null +++ b/src/Service.Tests/UnitTests/McpStdoutWriterTests.cs @@ -0,0 +1,229 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +#nullable enable + +using System; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.IO; +using System.Linq; +using System.Text; +using System.Threading; +using System.Threading.Tasks; +using Azure.DataApiBuilder.Mcp.Core; +using Microsoft.VisualStudio.TestTools.UnitTesting; + +namespace Azure.DataApiBuilder.Service.Tests.UnitTests +{ + /// + /// Unit tests for — the process-wide, + /// lock-protected owner of the MCP stdio JSON-RPC channel. + /// Validates concurrency safety (no torn lines), disposal idempotency, + /// and post-dispose write semantics. + /// + [TestClass] + public class McpStdoutWriterTests + { + /// + /// Calling twice must not throw. + /// This guards against double-shutdown (e.g. ProcessExit hook running + /// alongside DI container disposal). + /// + [TestMethod] + public void Dispose_IsIdempotent() + { + // Arrange — back the writer with an in-memory stream so we never + // touch the real stdout from a unit test. leaveOpen:true so the + // 'using' on MemoryStream is the sole owner. + using MemoryStream ms = new(); + StreamWriter inner = new( + ms, + new UTF8Encoding(encoderShouldEmitUTF8Identifier: false), + bufferSize: -1, + leaveOpen: true); + McpStdoutWriter writer = new(inner); + + // Act + writer.Dispose(); + writer.Dispose(); // Second call must be a no-op. + + // Assert — no exception thrown is the success criterion. + } + + /// + /// After , further + /// calls must silently no-op. + /// Late writes can occur from queued logger callbacks during shutdown, + /// and they must not throw ObjectDisposedException through the + /// logging pipeline. + /// + [TestMethod] + public void WriteLine_AfterDispose_IsNoOp() + { + // Arrange — leaveOpen:true so disposing the writer doesn't close + // the MemoryStream we still need to inspect afterwards. + using MemoryStream ms = new(); + StreamWriter inner = new( + ms, + new UTF8Encoding(encoderShouldEmitUTF8Identifier: false), + bufferSize: -1, + leaveOpen: true) + { + AutoFlush = true + }; + McpStdoutWriter writer = new(inner); + + // Write one line so we have a known baseline length. + writer.WriteLine("before-dispose"); + long lengthBeforeDispose = ms.Length; + + // Act — dispose then attempt to write. + writer.Dispose(); + writer.WriteLine("after-dispose"); // Must not throw. + + // Assert — stream length must not have grown after dispose. + Assert.AreEqual( + expected: lengthBeforeDispose, + actual: ms.Length, + message: "WriteLine after Dispose must be a silent no-op."); + } + + /// + /// Heavy concurrency test that exercises the lock contract: + /// many threads calling in + /// parallel must produce intact, non-interleaved lines on the stream. + /// This is the core invariant that protects the MCP JSON-RPC channel + /// from byte-level corruption when notifications and responses race. + /// + [TestMethod] + public void WriteLine_FromManyThreads_ProducesIntactNonInterleavedLines() + { + // Arrange + const int threadCount = 16; + const int writesPerThread = 500; + const int totalWrites = threadCount * writesPerThread; + + using MemoryStream ms = new(); + StreamWriter inner = new( + ms, + new UTF8Encoding(encoderShouldEmitUTF8Identifier: false), + bufferSize: -1, + leaveOpen: true) + { + AutoFlush = true + }; + using McpStdoutWriter writer = new(inner); + + // Each thread emits a unique, recognizable payload. + // Format: "thread-{id}-write-{sequence}" — easy to parse and tally. + ConcurrentBag expected = new(); + + // Act — fan out N parallel producers. + Parallel.For(0, threadCount, threadId => + { + for (int i = 0; i < writesPerThread; i++) + { + string line = $"thread-{threadId:D2}-write-{i:D4}"; + expected.Add(line); + writer.WriteLine(line); + } + }); + + // Flush by disposing the underlying writer reference (the + // McpStdoutWriter wraps it; dispose forwards to inner). + writer.Dispose(); + + // Assert — read back and verify line-by-line integrity. + ms.Position = 0; + using StreamReader reader = new(ms, new UTF8Encoding(encoderShouldEmitUTF8Identifier: false)); + string content = reader.ReadToEnd(); + string[] lines = content.Split(new[] { Environment.NewLine }, StringSplitOptions.RemoveEmptyEntries); + + // 1. All writes accounted for — no dropped or extra lines. + Assert.AreEqual( + expected: totalWrites, + actual: lines.Length, + message: $"Expected {totalWrites} intact lines but got {lines.Length}."); + + // 2. Every line matches the exact pattern (no torn writes). + // A torn write would produce a malformed line that doesn't fit + // the "thread-XX-write-YYYY" template. + string[] malformed = lines + .Where(l => !System.Text.RegularExpressions.Regex.IsMatch(l, @"^thread-\d{2}-write-\d{4}$")) + .ToArray(); + Assert.AreEqual( + expected: 0, + actual: malformed.Length, + message: $"Found {malformed.Length} torn/interleaved lines. First: '{(malformed.Length > 0 ? malformed[0] : string.Empty)}'."); + + // 3. The set of emitted lines exactly matches the set produced by threads. + HashSet actualSet = new(lines); + HashSet expectedSet = new(expected); + Assert.IsTrue( + actualSet.SetEquals(expectedSet), + "Set of emitted lines does not match set produced by threads."); + } + + /// + /// A late racing with concurrent + /// writes must be safe: writes that win the lock first complete; writes + /// that arrive after Dispose silently no-op. No exception, no crash. + /// + [TestMethod] + public void Dispose_DuringConcurrentWrites_DoesNotThrow() + { + // Arrange + using MemoryStream ms = new(); + StreamWriter inner = new( + ms, + new UTF8Encoding(encoderShouldEmitUTF8Identifier: false), + bufferSize: -1, + leaveOpen: true) + { + AutoFlush = true + }; + McpStdoutWriter writer = new(inner); + + // Act — kick off a producer in the background and dispose mid-flight. + Task producer = Task.Run(() => + { + for (int i = 0; i < 1000; i++) + { + writer.WriteLine($"line-{i:D4}"); + } + }); + + // Small delay to let some writes happen, then dispose. + Thread.Sleep(5); + writer.Dispose(); + + // Wait for the producer to finish — must not throw. + producer.Wait(TimeSpan.FromSeconds(5)); + + // Assert + Assert.IsTrue(producer.IsCompletedSuccessfully, + $"Producer task did not complete successfully. Status: {producer.Status}, Exception: {producer.Exception?.Message}"); + } + + /// + /// The default constructor must NOT open the real stdout stream. + /// This is critical: DI registers the writer eagerly during host build, + /// and we must not interfere with stdout until the first actual write. + /// (Verified indirectly: constructing then disposing must not throw, + /// even when stdout is in an unusual state during test execution.) + /// + [TestMethod] + public void Constructor_DoesNotOpenStdout() + { + // Act — default ctor must complete without touching stdout. + McpStdoutWriter writer = new(); + + // Dispose must also be safe when no write ever occurred (lazy init + // means _writer is still null inside Dispose). + writer.Dispose(); + + // Assert — no exception is the success criterion. + } + } +} diff --git a/src/Service/Program.cs b/src/Service/Program.cs index 11fb9f5cc7..2963f5278b 100644 --- a/src/Service/Program.cs +++ b/src/Service/Program.cs @@ -12,6 +12,8 @@ using Azure.DataApiBuilder.Config; using Azure.DataApiBuilder.Config.ObjectModel; using Azure.DataApiBuilder.Core.Telemetry; +using Azure.DataApiBuilder.Mcp.Core; +using Azure.DataApiBuilder.Mcp.Telemetry; using Azure.DataApiBuilder.Service.Exceptions; using Azure.DataApiBuilder.Service.Telemetry; using Azure.DataApiBuilder.Service.Utilities; @@ -38,6 +40,34 @@ public class Program public static bool IsHttpsRedirectionDisabled { get; private set; } public static DynamicLogLevelProvider LogLevelProvider = new(); + /// + /// Process-wide owner of the MCP stdio process's stdout stream. + /// Both the JSON-RPC server () and the notification writer share this + /// instance so concurrent writes to stdout are serialized through one lock. + /// + private static readonly McpStdoutWriter _mcpStdoutWriter = new(); + + /// + /// MCP log notification writer for sending logs to MCP clients via notifications/message. + /// Created once and shared between logging pipeline and MCP server. + /// + private static readonly McpLogNotificationWriter _mcpNotificationWriter = new(_mcpStdoutWriter); + + /// + /// Ensures the shared MCP stdout writer is flushed and disposed on + /// process exit. The writer is registered with DI as an externally + /// owned singleton instance (AddSingleton(instance)), and + /// does not + /// dispose externally constructed instances. Hooking + /// guarantees the underlying + /// is released even when the host shuts + /// down via signal or unhandled exception path. + /// + static Program() + { + AppDomain.CurrentDomain.ProcessExit += (_, _) => _mcpStdoutWriter.Dispose(); + } + public static void Main(string[] args) { bool runMcpStdio = McpStdioHelper.ShouldRunMcpStdio(args, out string? mcpRole); @@ -138,6 +168,13 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st { services.AddSingleton(LogLevelProvider); services.AddSingleton(LogLevelProvider); + + // For MCP stdio mode, register the notification writer for sending logs to MCP clients + if (runMcpStdio) + { + services.AddSingleton(_mcpStdoutWriter); + services.AddSingleton(_mcpNotificationWriter); + } }) .ConfigureLogging(logging => { @@ -147,6 +184,10 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st // For non-MCP mode, use the configured level directly. if (runMcpStdio) { + // Clear all default providers (Console, Debug, EventSource, EventLog) + // to ensure stdout remains pure JSON-RPC for MCP protocol compliance. + logging.ClearProviders(); + // Allow all logs through framework, filter dynamically logging.SetMinimumLevel(LogLevel.Trace); } @@ -159,6 +200,12 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st logging.AddFilter(logLevel => LogLevelProvider.ShouldLog(logLevel)); logging.AddFilter("Microsoft", logLevel => LogLevelProvider.ShouldLog(logLevel)); logging.AddFilter("Microsoft.Hosting.Lifetime", logLevel => LogLevelProvider.ShouldLog(logLevel)); + + // For MCP stdio mode, add the MCP logger provider to send logs as notifications + if (runMcpStdio) + { + logging.AddProvider(new McpLoggerProvider(_mcpNotificationWriter)); + } }) .ConfigureWebHostDefaults(webBuilder => { diff --git a/src/Service/Telemetry/DynamicLogLevelProvider.cs b/src/Service/Telemetry/DynamicLogLevelProvider.cs index 517f901546..8e29086f52 100644 --- a/src/Service/Telemetry/DynamicLogLevelProvider.cs +++ b/src/Service/Telemetry/DynamicLogLevelProvider.cs @@ -1,5 +1,3 @@ -using System; -using System.Collections.Generic; using Azure.DataApiBuilder.Config.ObjectModel; using Azure.DataApiBuilder.Core.Telemetry; using Microsoft.Extensions.Logging; @@ -11,22 +9,6 @@ namespace Azure.DataApiBuilder.Service.Telemetry /// public class DynamicLogLevelProvider : ILogLevelController { - /// - /// Maps MCP log level strings to Microsoft.Extensions.Logging.LogLevel. - /// MCP levels: debug, info, notice, warning, error, critical, alert, emergency. - /// - private static readonly Dictionary _mcpLevelMapping = new(StringComparer.OrdinalIgnoreCase) - { - ["debug"] = LogLevel.Debug, - ["info"] = LogLevel.Information, - ["notice"] = LogLevel.Information, // MCP "notice" maps to Information (no direct equivalent) - ["warning"] = LogLevel.Warning, - ["error"] = LogLevel.Error, - ["critical"] = LogLevel.Critical, - ["alert"] = LogLevel.Critical, // MCP "alert" maps to Critical - ["emergency"] = LogLevel.Critical // MCP "emergency" maps to Critical - }; - public LogLevel CurrentLogLevel { get; private set; } public bool IsCliOverridden { get; private set; } @@ -98,12 +80,7 @@ public bool UpdateFromMcp(string mcpLevel) return false; } - if (string.IsNullOrWhiteSpace(mcpLevel)) - { - return false; - } - - if (_mcpLevelMapping.TryGetValue(mcpLevel, out LogLevel logLevel)) + if (McpLogLevelConverter.TryConvertFromMcp(mcpLevel, out LogLevel logLevel)) { CurrentLogLevel = logLevel; return true; From de85dd1e93371cf457f03709e2775d4722209d98 Mon Sep 17 00:00:00 2001 From: Ruben Cerna Date: Wed, 6 May 2026 19:50:35 -0700 Subject: [PATCH 3/3] Fix merge conflict in test --- .../Configuration/RuntimeConfigLoaderTests.cs | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/src/Service.Tests/Configuration/RuntimeConfigLoaderTests.cs b/src/Service.Tests/Configuration/RuntimeConfigLoaderTests.cs index df5e2d584d..7c972a2d43 100644 --- a/src/Service.Tests/Configuration/RuntimeConfigLoaderTests.cs +++ b/src/Service.Tests/Configuration/RuntimeConfigLoaderTests.cs @@ -277,7 +277,19 @@ public async Task ChildConfigLoadFailureHaltsParentConfigLoading() { Console.SetError(sw); + ILoggerFactory loggerFactory = LoggerFactory.Create(builder => + { + builder.SetMinimumLevel(LogLevel.Trace); + builder.AddConsole(options => + { + options.LogToStandardErrorThreshold = LogLevel.Error; + }); + }); + ILogger logger = loggerFactory.CreateLogger(); + + loader.SetLogger(logger); bool loaded = loader.TryLoadConfig("dab-config.json", out RuntimeConfig _); + await TestHelper.DelayTask(() => string.IsNullOrWhiteSpace(sw.ToString())); string error = sw.ToString(); Assert.IsFalse(loaded, "Config loading should fail when a child config file exists but cannot be parsed.");