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/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 4db38dede5..33453ddcab 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 c03025c584..1b17dacf03 100644 --- a/src/Cli.Tests/EnvironmentTests.cs +++ b/src/Cli.Tests/EnvironmentTests.cs @@ -162,7 +162,7 @@ public async Task FailureToStartEngineWhenEnvVarNamedWrong() $"-c {TEST_RUNTIME_CONFIG_FILE}" ); - string? output = await process.StandardError.ReadLineAsync(); + 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); 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 1dc609a0c8..e1bbc02e11 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!); @@ -285,6 +286,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 aff6983f22..8a416e26ca 100644 --- a/src/Cli/ConfigGenerator.cs +++ b/src/Cli/ConfigGenerator.cs @@ -2711,7 +2711,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; } @@ -2725,19 +2725,19 @@ public static bool TryStartEngineWithOptions(StartOptions options, FileSystemRun // duplicate output (stderr + stdout). if (!loader.IsParseErrorEmitted) { - _logger.LogError("Failed to parse the config file: {runtimeConfigFile}.", runtimeConfigFile); + 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; } @@ -2756,9 +2756,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; } @@ -2767,8 +2766,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) @@ -2870,16 +2889,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 e7bc30b758..1f9ef6d282 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 933fa6369e..016931bf62 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_"; @@ -97,8 +95,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; @@ -106,7 +103,6 @@ public FileSystemRuntimeConfigLoader( ConfigFilePath = GetFinalConfigFilePath(); _isCliLoader = isCliLoader; _logger = logger; - _logBuffer = logBuffer; } /// @@ -313,7 +309,7 @@ public bool TryLoadConfig( if (parseError is not null) { - Console.Error.WriteLine(parseError); + SendLogToBufferOrLogger(LogLevel.Error, parseError); IsParseErrorEmitted = true; } @@ -556,10 +552,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!); } /// @@ -572,7 +569,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 57d1695fab..41be045ecb 100644 --- a/src/Config/RuntimeConfigLoader.cs +++ b/src/Config/RuntimeConfigLoader.cs @@ -26,6 +26,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/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/Configuration/ConfigurationTests.cs b/src/Service.Tests/Configuration/ConfigurationTests.cs index 7b04ce8189..64e80141a0 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 d724753f97..7c972a2d43 100644 --- a/src/Service.Tests/Configuration/RuntimeConfigLoaderTests.cs +++ b/src/Service.Tests/Configuration/RuntimeConfigLoaderTests.cs @@ -11,6 +11,7 @@ using Azure.DataApiBuilder.Config; using Azure.DataApiBuilder.Config.Converters; using Azure.DataApiBuilder.Config.ObjectModel; +using Microsoft.Extensions.Logging; using Microsoft.VisualStudio.TestTools.UnitTesting; using Newtonsoft.Json.Linq; @@ -96,8 +97,21 @@ 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 _); + 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()), @@ -263,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."); 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/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.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..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); } @@ -157,6 +198,14 @@ 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)); + + // 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/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..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,28 +9,20 @@ 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; } 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 +30,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 +54,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) @@ -81,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; @@ -96,6 +90,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;