diff --git a/src/Azure.DataApiBuilder.Mcp/Core/McpStdioServer.cs b/src/Azure.DataApiBuilder.Mcp/Core/McpStdioServer.cs index 0588050fb0..8ec232981a 100644 --- a/src/Azure.DataApiBuilder.Mcp/Core/McpStdioServer.cs +++ b/src/Azure.DataApiBuilder.Mcp/Core/McpStdioServer.cs @@ -8,6 +8,7 @@ using Azure.DataApiBuilder.Core.Configurations; using Azure.DataApiBuilder.Core.Telemetry; using Azure.DataApiBuilder.Mcp.Model; +using Azure.DataApiBuilder.Mcp.Telemetry; using Azure.DataApiBuilder.Mcp.Utils; using Microsoft.AspNetCore.Http; using Microsoft.Extensions.Configuration; @@ -26,6 +27,7 @@ public class McpStdioServer : IMcpStdioServer { private readonly McpToolRegistry _toolRegistry; private readonly IServiceProvider _serviceProvider; + private readonly McpStdoutWriter _stdoutWriter; private readonly string _protocolVersion; private const int MAX_LINE_LENGTH = 1024 * 1024; // 1 MB limit for incoming JSON-RPC requests @@ -35,6 +37,11 @@ public McpStdioServer(McpToolRegistry toolRegistry, IServiceProvider serviceProv _toolRegistry = toolRegistry ?? throw new ArgumentNullException(nameof(toolRegistry)); _serviceProvider = serviceProvider ?? throw new ArgumentNullException(nameof(serviceProvider)); + // Resolve the shared stdout writer so JSON-RPC responses and + // notifications/message frames are serialized through one lock. + // Falls back to a fresh instance if DI didn't register one (defensive). + _stdoutWriter = _serviceProvider.GetService() ?? new McpStdoutWriter(); + // Allow protocol version to be configured via IConfiguration, using centralized defaults. IConfiguration? configuration = _serviceProvider.GetService(); _protocolVersion = McpProtocolDefaults.ResolveProtocolVersion(configuration); @@ -47,16 +54,14 @@ public McpStdioServer(McpToolRegistry toolRegistry, IServiceProvider serviceProv /// A task representing the asynchronous operation. public async Task RunAsync(CancellationToken cancellationToken) { - // Use UTF-8 WITHOUT BOM + // Use UTF-8 WITHOUT BOM for stdin. Stdout is owned by McpStdoutWriter, + // which serializes all writes from McpStdioServer and the MCP logging + // pipeline so JSON-RPC frames cannot interleave at the byte level. UTF8Encoding utf8NoBom = new(encoderShouldEmitUTF8Identifier: false); using Stream stdin = Console.OpenStandardInput(); - using Stream stdout = Console.OpenStandardOutput(); using StreamReader reader = new(stdin, utf8NoBom); - using StreamWriter writer = new(stdout, utf8NoBom) { AutoFlush = true }; - // Redirect Console.Out to use our writer - Console.SetOut(writer); while (!cancellationToken.IsCancellationRequested) { string? line = await reader.ReadLineAsync(cancellationToken); @@ -298,16 +303,31 @@ private void HandleSetLogLevel(JsonElement? id, JsonElement root) // If CLI or Config overrode, this returns false but we still return success to the client bool updated = logLevelController.UpdateFromMcp(level); - // If MCP successfully changed the log level to something other than "none", - // ensure Console.Error is pointing to the real stderr (not TextWriter.Null). - // This handles the case where MCP stdio mode started with LogLevel.None (quiet startup) - // and the client later enables logging via logging/setLevel. + // Determine if logging is enabled (level != "none") + // Note: Even if CLI/Config overrode the level, we still enable notifications + // when the client requests logging. They'll get logs at the overridden level. bool isLoggingEnabled = !string.Equals(level, "none", StringComparison.OrdinalIgnoreCase); + + // Only restore stderr when this MCP call actually changed the effective level. + // If CLI/Config overrode (updated == false), stderr is already in the correct state: + // - CLI/Config level == "none": stderr was redirected to TextWriter.Null at startup + // and must stay that way; restoring it would re-introduce noisy output even + // though the operator explicitly asked for silence. + // - CLI/Config level != "none": stderr was never redirected, so restoring is a no-op. if (updated && isLoggingEnabled) { RestoreStderrIfNeeded(); } + // Enable or disable MCP log notifications based on the requested level + // When CLI/Config overrode, notifications are still enabled - client asked for logs, + // they just get them at the CLI/Config level instead of the requested level. + IMcpLogNotificationWriter? notificationWriter = _serviceProvider.GetService(); + if (notificationWriter != null) + { + notificationWriter.IsEnabled = isLoggingEnabled; + } + // Always return success (empty result object) per MCP spec WriteResult(id, new { }); } @@ -539,39 +559,41 @@ private static string SafeToString(object obj) /// /// Writes a JSON-RPC result response to the standard output. + /// Routed through so the write is serialized + /// with notifications/message frames from the logging pipeline. /// /// The request identifier extracted from the incoming JSON-RPC request. Used to correlate the response with the request. /// The result object to include in the response. - private static void WriteResult(JsonElement? id, object resultObject) + private void WriteResult(JsonElement? id, object resultObject) { var response = new { - jsonrpc = "2.0", + jsonrpc = McpStdioJsonRpcErrorCodes.JSON_RPC_VERSION, id = id.HasValue ? GetIdValue(id.Value) : null, result = resultObject }; - string json = JsonSerializer.Serialize(response); - Console.Out.WriteLine(json); + _stdoutWriter.WriteLine(JsonSerializer.Serialize(response)); } /// /// Writes a JSON-RPC error response to the standard output. + /// Routed through so the write is serialized + /// with notifications/message frames from the logging pipeline. /// /// The request identifier extracted from the incoming JSON-RPC request. Used to correlate the response with the request. /// The error code. /// The error message. - private static void WriteError(JsonElement? id, int code, string message) + private void WriteError(JsonElement? id, int code, string message) { var errorObj = new { - jsonrpc = "2.0", + jsonrpc = McpStdioJsonRpcErrorCodes.JSON_RPC_VERSION, id = id.HasValue ? GetIdValue(id.Value) : null, error = new { code, message } }; - string json = JsonSerializer.Serialize(errorObj); - Console.Out.WriteLine(json); + _stdoutWriter.WriteLine(JsonSerializer.Serialize(errorObj)); } /// diff --git a/src/Azure.DataApiBuilder.Mcp/Core/McpStdoutWriter.cs b/src/Azure.DataApiBuilder.Mcp/Core/McpStdoutWriter.cs new file mode 100644 index 0000000000..7a30fccec3 --- /dev/null +++ b/src/Azure.DataApiBuilder.Mcp/Core/McpStdoutWriter.cs @@ -0,0 +1,101 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System.Text; + +namespace Azure.DataApiBuilder.Mcp.Core +{ + /// + /// Process-wide owner of the MCP stdio server's stdout stream. + /// + /// In MCP stdio mode, stdout is the JSON-RPC channel and is shared by + /// multiple writers — JSON-RPC responses from + /// and asynchronous notifications/message frames from the logging + /// pipeline. Without coordination, two writers calling WriteLine + /// concurrently can interleave at the byte level and corrupt the channel. + /// + /// This class wraps the underlying and serializes + /// every write through a single lock so JSON-RPC frames stay intact. + /// Registered as a singleton in DI for MCP stdio mode; instantiated lazily + /// (the underlying stream is opened on the first write) so non-MCP code + /// paths and unit tests can construct the type without side effects. + /// + public sealed class McpStdoutWriter : IDisposable + { + private readonly object _lock = new(); + private TextWriter? _writer; + private bool _disposed; + + /// + /// Production constructor. The underlying stdout stream is opened + /// lazily on the first call. + /// + public McpStdoutWriter() + { + } + + /// + /// Test-only constructor that injects a pre-built writer so unit tests + /// can verify lock behavior, disposal semantics, and notification + /// framing without touching the real stdout stream. + /// + internal McpStdoutWriter(TextWriter writer) + { + _writer = writer ?? throw new ArgumentNullException(nameof(writer)); + } + + /// + /// Writes a single line to stdout under a process-wide lock so + /// concurrent JSON-RPC responses and notifications cannot interleave. + /// No-op after . + /// + public void WriteLine(string line) + { + lock (_lock) + { + if (_disposed) + { + return; + } + + EnsureInitialized(); + _writer!.WriteLine(line); + } + } + + public void Dispose() + { + lock (_lock) + { + if (_disposed) + { + return; + } + + _disposed = true; + _writer?.Dispose(); + _writer = null; + } + } + + private void EnsureInitialized() + { + if (_writer is not null) + { + return; + } + + // Opening the raw stdout stream bypasses any Console.SetOut(...) + // redirection. This is intentional: in MCP stdio mode, Program.cs + // redirects Console.Out to a sink (TextWriter.Null or stderr) so + // stray Console.WriteLine calls from third-party code cannot + // corrupt the JSON-RPC channel. Only this class - and only via + // WriteLine() - is allowed to write to the real stdout. + Stream stdout = Console.OpenStandardOutput(); + _writer = new StreamWriter(stdout, new UTF8Encoding(encoderShouldEmitUTF8Identifier: false)) + { + AutoFlush = true + }; + } + } +} diff --git a/src/Azure.DataApiBuilder.Mcp/Model/McpStdioJsonRpcErrorCodes.cs b/src/Azure.DataApiBuilder.Mcp/Model/McpStdioJsonRpcErrorCodes.cs index 3bac194068..07e5c2c9b5 100644 --- a/src/Azure.DataApiBuilder.Mcp/Model/McpStdioJsonRpcErrorCodes.cs +++ b/src/Azure.DataApiBuilder.Mcp/Model/McpStdioJsonRpcErrorCodes.cs @@ -7,6 +7,11 @@ namespace Azure.DataApiBuilder.Mcp.Model /// internal static class McpStdioJsonRpcErrorCodes { + /// + /// JSON-RPC protocol version. + /// + public const string JSON_RPC_VERSION = "2.0"; + /// /// Invalid JSON was received by the server. /// An error occurred on the server while parsing the JSON text. diff --git a/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLogNotificationWriter.cs b/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLogNotificationWriter.cs new file mode 100644 index 0000000000..1a2ba3cb9a --- /dev/null +++ b/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLogNotificationWriter.cs @@ -0,0 +1,114 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System.Text.Json; +using Azure.DataApiBuilder.Core.Telemetry; +using Azure.DataApiBuilder.Mcp.Core; +using Azure.DataApiBuilder.Mcp.Model; +using Microsoft.Extensions.Logging; + +namespace Azure.DataApiBuilder.Mcp.Telemetry; + +/// +/// Writes log messages as MCP `notifications/message` JSON-RPC notifications. +/// This allows MCP clients (like MCP Inspector) to receive log output in real-time. +/// +/// +/// MCP spec: https://modelcontextprotocol.io/specification/2025-11-05/server/utilities/logging +/// The notification format is: +/// +/// { +/// "jsonrpc": "2.0", +/// "method": "notifications/message", +/// "params": { +/// "level": "info", +/// "logger": "CategoryName", +/// "data": "The log message" +/// } +/// } +/// +/// All writes are routed through the shared so +/// notifications cannot interleave with JSON-RPC responses written by +/// . +/// +public class McpLogNotificationWriter : IMcpLogNotificationWriter +{ + private readonly McpStdoutWriter? _stdoutWriter; + + /// + /// Creates a notification writer that writes through the shared stdout + /// writer. The shared writer serializes notifications with JSON-RPC + /// responses so concurrent writes do not interleave on the wire. + /// + /// + /// Shared stdout writer. May be null for unit tests that do not + /// exercise the write path; in that case + /// becomes a no-op. + /// + public McpLogNotificationWriter(McpStdoutWriter? stdoutWriter = null) + { + _stdoutWriter = stdoutWriter; + } + + /// + /// Gets or sets whether MCP log notifications are enabled. This is the + /// single source of truth for whether notifications flow to the client; + /// it is consulted by so that + /// the gate is enforced once, at log time, before any formatter work runs. + /// intentionally does not re-check this + /// flag — callers must gate via . + /// + public bool IsEnabled { get; set; } + + /// + /// Writes a log message as an MCP notification. The caller is responsible + /// for gating on ; already + /// does this in its override. + /// + /// The .NET log level. + /// The logger category (typically class name). + /// The formatted log message. + public void WriteNotification(LogLevel logLevel, string categoryName, string message) + { + // No IsEnabled check here: the gate lives in McpLogger.IsEnabled so + // that we have a single source of truth and a single check site. + // The _stdoutWriter null check remains as a defensive guard for unit + // tests that construct the writer without a backing stdout. + if (_stdoutWriter is null) + { + return; + } + + string mcpLevel = McpLogLevelConverter.ConvertToMcp(logLevel); + + var notification = new + { + jsonrpc = McpStdioJsonRpcErrorCodes.JSON_RPC_VERSION, + method = "notifications/message", + @params = new + { + level = mcpLevel, + logger = categoryName, + data = message + } + }; + + _stdoutWriter.WriteLine(JsonSerializer.Serialize(notification)); + } +} + +/// +/// Interface for MCP log notification writing. +/// +public interface IMcpLogNotificationWriter +{ + /// + /// Gets or sets whether MCP log notifications are enabled. + /// + bool IsEnabled { get; set; } + + /// + /// Writes a log message as an MCP notification. + /// + void WriteNotification(LogLevel logLevel, string categoryName, string message); +} diff --git a/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLogger.cs b/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLogger.cs new file mode 100644 index 0000000000..0338431a1d --- /dev/null +++ b/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLogger.cs @@ -0,0 +1,126 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using Microsoft.Extensions.Logging; + +namespace Azure.DataApiBuilder.Mcp.Telemetry; + +/// +/// ILogger implementation that sends log messages as MCP notifications. +/// +public class McpLogger : ILogger +{ + private readonly string _categoryName; + private readonly IMcpLogNotificationWriter _writer; + + /// + /// Creates a new . + /// + /// + /// No level-filter delegate is accepted here. Level filtering is the job + /// of the logging framework's filter chain (configured via + /// ILoggingBuilder.AddFilter(...) in Program.cs); by the time the + /// framework calls , those filters have already passed. + /// Re-running the same delegate against the same shared + /// LogLevelProvider state would produce the same answer and only + /// add a maintenance trap (a future contributor could mistake the per- + /// logger filter for an independent gate). + /// + public McpLogger(string categoryName, IMcpLogNotificationWriter writer) + { + _categoryName = categoryName ?? throw new ArgumentNullException(nameof(categoryName)); + _writer = writer ?? throw new ArgumentNullException(nameof(writer)); + } + + /// + /// + /// Scopes are intentionally not supported in this implementation. The MCP + /// notifications/message frame has no first-class structured field + /// for scope state, and we currently emit a plain string in params.data. + /// + /// TODO: Consider implementing + /// on so scope state can be flowed through + /// from the host (e.g. ASP.NET Core request scopes, activity correlation + /// IDs). When done, this method should return a real scope tied to an + /// , and + /// should walk + /// + /// to append (or attach as a structured field on the JSON-RPC notification) + /// the active scope chain. See aaronburtle's review on PR for context. + /// + public IDisposable? BeginScope(TState state) where TState : notnull + { + // Scopes are not supported for MCP notifications. See remarks above + // for the path to add ISupportExternalScope support in the future. + return NullScope.Instance; + } + + /// + /// + /// Returns true when the writer is enabled (the MCP client has issued + /// logging/setLevel with a non-"none" value) and the requested + /// level is not . Per-level filtering is + /// applied upstream by the framework's filter chain in Program.cs. + /// + public bool IsEnabled(LogLevel logLevel) + { + return _writer.IsEnabled && logLevel != LogLevel.None; + } + + /// + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) + { + if (!IsEnabled(logLevel)) + { + return; + } + + if (formatter == null) + { + throw new ArgumentNullException(nameof(formatter)); + } + + string message = formatter(state, exception); + + if (string.IsNullOrEmpty(message) && exception == null) + { + return; + } + + // Append the full exception details (type, message, stack trace, and + // any inner exceptions) using Exception.ToString(). This matches the + // behavior of the built-in console/Serilog formatters and is what MCP + // clients (e.g. MCP Inspector) render for log notifications. Dropping + // the stack trace would make production triage from a remote client + // effectively impossible. ToString() walks InnerException chains and + // flattens AggregateException, so no manual recursion is needed. + if (exception != null) + { + string separator = string.IsNullOrEmpty(message) ? string.Empty : Environment.NewLine; + message = $"{message}{separator}{exception}"; + } + + _writer.WriteNotification(logLevel, _categoryName, message); + } + + /// + /// Null scope implementation for when scopes are not supported. + /// + private sealed class NullScope : IDisposable + { + public static NullScope Instance { get; } = new NullScope(); + + private NullScope() + { + } + + public void Dispose() + { + } + } +} diff --git a/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLoggerProvider.cs b/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLoggerProvider.cs new file mode 100644 index 0000000000..e86120462c --- /dev/null +++ b/src/Azure.DataApiBuilder.Mcp/Telemetry/McpLoggerProvider.cs @@ -0,0 +1,58 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System.Collections.Concurrent; +using Microsoft.Extensions.Logging; + +namespace Azure.DataApiBuilder.Mcp.Telemetry; + +/// +/// Logger provider that creates McpLogger instances for sending logs as MCP notifications. +/// +public class McpLoggerProvider : ILoggerProvider +{ + private readonly IMcpLogNotificationWriter _writer; + private readonly ConcurrentDictionary _loggers = new(); + private bool _disposed; + + /// + /// Creates a new . + /// + /// The notification writer used to send log messages to the MCP client. + /// + /// No level-filter delegate is accepted here. Level filtering is owned + /// by the logging framework's filter chain configured in Program.cs + /// (logging.AddFilter(logLevel => LogLevelProvider.ShouldLog(logLevel))), + /// which runs before any provider's logger is invoked. Threading the + /// same delegate through this provider would just call the same shared + /// state twice and obscure where filtering actually happens. + /// + public McpLoggerProvider(IMcpLogNotificationWriter writer) + { + _writer = writer ?? throw new ArgumentNullException(nameof(writer)); + } + + /// + /// + /// Thrown when the provider has already been disposed. Returning a fresh + /// after disposal would hand the caller a stale + /// reference to and bypass any teardown the host + /// performed (e.g. flushing the underlying stdout writer). This matches + /// the behavior of the framework ConsoleLoggerProvider. + /// + public ILogger CreateLogger(string categoryName) + { + ObjectDisposedException.ThrowIf(_disposed, this); + return _loggers.GetOrAdd(categoryName, name => new McpLogger(name, _writer)); + } + + /// + public void Dispose() + { + if (!_disposed) + { + _loggers.Clear(); + _disposed = true; + } + } +} diff --git a/src/Core/Telemetry/McpLogLevelConverter.cs b/src/Core/Telemetry/McpLogLevelConverter.cs new file mode 100644 index 0000000000..f8c4484e2c --- /dev/null +++ b/src/Core/Telemetry/McpLogLevelConverter.cs @@ -0,0 +1,70 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using Microsoft.Extensions.Logging; + +namespace Azure.DataApiBuilder.Core.Telemetry +{ + /// + /// Provides conversion between .NET LogLevel and MCP log level strings. + /// MCP log levels: debug, info, notice, warning, error, critical, alert, emergency. + /// + /// + /// This class centralizes the mapping between MCP and .NET log levels, + /// avoiding duplication across DynamicLogLevelProvider and McpLogNotificationWriter. + /// + public static class McpLogLevelConverter + { + /// + /// Maps MCP log level strings to Microsoft.Extensions.Logging.LogLevel. + /// + private static readonly Dictionary _mcpToLogLevel = new(StringComparer.OrdinalIgnoreCase) + { + ["debug"] = LogLevel.Debug, + ["info"] = LogLevel.Information, + ["notice"] = LogLevel.Information, // MCP "notice" maps to Information (no direct equivalent) + ["warning"] = LogLevel.Warning, + ["error"] = LogLevel.Error, + ["critical"] = LogLevel.Critical, + ["alert"] = LogLevel.Critical, // MCP "alert" maps to Critical + ["emergency"] = LogLevel.Critical // MCP "emergency" maps to Critical + }; + + /// + /// Converts an MCP log level string to a .NET LogLevel. + /// + /// The MCP log level string (e.g., "debug", "info", "warning"). + /// The converted LogLevel if successful. + /// True if the conversion was successful; false if the MCP level was not recognized. + public static bool TryConvertFromMcp(string mcpLevel, out LogLevel logLevel) + { + if (string.IsNullOrWhiteSpace(mcpLevel)) + { + logLevel = LogLevel.None; + return false; + } + + return _mcpToLogLevel.TryGetValue(mcpLevel, out logLevel); + } + + /// + /// Converts a .NET LogLevel to an MCP log level string. + /// + /// The .NET LogLevel to convert. + /// The MCP log level string. + public static string ConvertToMcp(LogLevel logLevel) + { + return logLevel switch + { + LogLevel.Trace => "debug", + LogLevel.Debug => "debug", + LogLevel.Information => "info", + LogLevel.Warning => "warning", + LogLevel.Error => "error", + LogLevel.Critical => "critical", + LogLevel.None => "debug", // Default to debug for None + _ => "info" + }; + } + } +} diff --git a/src/Service.Tests/UnitTests/DynamicLogLevelProviderTests.cs b/src/Service.Tests/UnitTests/DynamicLogLevelProviderTests.cs index 131155c171..779277c2b5 100644 --- a/src/Service.Tests/UnitTests/DynamicLogLevelProviderTests.cs +++ b/src/Service.Tests/UnitTests/DynamicLogLevelProviderTests.cs @@ -3,6 +3,7 @@ #nullable enable +using System.Threading.Tasks; using Azure.DataApiBuilder.Service.Telemetry; using Microsoft.Extensions.Logging; using Microsoft.VisualStudio.TestTools.UnitTesting; @@ -53,5 +54,86 @@ public void ShouldLog_ReturnsCorrectResult() Assert.IsTrue(provider.ShouldLog(LogLevel.Error)); Assert.IsFalse(provider.ShouldLog(LogLevel.Debug)); } + + /// + /// Concurrency safety: many threads racing on + /// and + /// must not + /// produce torn reads, exceptions, or corrupted state. The provider + /// stores state in atomic-sized fields (enum + bools), so reads/writes + /// are inherently safe; this test guards against future regressions + /// (e.g., introducing a non-atomic field) by exercising the contract. + /// + [TestMethod] + public void UpdateFromMcp_UnderConcurrency_StaysConsistent() + { + // Arrange + DynamicLogLevelProvider provider = new(); + provider.SetInitialLogLevel(LogLevel.Information, isCliOverridden: false, isConfigOverridden: false); + + const int iterations = 5_000; + + // Act — alternating writers + readers in parallel. + Task writers = Task.Run(() => + { + string[] levels = new[] { "debug", "info", "warning", "error" }; + for (int i = 0; i < iterations; i++) + { + provider.UpdateFromMcp(levels[i % levels.Length]); + } + }); + + Task readers = Task.Run(() => + { + for (int i = 0; i < iterations; i++) + { + // Read every property — must never throw or read + // an enum value outside the LogLevel range. + LogLevel current = provider.CurrentLogLevel; + bool _ = provider.ShouldLog(LogLevel.Information); + Assert.IsTrue( + current >= LogLevel.Trace && current <= LogLevel.None, + $"CurrentLogLevel out of range: {(int)current}"); + } + }); + + // Assert — both tasks complete cleanly. + Task.WaitAll(new[] { writers, readers }, millisecondsTimeout: 5_000); + Assert.IsTrue(writers.IsCompletedSuccessfully, $"Writers task failed: {writers.Exception?.Message}"); + Assert.IsTrue(readers.IsCompletedSuccessfully, $"Readers task failed: {readers.Exception?.Message}"); + + // Final state is one of the four levels — exact value is + // race-dependent but it must be a valid level. + Assert.IsTrue( + provider.CurrentLogLevel == LogLevel.Debug || + provider.CurrentLogLevel == LogLevel.Information || + provider.CurrentLogLevel == LogLevel.Warning || + provider.CurrentLogLevel == LogLevel.Error, + $"Unexpected final level: {provider.CurrentLogLevel}"); + } + + /// + /// CLI override is sticky: once the CLI flag pins the level, no number + /// of MCP logging/setLevel requests (even concurrent) may change + /// . Validates the + /// precedence guarantee under contention. + /// + [TestMethod] + public void UpdateFromMcp_CliOverride_StaysStickyUnderConcurrency() + { + // Arrange — CLI pins level to Warning. + DynamicLogLevelProvider provider = new(); + provider.SetInitialLogLevel(LogLevel.Warning, isCliOverridden: true, isConfigOverridden: false); + + // Act — flood with MCP setLevel requests trying to flip it. + Parallel.For(0, 2_000, _ => + { + bool changed = provider.UpdateFromMcp("debug"); + Assert.IsFalse(changed, "CLI override must block all MCP changes."); + }); + + // Assert — level never moved off Warning. + Assert.AreEqual(LogLevel.Warning, provider.CurrentLogLevel); + } } } diff --git a/src/Service.Tests/UnitTests/McpLogNotificationTests.cs b/src/Service.Tests/UnitTests/McpLogNotificationTests.cs new file mode 100644 index 0000000000..7f38def9c3 --- /dev/null +++ b/src/Service.Tests/UnitTests/McpLogNotificationTests.cs @@ -0,0 +1,232 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +#nullable enable + +using System.IO; +using System.Text; +using System.Text.Json; +using Azure.DataApiBuilder.Mcp.Core; +using Azure.DataApiBuilder.Mcp.Telemetry; +using Microsoft.Extensions.Logging; +using Microsoft.VisualStudio.TestTools.UnitTesting; + +namespace Azure.DataApiBuilder.Service.Tests.UnitTests +{ + /// + /// Unit tests for the MCP logging notification components. + /// + [TestClass] + public class McpLogNotificationTests + { + [TestMethod] + public void McpLogNotificationWriter_IsEnabledFalseByDefault() + { + // Arrange & Act + McpLogNotificationWriter writer = new(); + + // Assert + Assert.IsFalse(writer.IsEnabled); + } + + [TestMethod] + public void McpLogNotificationWriter_CanBeEnabled() + { + // Arrange + McpLogNotificationWriter writer = new() + { + // Act + IsEnabled = true + }; + + // Assert + Assert.IsTrue(writer.IsEnabled); + } + + [TestMethod] + public void McpLogger_IsEnabledReturnsFalse_WhenWriterDisabled() + { + // Arrange + McpLogNotificationWriter writer = new() + { + IsEnabled = false + }; + McpLogger logger = new("TestCategory", writer); + + // Act & Assert + Assert.IsFalse(logger.IsEnabled(LogLevel.Information)); + Assert.IsFalse(logger.IsEnabled(LogLevel.Error)); + } + + [TestMethod] + public void McpLogger_IsEnabledReturnsTrue_WhenWriterEnabled() + { + // Arrange + McpLogNotificationWriter writer = new() + { + IsEnabled = true + }; + McpLogger logger = new("TestCategory", writer); + + // Act & Assert + Assert.IsTrue(logger.IsEnabled(LogLevel.Information)); + Assert.IsTrue(logger.IsEnabled(LogLevel.Error)); + } + + [TestMethod] + public void McpLogger_NoneLevel_AlwaysReturnsFalse() + { + // Arrange + McpLogNotificationWriter writer = new() + { + IsEnabled = true + }; + McpLogger logger = new("TestCategory", writer); + + // Act & Assert - LogLevel.None should always be disabled + Assert.IsFalse(logger.IsEnabled(LogLevel.None)); + } + + [TestMethod] + public void McpLoggerProvider_CreatesSameLoggerForSameCategory() + { + // Arrange + McpLogNotificationWriter writer = new(); + McpLoggerProvider provider = new(writer); + + // Act + ILogger logger1 = provider.CreateLogger("TestCategory"); + ILogger logger2 = provider.CreateLogger("TestCategory"); + ILogger logger3 = provider.CreateLogger("OtherCategory"); + + // Assert - same category should return same logger instance + Assert.AreSame(logger1, logger2); + Assert.AreNotSame(logger1, logger3); + } + + /// + /// When constructed without a backing + /// (the unit-test default), + /// must be a silent no-op rather than throwing a NullReferenceException. + /// This guards the safety net for tests and any non-stdio host that + /// constructs the type without a stdout sink. + /// + [TestMethod] + public void WriteNotification_DoesNotThrow_WhenStdoutWriterIsNull() + { + // Arrange — null stdout writer is the default ctor path. + McpLogNotificationWriter writer = new() + { + IsEnabled = true + }; + + // Act & Assert — must not throw. + writer.WriteNotification(LogLevel.Information, "TestCategory", "hello"); + } + + /// + /// End-to-end of the notification pipeline: when wired to a real + /// , + /// must emit a single, well-formed MCP notifications/message + /// frame (jsonrpc + method + params { level, logger, data }). + /// Verifies framing contract + exact JSON structure. + /// + [TestMethod] + public void WriteNotification_EmitsValidMcpFrame() + { + // Arrange — back the stdout writer with an in-memory stream so we + // can inspect the exact bytes emitted. + using MemoryStream ms = new(); + StreamWriter inner = new( + ms, + new UTF8Encoding(encoderShouldEmitUTF8Identifier: false), + bufferSize: -1, + leaveOpen: true) + { + AutoFlush = true + }; + using McpStdoutWriter stdout = new(inner); + McpLogNotificationWriter writer = new(stdout) + { + IsEnabled = true + }; + + // Act + writer.WriteNotification(LogLevel.Warning, "MyApp.SomeService", "uh oh"); + + // Assert — single line, valid JSON, correct shape. + ms.Position = 0; + string content = new StreamReader(ms).ReadToEnd().TrimEnd(); + Assert.IsFalse(string.IsNullOrEmpty(content), "No frame written."); + + using JsonDocument doc = JsonDocument.Parse(content); + JsonElement root = doc.RootElement; + + Assert.AreEqual("2.0", root.GetProperty("jsonrpc").GetString()); + Assert.AreEqual("notifications/message", root.GetProperty("method").GetString()); + + JsonElement paramsElem = root.GetProperty("params"); + Assert.AreEqual("warning", paramsElem.GetProperty("level").GetString(), + "MCP level should be lowercase per spec."); + Assert.AreEqual("MyApp.SomeService", paramsElem.GetProperty("logger").GetString()); + Assert.AreEqual("uh oh", paramsElem.GetProperty("data").GetString()); + } + + /// + /// Single-source-of-truth gate: when the writer's IsEnabled is + /// false, must return false + /// for any non-None level so the logging framework never invokes the + /// formatter. This protects callers from doing unnecessary string work. + /// + [TestMethod] + public void McpLogger_GateBlocksAllLevels_WhenWriterDisabled() + { + // Arrange + McpLogNotificationWriter writer = new() + { + IsEnabled = false + }; + McpLogger logger = new("Cat", writer); + + // Act & Assert — every non-None level is blocked when writer is off. + foreach (LogLevel level in new[] + { + LogLevel.Trace, LogLevel.Debug, LogLevel.Information, + LogLevel.Warning, LogLevel.Error, LogLevel.Critical + }) + { + Assert.IsFalse(logger.IsEnabled(level), + $"Level {level} should be disabled when writer.IsEnabled=false."); + } + } + + /// + /// Flipping at runtime + /// (which is what MCP logging/setLevel does indirectly) must + /// take immediate effect on subsequent + /// calls. Confirms the property is the live single source of truth and + /// not cached anywhere downstream. + /// + [TestMethod] + public void McpLogger_RespectsRuntimeIsEnabledFlip() + { + // Arrange — start disabled. + McpLogNotificationWriter writer = new() + { + IsEnabled = false + }; + McpLogger logger = new("Cat", writer); + Assert.IsFalse(logger.IsEnabled(LogLevel.Information)); + + // Act — flip the gate on. + writer.IsEnabled = true; + + // Assert — logger reflects the new state immediately. + Assert.IsTrue(logger.IsEnabled(LogLevel.Information)); + + // Flip back off — must propagate again. + writer.IsEnabled = false; + Assert.IsFalse(logger.IsEnabled(LogLevel.Information)); + } + } +} diff --git a/src/Service.Tests/UnitTests/McpStdoutWriterTests.cs b/src/Service.Tests/UnitTests/McpStdoutWriterTests.cs new file mode 100644 index 0000000000..420b6842a6 --- /dev/null +++ b/src/Service.Tests/UnitTests/McpStdoutWriterTests.cs @@ -0,0 +1,229 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +#nullable enable + +using System; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.IO; +using System.Linq; +using System.Text; +using System.Threading; +using System.Threading.Tasks; +using Azure.DataApiBuilder.Mcp.Core; +using Microsoft.VisualStudio.TestTools.UnitTesting; + +namespace Azure.DataApiBuilder.Service.Tests.UnitTests +{ + /// + /// Unit tests for — the process-wide, + /// lock-protected owner of the MCP stdio JSON-RPC channel. + /// Validates concurrency safety (no torn lines), disposal idempotency, + /// and post-dispose write semantics. + /// + [TestClass] + public class McpStdoutWriterTests + { + /// + /// Calling twice must not throw. + /// This guards against double-shutdown (e.g. ProcessExit hook running + /// alongside DI container disposal). + /// + [TestMethod] + public void Dispose_IsIdempotent() + { + // Arrange — back the writer with an in-memory stream so we never + // touch the real stdout from a unit test. leaveOpen:true so the + // 'using' on MemoryStream is the sole owner. + using MemoryStream ms = new(); + StreamWriter inner = new( + ms, + new UTF8Encoding(encoderShouldEmitUTF8Identifier: false), + bufferSize: -1, + leaveOpen: true); + McpStdoutWriter writer = new(inner); + + // Act + writer.Dispose(); + writer.Dispose(); // Second call must be a no-op. + + // Assert — no exception thrown is the success criterion. + } + + /// + /// After , further + /// calls must silently no-op. + /// Late writes can occur from queued logger callbacks during shutdown, + /// and they must not throw ObjectDisposedException through the + /// logging pipeline. + /// + [TestMethod] + public void WriteLine_AfterDispose_IsNoOp() + { + // Arrange — leaveOpen:true so disposing the writer doesn't close + // the MemoryStream we still need to inspect afterwards. + using MemoryStream ms = new(); + StreamWriter inner = new( + ms, + new UTF8Encoding(encoderShouldEmitUTF8Identifier: false), + bufferSize: -1, + leaveOpen: true) + { + AutoFlush = true + }; + McpStdoutWriter writer = new(inner); + + // Write one line so we have a known baseline length. + writer.WriteLine("before-dispose"); + long lengthBeforeDispose = ms.Length; + + // Act — dispose then attempt to write. + writer.Dispose(); + writer.WriteLine("after-dispose"); // Must not throw. + + // Assert — stream length must not have grown after dispose. + Assert.AreEqual( + expected: lengthBeforeDispose, + actual: ms.Length, + message: "WriteLine after Dispose must be a silent no-op."); + } + + /// + /// Heavy concurrency test that exercises the lock contract: + /// many threads calling in + /// parallel must produce intact, non-interleaved lines on the stream. + /// This is the core invariant that protects the MCP JSON-RPC channel + /// from byte-level corruption when notifications and responses race. + /// + [TestMethod] + public void WriteLine_FromManyThreads_ProducesIntactNonInterleavedLines() + { + // Arrange + const int threadCount = 16; + const int writesPerThread = 500; + const int totalWrites = threadCount * writesPerThread; + + using MemoryStream ms = new(); + StreamWriter inner = new( + ms, + new UTF8Encoding(encoderShouldEmitUTF8Identifier: false), + bufferSize: -1, + leaveOpen: true) + { + AutoFlush = true + }; + using McpStdoutWriter writer = new(inner); + + // Each thread emits a unique, recognizable payload. + // Format: "thread-{id}-write-{sequence}" — easy to parse and tally. + ConcurrentBag expected = new(); + + // Act — fan out N parallel producers. + Parallel.For(0, threadCount, threadId => + { + for (int i = 0; i < writesPerThread; i++) + { + string line = $"thread-{threadId:D2}-write-{i:D4}"; + expected.Add(line); + writer.WriteLine(line); + } + }); + + // Flush by disposing the underlying writer reference (the + // McpStdoutWriter wraps it; dispose forwards to inner). + writer.Dispose(); + + // Assert — read back and verify line-by-line integrity. + ms.Position = 0; + using StreamReader reader = new(ms, new UTF8Encoding(encoderShouldEmitUTF8Identifier: false)); + string content = reader.ReadToEnd(); + string[] lines = content.Split(new[] { Environment.NewLine }, StringSplitOptions.RemoveEmptyEntries); + + // 1. All writes accounted for — no dropped or extra lines. + Assert.AreEqual( + expected: totalWrites, + actual: lines.Length, + message: $"Expected {totalWrites} intact lines but got {lines.Length}."); + + // 2. Every line matches the exact pattern (no torn writes). + // A torn write would produce a malformed line that doesn't fit + // the "thread-XX-write-YYYY" template. + string[] malformed = lines + .Where(l => !System.Text.RegularExpressions.Regex.IsMatch(l, @"^thread-\d{2}-write-\d{4}$")) + .ToArray(); + Assert.AreEqual( + expected: 0, + actual: malformed.Length, + message: $"Found {malformed.Length} torn/interleaved lines. First: '{(malformed.Length > 0 ? malformed[0] : string.Empty)}'."); + + // 3. The set of emitted lines exactly matches the set produced by threads. + HashSet actualSet = new(lines); + HashSet expectedSet = new(expected); + Assert.IsTrue( + actualSet.SetEquals(expectedSet), + "Set of emitted lines does not match set produced by threads."); + } + + /// + /// A late racing with concurrent + /// writes must be safe: writes that win the lock first complete; writes + /// that arrive after Dispose silently no-op. No exception, no crash. + /// + [TestMethod] + public void Dispose_DuringConcurrentWrites_DoesNotThrow() + { + // Arrange + using MemoryStream ms = new(); + StreamWriter inner = new( + ms, + new UTF8Encoding(encoderShouldEmitUTF8Identifier: false), + bufferSize: -1, + leaveOpen: true) + { + AutoFlush = true + }; + McpStdoutWriter writer = new(inner); + + // Act — kick off a producer in the background and dispose mid-flight. + Task producer = Task.Run(() => + { + for (int i = 0; i < 1000; i++) + { + writer.WriteLine($"line-{i:D4}"); + } + }); + + // Small delay to let some writes happen, then dispose. + Thread.Sleep(5); + writer.Dispose(); + + // Wait for the producer to finish — must not throw. + producer.Wait(TimeSpan.FromSeconds(5)); + + // Assert + Assert.IsTrue(producer.IsCompletedSuccessfully, + $"Producer task did not complete successfully. Status: {producer.Status}, Exception: {producer.Exception?.Message}"); + } + + /// + /// The default constructor must NOT open the real stdout stream. + /// This is critical: DI registers the writer eagerly during host build, + /// and we must not interfere with stdout until the first actual write. + /// (Verified indirectly: constructing then disposing must not throw, + /// even when stdout is in an unusual state during test execution.) + /// + [TestMethod] + public void Constructor_DoesNotOpenStdout() + { + // Act — default ctor must complete without touching stdout. + McpStdoutWriter writer = new(); + + // Dispose must also be safe when no write ever occurred (lazy init + // means _writer is still null inside Dispose). + writer.Dispose(); + + // Assert — no exception is the success criterion. + } + } +} diff --git a/src/Service/Program.cs b/src/Service/Program.cs index 11fb9f5cc7..2963f5278b 100644 --- a/src/Service/Program.cs +++ b/src/Service/Program.cs @@ -12,6 +12,8 @@ using Azure.DataApiBuilder.Config; using Azure.DataApiBuilder.Config.ObjectModel; using Azure.DataApiBuilder.Core.Telemetry; +using Azure.DataApiBuilder.Mcp.Core; +using Azure.DataApiBuilder.Mcp.Telemetry; using Azure.DataApiBuilder.Service.Exceptions; using Azure.DataApiBuilder.Service.Telemetry; using Azure.DataApiBuilder.Service.Utilities; @@ -38,6 +40,34 @@ public class Program public static bool IsHttpsRedirectionDisabled { get; private set; } public static DynamicLogLevelProvider LogLevelProvider = new(); + /// + /// Process-wide owner of the MCP stdio process's stdout stream. + /// Both the JSON-RPC server () and the notification writer share this + /// instance so concurrent writes to stdout are serialized through one lock. + /// + private static readonly McpStdoutWriter _mcpStdoutWriter = new(); + + /// + /// MCP log notification writer for sending logs to MCP clients via notifications/message. + /// Created once and shared between logging pipeline and MCP server. + /// + private static readonly McpLogNotificationWriter _mcpNotificationWriter = new(_mcpStdoutWriter); + + /// + /// Ensures the shared MCP stdout writer is flushed and disposed on + /// process exit. The writer is registered with DI as an externally + /// owned singleton instance (AddSingleton(instance)), and + /// does not + /// dispose externally constructed instances. Hooking + /// guarantees the underlying + /// is released even when the host shuts + /// down via signal or unhandled exception path. + /// + static Program() + { + AppDomain.CurrentDomain.ProcessExit += (_, _) => _mcpStdoutWriter.Dispose(); + } + public static void Main(string[] args) { bool runMcpStdio = McpStdioHelper.ShouldRunMcpStdio(args, out string? mcpRole); @@ -138,6 +168,13 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st { services.AddSingleton(LogLevelProvider); services.AddSingleton(LogLevelProvider); + + // For MCP stdio mode, register the notification writer for sending logs to MCP clients + if (runMcpStdio) + { + services.AddSingleton(_mcpStdoutWriter); + services.AddSingleton(_mcpNotificationWriter); + } }) .ConfigureLogging(logging => { @@ -147,6 +184,10 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st // For non-MCP mode, use the configured level directly. if (runMcpStdio) { + // Clear all default providers (Console, Debug, EventSource, EventLog) + // to ensure stdout remains pure JSON-RPC for MCP protocol compliance. + logging.ClearProviders(); + // Allow all logs through framework, filter dynamically logging.SetMinimumLevel(LogLevel.Trace); } @@ -159,6 +200,12 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st logging.AddFilter(logLevel => LogLevelProvider.ShouldLog(logLevel)); logging.AddFilter("Microsoft", logLevel => LogLevelProvider.ShouldLog(logLevel)); logging.AddFilter("Microsoft.Hosting.Lifetime", logLevel => LogLevelProvider.ShouldLog(logLevel)); + + // For MCP stdio mode, add the MCP logger provider to send logs as notifications + if (runMcpStdio) + { + logging.AddProvider(new McpLoggerProvider(_mcpNotificationWriter)); + } }) .ConfigureWebHostDefaults(webBuilder => { diff --git a/src/Service/Telemetry/DynamicLogLevelProvider.cs b/src/Service/Telemetry/DynamicLogLevelProvider.cs index 517f901546..8e29086f52 100644 --- a/src/Service/Telemetry/DynamicLogLevelProvider.cs +++ b/src/Service/Telemetry/DynamicLogLevelProvider.cs @@ -1,5 +1,3 @@ -using System; -using System.Collections.Generic; using Azure.DataApiBuilder.Config.ObjectModel; using Azure.DataApiBuilder.Core.Telemetry; using Microsoft.Extensions.Logging; @@ -11,22 +9,6 @@ namespace Azure.DataApiBuilder.Service.Telemetry /// public class DynamicLogLevelProvider : ILogLevelController { - /// - /// Maps MCP log level strings to Microsoft.Extensions.Logging.LogLevel. - /// MCP levels: debug, info, notice, warning, error, critical, alert, emergency. - /// - private static readonly Dictionary _mcpLevelMapping = new(StringComparer.OrdinalIgnoreCase) - { - ["debug"] = LogLevel.Debug, - ["info"] = LogLevel.Information, - ["notice"] = LogLevel.Information, // MCP "notice" maps to Information (no direct equivalent) - ["warning"] = LogLevel.Warning, - ["error"] = LogLevel.Error, - ["critical"] = LogLevel.Critical, - ["alert"] = LogLevel.Critical, // MCP "alert" maps to Critical - ["emergency"] = LogLevel.Critical // MCP "emergency" maps to Critical - }; - public LogLevel CurrentLogLevel { get; private set; } public bool IsCliOverridden { get; private set; } @@ -98,12 +80,7 @@ public bool UpdateFromMcp(string mcpLevel) return false; } - if (string.IsNullOrWhiteSpace(mcpLevel)) - { - return false; - } - - if (_mcpLevelMapping.TryGetValue(mcpLevel, out LogLevel logLevel)) + if (McpLogLevelConverter.TryConvertFromMcp(mcpLevel, out LogLevel logLevel)) { CurrentLogLevel = logLevel; return true;