diff --git a/src/Aspire.AppHost/AppHost.cs b/src/Aspire.AppHost/AppHost.cs index 428b75a499..b51bffb922 100644 --- a/src/Aspire.AppHost/AppHost.cs +++ b/src/Aspire.AppHost/AppHost.cs @@ -1,4 +1,6 @@ +using Azure.DataApiBuilder.Product; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; var builder = DistributedApplication.CreateBuilder(args); @@ -15,7 +17,7 @@ if (string.IsNullOrEmpty(databaseConnectionString)) { - Console.WriteLine("No connection string provided, starting a local SQL Server container."); + BootstrapLogger.Instance.LogInformation("No connection string provided, starting a local SQL Server container."); sqlDbContainer = builder.AddSqlServer("sqlserver") .WithDataVolume() @@ -53,9 +55,9 @@ IResourceBuilder? postgresDB = null; - if (!string.IsNullOrEmpty(databaseConnectionString)) + if (string.IsNullOrEmpty(databaseConnectionString)) { - Console.WriteLine("No connection string provided, starting a local PostgreSQL container."); + BootstrapLogger.Instance.LogInformation("No connection string provided, starting a local PostgreSQL container."); postgresDB = builder.AddPostgres("postgres") .WithPgAdmin() diff --git a/src/Aspire.AppHost/Aspire.AppHost.csproj b/src/Aspire.AppHost/Aspire.AppHost.csproj index 4fbe70cdcf..c88765b35b 100644 --- a/src/Aspire.AppHost/Aspire.AppHost.csproj +++ b/src/Aspire.AppHost/Aspire.AppHost.csproj @@ -22,6 +22,11 @@ + + diff --git a/src/Cli.Tests/CustomLoggerTests.cs b/src/Cli.Tests/CustomLoggerTests.cs index cce73f0f75..0435af4169 100644 --- a/src/Cli.Tests/CustomLoggerTests.cs +++ b/src/Cli.Tests/CustomLoggerTests.cs @@ -1,6 +1,9 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. +using System.Globalization; +using System.Text.RegularExpressions; + namespace Cli.Tests; /// @@ -29,22 +32,35 @@ public void ResetMcpStaticState() Cli.Utils.ConfigLogLevel = LogLevel.Information; } + /// + /// Matches the timestamp prefix: exactly three fractional-second digits followed by a + /// literal 'Z'. The 'Z' immediately after the third digit is what rules out any + /// additional (e.g. microsecond) precision. + /// + private static readonly Regex _timestampPrefix = + new(@"^(?\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z) ", RegexOptions.Compiled); + /// /// Redirects Console.Out and Console.Error around - /// and returns whatever was written to each. Restores the original writers - /// on exit. + /// and returns whatever was written to each, together with the UTC instants + /// captured immediately before and after the action. Restores the original + /// writers on exit. /// - private static (string Stdout, string Stderr) CaptureConsole(Action action) + private static (string Stdout, string Stderr, DateTime Before, DateTime After) CaptureConsole(Action action) { TextWriter originalOut = Console.Out; TextWriter originalError = Console.Error; StringWriter stdout = new(); StringWriter stderr = new(); + DateTime before; + DateTime after; try { Console.SetOut(stdout); Console.SetError(stderr); + before = DateTime.UtcNow; action(); + after = DateTime.UtcNow; } finally { @@ -52,7 +68,61 @@ private static (string Stdout, string Stderr) CaptureConsole(Action action) Console.SetError(originalError); } - return (stdout.ToString(), stderr.ToString()); + return (stdout.ToString(), stderr.ToString(), before, after); + } + + /// + /// Asserts that begins with a timestamp that parses as UTC, + /// ends in 'Z', carries exactly three fractional-second digits, and falls inside the + /// window captured around the logging call. Returns the remainder of the entry so + /// callers can keep asserting on the severity label and message. + /// + private static string AssertStartsWithUtcTimestamp(string entry, DateTime before, DateTime after) + { + System.Text.RegularExpressions.Match match = _timestampPrefix.Match(entry); + Assert.IsTrue(match.Success, + $"Expected entry to start with an ISO 8601 UTC timestamp (yyyy-MM-ddTHH:mm:ss.fffZ) but got: '{entry}'"); + + string timestamp = match.Groups["ts"].Value; + Assert.IsTrue(timestamp.EndsWith("Z", StringComparison.Ordinal), + $"Timestamp '{timestamp}' must end with 'Z' to denote UTC."); + Assert.AreEqual(3, timestamp.Split('.')[1].TrimEnd('Z').Length, + $"Timestamp '{timestamp}' must carry exactly three fractional-second digits."); + + Assert.IsTrue( + DateTime.TryParseExact( + timestamp, + "yyyy-MM-dd'T'HH:mm:ss.fff'Z'", + CultureInfo.InvariantCulture, + DateTimeStyles.AssumeUniversal | DateTimeStyles.AdjustToUniversal, + out DateTime parsed), + $"Timestamp '{timestamp}' could not be parsed as an invariant-culture UTC value."); + Assert.AreEqual(DateTimeKind.Utc, parsed.Kind, "Parsed timestamp must be UTC."); + + // The emitted value is truncated to milliseconds, so compare against a + // millisecond-truncated lower bound. + DateTime lowerBound = before.AddTicks(-(before.Ticks % TimeSpan.TicksPerMillisecond)); + Assert.IsTrue(parsed >= lowerBound && parsed <= after, + $"Timestamp '{timestamp}' is outside the window [{lowerBound:O}, {after:O}] captured around the log call."); + + return entry[match.Length..]; + } + + /// + /// Asserts that every emitted line is timestamped (the CLI logger writes one line per + /// entry) and returns the lines with their timestamps stripped. + /// + private static string[] AssertEveryEntryTimestamped(string output, DateTime before, DateTime after) + { + string[] entries = output + .Split('\n') + .Select(line => line.TrimEnd('\r')) + .Where(line => !string.IsNullOrWhiteSpace(line)) + .ToArray(); + + Assert.IsTrue(entries.Length > 0, $"Expected at least one log entry but got: '{output}'"); + + return entries.Select(entry => AssertStartsWithUtcTimestamp(entry, before, after)).ToArray(); } private static ILogger NewLogger() => @@ -72,13 +142,15 @@ public void LogOutput_UsesAbbreviatedLogLevelLabels(LogLevel logLevel, string ex { const string Message = "test message"; - (string stdout, string stderr) = CaptureConsole(() => NewLogger().Log(logLevel, Message)); + (string stdout, string stderr, DateTime before, DateTime after) = + CaptureConsole(() => NewLogger().Log(logLevel, Message)); string actual = expectStderr ? stderr : stdout; string other = expectStderr ? stdout : stderr; - Assert.IsTrue(actual.StartsWith(expectedPrefix), - $"Expected output to start with '{expectedPrefix}' but got: '{actual}'"); + string[] withoutTimestamps = AssertEveryEntryTimestamped(actual, before, after); + Assert.IsTrue(withoutTimestamps.Single().StartsWith(expectedPrefix), + $"Expected the timestamp to be followed immediately by '{expectedPrefix}' but got: '{actual}'"); StringAssert.Contains(actual, Message); Assert.AreEqual(string.Empty, other, $"Did not expect output on the other stream but got: '{other}'"); @@ -94,7 +166,7 @@ public void Mcp_NoOverrides_SuppressesAllOutput() { Cli.Utils.IsMcpStdioMode = true; - (string stdout, string stderr) = CaptureConsole(() => + (string stdout, string stderr, _, _) = CaptureConsole(() => { ILogger logger = NewLogger(); logger.Log(LogLevel.Information, "info should not appear"); @@ -117,7 +189,7 @@ public void Mcp_CliOverride_WritesToStderrAndHonorsCliLevel() Cli.Utils.IsCliOverriding = true; Cli.Utils.CliLogLevel = LogLevel.Warning; - (string stdout, string stderr) = CaptureConsole(() => + (string stdout, string stderr, DateTime before, DateTime after) = CaptureConsole(() => { ILogger logger = NewLogger(); logger.Log(LogLevel.Information, "filtered info"); // below threshold @@ -129,6 +201,13 @@ public void Mcp_CliOverride_WritesToStderrAndHonorsCliLevel() Assert.IsFalse(stderr.Contains("filtered info"), $"Below-threshold log should be filtered. Got: '{stderr}'"); StringAssert.Contains(stderr, "warn: visible warn"); StringAssert.Contains(stderr, "fail: visible error"); + + // Every emitted entry - not just the first - must carry a UTC timestamp. + string[] withoutTimestamps = AssertEveryEntryTimestamped(stderr, before, after); + CollectionAssert.AreEqual( + new[] { "warn: visible warn", "fail: visible error" }, + withoutTimestamps, + $"Expected exactly the above-threshold entries, each prefixed by a timestamp. Got: '{stderr}'"); } /// @@ -143,16 +222,24 @@ public void Mcp_ConfigOverride_WritesToStderrAndHonorsConfigLevel() Cli.Utils.IsConfigOverriding = true; Cli.Utils.ConfigLogLevel = LogLevel.Information; - (string stdout, string stderr) = CaptureConsole(() => + (string stdout, string stderr, DateTime before, DateTime after) = CaptureConsole(() => { ILogger logger = NewLogger(); - logger.Log(LogLevel.Debug, "filtered debug"); // below threshold - logger.Log(LogLevel.Information, "visible info"); // at threshold + logger.Log(LogLevel.Debug, "filtered debug"); // below threshold + logger.Log(LogLevel.Information, "visible info"); // at threshold + logger.Log(LogLevel.Error, "visible error"); // above threshold }); Assert.AreEqual(string.Empty, stdout, "MCP mode must never write to stdout."); Assert.IsFalse(stderr.Contains("filtered debug"), $"Below-threshold log should be filtered. Got: '{stderr}'"); StringAssert.Contains(stderr, "info: visible info"); + + // Every emitted entry - not just the first - must carry a UTC timestamp. + string[] withoutTimestamps = AssertEveryEntryTimestamped(stderr, before, after); + CollectionAssert.AreEqual( + new[] { "info: visible info", "fail: visible error" }, + withoutTimestamps, + $"Expected exactly the above-threshold entries, each prefixed by a timestamp. Got: '{stderr}'"); } /// @@ -168,7 +255,7 @@ public void Mcp_CliOverridePrecedesConfigOverride() Cli.Utils.IsConfigOverriding = true; Cli.Utils.ConfigLogLevel = LogLevel.Information; - (_, string stderr) = CaptureConsole(() => + (_, string stderr, _, _) = CaptureConsole(() => { ILogger logger = NewLogger(); logger.Log(LogLevel.Information, "filtered by CLI Warning"); diff --git a/src/Cli/CustomLoggerProvider.cs b/src/Cli/CustomLoggerProvider.cs index a4625b0924..99a596df6f 100644 --- a/src/Cli/CustomLoggerProvider.cs +++ b/src/Cli/CustomLoggerProvider.cs @@ -1,6 +1,8 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. +using System.Globalization; +using Azure.DataApiBuilder.Product; using Microsoft.Extensions.Logging; /// @@ -25,6 +27,8 @@ public ILogger CreateLogger(string categoryName) public class CustomConsoleLogger : ILogger { + private const string UTC_TIMESTAMP_FORMAT = BootstrapLogger.UTC_TIMESTAMP_FORMAT; + private readonly LogLevel _minimumLogLevel; // Minimum LogLevel for CLI output. @@ -124,13 +128,14 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except // Apply colors so the abbreviation matches the visual style of engine logs. // try/finally guarantees the original colors are restored even if Write throws, // otherwise the console would be left tinted (e.g. red on error) for subsequent output. + string mcpTimestamp = DateTime.UtcNow.ToString(UTC_TIMESTAMP_FORMAT, CultureInfo.InvariantCulture); ConsoleColor mcpOriginalForeGroundColor = Console.ForegroundColor; ConsoleColor mcpOriginalBackGroundColor = Console.BackgroundColor; try { Console.ForegroundColor = _logLevelToForeGroundConsoleColorMap.GetValueOrDefault(logLevel, ConsoleColor.White); Console.BackgroundColor = _logLevelToBackGroundConsoleColorMap.GetValueOrDefault(logLevel, ConsoleColor.Black); - Console.Error.Write($"{mcpAbbreviation}:"); + Console.Error.Write($"{mcpTimestamp} {mcpAbbreviation}:"); } finally { @@ -153,6 +158,7 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except } TextWriter writer = logLevel >= LogLevel.Error ? Console.Error : Console.Out; + string timestamp = DateTime.UtcNow.ToString(UTC_TIMESTAMP_FORMAT, CultureInfo.InvariantCulture); // try/finally guarantees the original colors are restored even if Write throws, // otherwise the console would be left tinted (e.g. red on error) for subsequent output. ConsoleColor originalForeGroundColor = Console.ForegroundColor; @@ -161,7 +167,7 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except { Console.ForegroundColor = _logLevelToForeGroundConsoleColorMap.GetValueOrDefault(logLevel, ConsoleColor.White); Console.BackgroundColor = _logLevelToBackGroundConsoleColorMap.GetValueOrDefault(logLevel, ConsoleColor.Black); - writer.Write($"{abbreviation}:"); + writer.Write($"{timestamp} {abbreviation}:"); } finally { diff --git a/src/Cli/Program.cs b/src/Cli/Program.cs index faba1ee6d5..8983eeee93 100644 --- a/src/Cli/Program.cs +++ b/src/Cli/Program.cs @@ -3,6 +3,7 @@ using System.IO.Abstractions; using Azure.DataApiBuilder.Config; +using Azure.DataApiBuilder.Product; using Cli.Commands; using CommandLine; using Microsoft.Extensions.Logging; @@ -59,6 +60,9 @@ private static void ParseEarlyFlags(string[] args) if (string.Equals(arg, "--mcp-stdio", StringComparison.OrdinalIgnoreCase)) { Utils.IsMcpStdioMode = true; + + // stdout is reserved for the JSON-RPC protocol stream. + BootstrapLogger.WriteAllOutputToStandardError = true; } else if (string.Equals(arg, "--log-level", StringComparison.OrdinalIgnoreCase) && i + 1 < args.Length) { diff --git a/src/Config/ConfigFileWatcher.cs b/src/Config/ConfigFileWatcher.cs index e1afb39838..4867fc10bf 100644 --- a/src/Config/ConfigFileWatcher.cs +++ b/src/Config/ConfigFileWatcher.cs @@ -3,6 +3,8 @@ using System.IO.Abstractions; using Azure.DataApiBuilder.Config.Utilities; +using Azure.DataApiBuilder.Product; +using Microsoft.Extensions.Logging; namespace Azure.DataApiBuilder.Config; @@ -109,17 +111,17 @@ private void OnConfigFileChange(object sender, FileSystemEventArgs e) catch (AggregateException ex) { // Need to remove the dependencies in startup on the RuntimeConfigProvider - // before we can have an ILogger here. + // before we can have an injected ILogger here. foreach (Exception exception in ex.InnerExceptions) { - Console.WriteLine("Unable to hot reload configuration file due to " + exception.Message); + BootstrapLogger.Instance.LogWarning("Unable to hot reload configuration file due to " + exception.Message); } } catch (Exception ex) { // Need to remove the dependencies in startup on the RuntimeConfigProvider - // before we can have an ILogger here. - Console.WriteLine("Unable to hot reload configuration file due to " + ex.Message); + // before we can have an injected ILogger here. + BootstrapLogger.Instance.LogWarning("Unable to hot reload configuration file due to " + ex.Message); } } diff --git a/src/Config/FileSystemRuntimeConfigLoader.cs b/src/Config/FileSystemRuntimeConfigLoader.cs index e3529c696f..a5eee855d7 100644 --- a/src/Config/FileSystemRuntimeConfigLoader.cs +++ b/src/Config/FileSystemRuntimeConfigLoader.cs @@ -9,6 +9,7 @@ using Azure.DataApiBuilder.Config.Converters; using Azure.DataApiBuilder.Config.ObjectModel; using Azure.DataApiBuilder.Config.Utilities; +using Azure.DataApiBuilder.Product; using Azure.DataApiBuilder.Service.Exceptions; using Microsoft.Extensions.Logging; @@ -181,8 +182,8 @@ private bool TrySetupConfigFileWatcher() catch (Exception ex) { // Need to remove the dependencies in startup on the RuntimeConfigProvider - // before we can have an ILogger here. - Console.WriteLine($"Attempt to configure config file watcher for hot reload failed due to: {ex.Message}."); + // before we can have an injected ILogger here. + (_logger as ILogger ?? BootstrapLogger.Instance).LogWarning($"Attempt to configure config file watcher for hot reload failed due to: {ex.Message}."); } return _configFileWatcher is not null; @@ -208,8 +209,8 @@ private void OnNewFileContentsDetected(object? sender, EventArgs e) catch (Exception ex) { // Need to remove the dependencies in startup on the RuntimeConfigProvider - // before we can have an ILogger here. - Console.WriteLine("Unable to hot reload configuration file due to " + ex.Message); + // before we can have an injected ILogger here. + (_logger as ILogger ?? BootstrapLogger.Instance).LogWarning("Unable to hot reload configuration file due to " + ex.Message); } } diff --git a/src/Config/Utilities/FileUtilities.cs b/src/Config/Utilities/FileUtilities.cs index 549d6dd720..fd190e4b0b 100644 --- a/src/Config/Utilities/FileUtilities.cs +++ b/src/Config/Utilities/FileUtilities.cs @@ -3,6 +3,8 @@ using System.IO.Abstractions; using System.Security.Cryptography; +using Azure.DataApiBuilder.Product; +using Microsoft.Extensions.Logging; namespace Azure.DataApiBuilder.Config.Utilities; @@ -61,13 +63,13 @@ public static byte[] ComputeHash(IFileSystem fileSystem, string filePath) } else { - Console.WriteLine($"Path '{filePath}' not found in: " + Directory.GetCurrentDirectory()); + BootstrapLogger.Instance.LogWarning($"Path '{filePath}' not found in: " + Directory.GetCurrentDirectory()); throw new FileNotFoundException(); } } catch (IOException ex) { - Console.WriteLine($"IO Exception, retrying due to {ex.Message}"); + BootstrapLogger.Instance.LogWarning($"IO Exception, retrying due to {ex.Message}"); if (runCount == RunLimit) { throw; diff --git a/src/Core/Configurations/RuntimeConfigProvider.cs b/src/Core/Configurations/RuntimeConfigProvider.cs index c38f666d5b..1932e74f33 100644 --- a/src/Core/Configurations/RuntimeConfigProvider.cs +++ b/src/Core/Configurations/RuntimeConfigProvider.cs @@ -8,6 +8,7 @@ using Azure.DataApiBuilder.Config; using Azure.DataApiBuilder.Config.NamingPolicies; using Azure.DataApiBuilder.Config.ObjectModel; +using Azure.DataApiBuilder.Product; using Azure.DataApiBuilder.Service.Exceptions; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Primitives; @@ -381,7 +382,7 @@ public void ValidateConfig() // Only used in hot reload to validate the configuration file if (_configLoader.DoesConfigNeedValidation()) { - Console.WriteLine("Validating hot-reloaded configuration file."); + BootstrapLogger.Instance.LogInformation("Validating hot-reloaded configuration file."); IFileSystem fileSystem = new FileSystem(); ILoggerFactory loggerFactory = new LoggerFactory(); ILogger logger = loggerFactory.CreateLogger(); @@ -408,7 +409,7 @@ public void ValidateConfig() subStatusCode: DataApiBuilderException.SubStatusCodes.ErrorInInitialization); } - Console.WriteLine("Validated hot-reloaded configuration file."); + BootstrapLogger.Instance.LogInformation("Validated hot-reloaded configuration file."); } } diff --git a/src/Core/Resolvers/SqlPaginationUtil.cs b/src/Core/Resolvers/SqlPaginationUtil.cs index eeea568223..19c2adfd4b 100644 --- a/src/Core/Resolvers/SqlPaginationUtil.cs +++ b/src/Core/Resolvers/SqlPaginationUtil.cs @@ -10,11 +10,13 @@ using Azure.DataApiBuilder.Core.Models; using Azure.DataApiBuilder.Core.Parsers; using Azure.DataApiBuilder.Core.Services; +using Azure.DataApiBuilder.Product; using Azure.DataApiBuilder.Service.Exceptions; using Azure.DataApiBuilder.Service.GraphQLBuilder.GraphQLTypes; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Http.Extensions; using Microsoft.AspNetCore.WebUtilities; +using Microsoft.Extensions.Logging; using QueryBuilder = Azure.DataApiBuilder.Service.GraphQLBuilder.Queries.QueryBuilder; namespace Azure.DataApiBuilder.Core.Resolvers @@ -764,7 +766,8 @@ internal static string ResolveRequestScheme(HttpRequest req) if (isExplicit && !isValid) { // Log a warning and ignore the invalid value, fallback to request's scheme - Console.WriteLine($"Warning: Invalid scheme '{rawScheme}' in X-Forwarded-Proto header. Falling back to request scheme: '{req.Scheme}'."); + // This static helper has no injected ILogger, so the shared bootstrap logger is used. + BootstrapLogger.Instance.LogWarning($"Invalid scheme '{rawScheme}' in X-Forwarded-Proto header. Falling back to request scheme: '{req.Scheme}'."); return req.Scheme; } @@ -788,7 +791,8 @@ internal static string ResolveRequestHost(HttpRequest req) if (isExplicit && !isValid) { // Log a warning and ignore the invalid value, fallback to request's host - Console.WriteLine($"Warning: Invalid host '{rawHost}' in X-Forwarded-Host header. Falling back to request host: '{req.Host}'."); + // This static helper has no injected ILogger, so the shared bootstrap logger is used. + BootstrapLogger.Instance.LogWarning($"Invalid host '{rawHost}' in X-Forwarded-Host header. Falling back to request host: '{req.Host}'."); return req.Host.ToString(); } diff --git a/src/Directory.Packages.props b/src/Directory.Packages.props index 56523d0a94..ddb12d4396 100644 --- a/src/Directory.Packages.props +++ b/src/Directory.Packages.props @@ -49,6 +49,7 @@ + diff --git a/src/Product/Azure.DataApiBuilder.Product.csproj b/src/Product/Azure.DataApiBuilder.Product.csproj index f2237e2fba..06a7aa956e 100644 --- a/src/Product/Azure.DataApiBuilder.Product.csproj +++ b/src/Product/Azure.DataApiBuilder.Product.csproj @@ -9,6 +9,13 @@ NU1603 + + + + + true diff --git a/src/Product/BootstrapLogger.cs b/src/Product/BootstrapLogger.cs new file mode 100644 index 0000000000..e3b3a39597 --- /dev/null +++ b/src/Product/BootstrapLogger.cs @@ -0,0 +1,86 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System.Globalization; +using Microsoft.Extensions.Logging; + +namespace Azure.DataApiBuilder.Product; + +/// +/// Centralized console logger used for diagnostics which can't be routed through +/// the dependency injection provided ILogger, e.g. messages emitted before the host +/// (and its logging pipeline) is built, or from static helpers which have no injected logger. +/// Output matches the console logging pipeline's format by prefixing every entry with an +/// ISO 8601 UTC timestamp with millisecond precision, e.g. +/// 2026-07-07T14:01:01.344Z fail: Unable to launch the Data API builder engine. +/// This is the single place where such timestamps are formatted, so call sites only +/// need to use the APIs. +/// +public static class BootstrapLogger +{ + /// + /// ISO 8601 UTC timestamp with millisecond precision. Shared by every console + /// logging path (engine, CLI and bootstrap) so all entries look identical. + /// + public const string UTC_TIMESTAMP_FORMAT = "yyyy-MM-dd'T'HH:mm:ss.fff'Z'"; + + /// + /// Maps LogLevel to abbreviated labels matching ASP.NET Core's default console formatter. + /// + private static readonly Dictionary _logLevelToAbbreviation = new() + { + { LogLevel.Trace, "trce" }, + { LogLevel.Debug, "dbug" }, + { LogLevel.Information, "info" }, + { LogLevel.Warning, "warn" }, + { LogLevel.Error, "fail" }, + { LogLevel.Critical, "crit" } + }; + + /// + /// Returns the abbreviated label used by the console logging paths for the given level, + /// or null when the level has no label (). + /// + public static string? GetAbbreviatedLogLevel(LogLevel logLevel) + => _logLevelToAbbreviation.TryGetValue(logLevel, out string? abbreviation) ? abbreviation : null; + + /// + /// When true, all entries are written to stderr. Set by hosts which reserve + /// stdout for a protocol stream, e.g. MCP stdio mode's JSON-RPC messages. + /// + public static bool WriteAllOutputToStandardError { get; set; } + + /// + /// Shared logger instance used by all call sites. + /// + public static ILogger Instance { get; } = new ConsoleBootstrapLogger(); + + private sealed class ConsoleBootstrapLogger : ILogger + { + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + public bool IsEnabled(LogLevel logLevel) => logLevel != LogLevel.None; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) + { + if (!IsEnabled(logLevel) || !_logLevelToAbbreviation.TryGetValue(logLevel, out string? abbreviation)) + { + return; + } + + string message = formatter(state, exception); + if (exception is not null) + { + message = string.IsNullOrEmpty(message) ? exception.ToString() : $"{message} {exception}"; + } + + // CultureInfo.InvariantCulture guarantees deterministic ISO 8601 output + // regardless of the machine's locale (digits, calendar). + string timestamp = DateTime.UtcNow.ToString(UTC_TIMESTAMP_FORMAT, CultureInfo.InvariantCulture); + TextWriter writer = WriteAllOutputToStandardError || logLevel >= LogLevel.Error + ? Console.Error + : Console.Out; + writer.WriteLine($"{timestamp} {abbreviation}: {message}"); + } + } +} diff --git a/src/Service.Tests/UnitTests/BootstrapLoggerTests.cs b/src/Service.Tests/UnitTests/BootstrapLoggerTests.cs new file mode 100644 index 0000000000..110312584a --- /dev/null +++ b/src/Service.Tests/UnitTests/BootstrapLoggerTests.cs @@ -0,0 +1,105 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +#nullable enable + +using System; +using System.IO; +using System.Text.RegularExpressions; +using Azure.DataApiBuilder.Product; +using Microsoft.Extensions.Logging; +using Microsoft.VisualStudio.TestTools.UnitTesting; + +namespace Azure.DataApiBuilder.Service.Tests.UnitTests +{ + /// + /// Unit tests for , the centralized logger used for + /// diagnostics emitted before (or outside of) the dependency injection provided + /// logging pipeline. Every entry must begin with an ISO 8601 UTC timestamp with + /// millisecond precision, and MCP stdio hosts must be able to route all output + /// to stderr so stdout stays reserved for JSON-RPC. + /// + [TestClass] + public class BootstrapLoggerTests + { + private const string TIMESTAMP_PATTERN = @"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z "; + + [TestInitialize] + [TestCleanup] + public void ResetStandardErrorRouting() + { + BootstrapLogger.WriteAllOutputToStandardError = false; + } + + /// + /// Redirects Console.Out and Console.Error around + /// and returns whatever was written to each. + /// + private static (string Stdout, string Stderr) CaptureConsole(Action action) + { + TextWriter originalOut = Console.Out; + TextWriter originalError = Console.Error; + StringWriter stdout = new(); + StringWriter stderr = new(); + try + { + Console.SetOut(stdout); + Console.SetError(stderr); + action(); + } + finally + { + Console.SetOut(originalOut); + Console.SetError(originalError); + } + + return (stdout.ToString(), stderr.ToString()); + } + + [DataTestMethod] + [DataRow(LogLevel.Information, "info", false, DisplayName = "Information is written to stdout")] + [DataRow(LogLevel.Warning, "warn", false, DisplayName = "Warning is written to stdout")] + [DataRow(LogLevel.Error, "fail", true, DisplayName = "Error is written to stderr")] + [DataRow(LogLevel.Critical, "crit", true, DisplayName = "Critical is written to stderr")] + public void Log_PrefixesUtcTimestampAndAbbreviatedLevel(LogLevel logLevel, string expectedAbbreviation, bool expectStderr) + { + const string message = "bootstrap diagnostic message"; + + (string stdout, string stderr) = CaptureConsole( + () => BootstrapLogger.Instance.Log(logLevel, default, message, null, (state, _) => state)); + + string actual = expectStderr ? stderr : stdout; + string other = expectStderr ? stdout : stderr; + + Assert.IsTrue( + Regex.IsMatch(actual, TIMESTAMP_PATTERN + Regex.Escape($"{expectedAbbreviation}: {message}")), + $"Expected an ISO 8601 UTC timestamp followed by '{expectedAbbreviation}: {message}' but got: '{actual}'"); + Assert.AreEqual(string.Empty, other, + $"Did not expect output on the other stream but got: '{other}'"); + } + + [TestMethod] + public void Log_WhenWriteAllOutputToStandardError_RoutesInformationToStandardError() + { + BootstrapLogger.WriteAllOutputToStandardError = true; + + (string stdout, string stderr) = CaptureConsole( + () => BootstrapLogger.Instance.LogInformation("mcp safe message")); + + Assert.AreEqual(string.Empty, stdout, $"Expected stdout to stay clean but got: '{stdout}'"); + Assert.IsTrue( + Regex.IsMatch(stderr, TIMESTAMP_PATTERN + "info: mcp safe message"), + $"Expected timestamped entry on stderr but got: '{stderr}'"); + } + + [TestMethod] + public void Log_WhenLogLevelNone_WritesNothing() + { + (string stdout, string stderr) = CaptureConsole( + () => BootstrapLogger.Instance.Log(LogLevel.None, default, "suppressed", null, (state, _) => state)); + + Assert.AreEqual(string.Empty, stdout); + Assert.AreEqual(string.Empty, stderr); + } + } +} diff --git a/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs new file mode 100644 index 0000000000..08a3999603 --- /dev/null +++ b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs @@ -0,0 +1,732 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +#nullable enable + +using System; +using System.Collections.Generic; +using System.Globalization; +using System.IO; +using System.IO.Abstractions; +using System.Linq; +using System.Text.RegularExpressions; +using Azure.DataApiBuilder.Config.Utilities; +using Azure.DataApiBuilder.Core.Resolvers; +using Azure.DataApiBuilder.Product; +using Azure.DataApiBuilder.Service.Telemetry; +using Microsoft.AspNetCore.Http; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Logging.Console; +using Microsoft.VisualStudio.TestTools.UnitTesting; + +namespace Azure.DataApiBuilder.Service.Tests.UnitTests +{ + /// + /// Verifies that every console log entry produced by the engine begins with an + /// ISO 8601 UTC timestamp with millisecond precision. Covers the two logging + /// factories built by (the startup logger factory and the + /// web host's logging pipeline) as well as the direct diagnostic call sites that + /// were migrated from Console.WriteLine to a logger. + /// + [TestClass] + public class ConsoleLogTimestampTests + { + private const string LOG_MESSAGE = "timestamp probe message"; + + /// + /// Matches the timestamp prefix: exactly three fractional-second digits followed + /// by a literal 'Z'. The trailing 'Z' immediately after the third digit is what + /// rules out additional (e.g. microsecond) precision. + /// + private static readonly Regex _timestampPrefix = + new(@"^(?\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z) ", RegexOptions.Compiled); + + /// + /// is process-wide mutable state read by the + /// logging configuration under test. Replace it per test and restore afterwards so + /// the rest of the suite keeps observing the default instance. + /// + private DynamicLogLevelProvider? _originalLogLevelProvider; + + [TestInitialize] + public void SetLogLevelProvider() + { + _originalLogLevelProvider = Program.LogLevelProvider; + DynamicLogLevelProvider provider = new(); + provider.SetInitialLogLevel(LogLevel.Information); + Program.LogLevelProvider = provider; + } + + [TestCleanup] + public void RestoreLogLevelProvider() + { + if (_originalLogLevelProvider is not null) + { + Program.LogLevelProvider = _originalLogLevelProvider; + } + + BootstrapLogger.WriteAllOutputToStandardError = false; + } + + /// + /// Asserts that begins with a timestamp that: + /// parses as UTC, ends in 'Z', carries exactly three fractional-second digits, + /// and falls within the window captured around the logging call. + /// + private static void AssertStartsWithUtcTimestamp(string output, DateTime before, DateTime after) + { + Match match = _timestampPrefix.Match(output); + Assert.IsTrue(match.Success, + $"Expected output to start with an ISO 8601 UTC timestamp (yyyy-MM-ddTHH:mm:ss.fffZ) but got: '{output}'"); + + string timestamp = match.Groups["ts"].Value; + Assert.IsTrue(timestamp.EndsWith("Z", StringComparison.Ordinal), + $"Timestamp '{timestamp}' must end with 'Z' to denote UTC."); + Assert.AreEqual(3, timestamp.Split('.')[1].TrimEnd('Z').Length, + $"Timestamp '{timestamp}' must carry exactly three fractional-second digits."); + + Assert.IsTrue( + DateTime.TryParseExact( + timestamp, + "yyyy-MM-dd'T'HH:mm:ss.fff'Z'", + CultureInfo.InvariantCulture, + DateTimeStyles.AssumeUniversal | DateTimeStyles.AdjustToUniversal, + out DateTime parsed), + $"Timestamp '{timestamp}' could not be parsed as an invariant-culture UTC value."); + Assert.AreEqual(DateTimeKind.Utc, parsed.Kind, "Parsed timestamp must be UTC."); + + // The emitted value is truncated to milliseconds, so compare against a + // millisecond-truncated lower bound. + DateTime lowerBound = before.AddTicks(-(before.Ticks % TimeSpan.TicksPerMillisecond)); + Assert.IsTrue(parsed >= lowerBound && parsed <= after, + $"Timestamp '{timestamp}' is outside the window [{lowerBound:O}, {after:O}] captured around the log call."); + } + + /// + /// Asserts every log entry is timestamped. Continuation lines (the console + /// formatter writes the message indented beneath its header line) are skipped + /// since the timestamp belongs to the entry, not to each physical line. + /// + private static void AssertEveryEntryTimestamped(string output, DateTime before, DateTime after) + { + string[] entries = output + .Split('\n') + .Select(line => line.TrimEnd('\r')) + .Where(line => !string.IsNullOrWhiteSpace(line) && !char.IsWhiteSpace(line[0])) + .ToArray(); + + Assert.IsTrue(entries.Length > 0, "Expected at least one log entry."); + foreach (string entry in entries) + { + AssertStartsWithUtcTimestamp(entry, before, after); + } + } + + /// + /// Redirects Console.Out/Console.Error around . The console + /// logger provider captures the current writers when it is constructed, so the + /// factory must be created inside the action. + /// + private static (string Stdout, string Stderr, DateTime Before, DateTime After) CaptureConsole(Action action) + { + TextWriter originalOut = Console.Out; + TextWriter originalError = Console.Error; + StringWriter stdout = new(); + StringWriter stderr = new(); + DateTime before; + DateTime after; + try + { + Console.SetOut(stdout); + Console.SetError(stderr); + before = DateTime.UtcNow; + action(); + after = DateTime.UtcNow; + } + finally + { + Console.SetOut(originalOut); + Console.SetError(originalError); + } + + return (stdout.ToString(), stderr.ToString(), before, after); + } + + /// + /// The startup logger factory (non-stdio) writes timestamped entries to stdout. + /// + [TestMethod] + public void GetLoggerFactoryForLogLevel_NormalMode_EmitsTimestampedEntry() + { + (string stdout, string stderr, DateTime before, DateTime after) = CaptureConsole(() => + { + using ILoggerFactory factory = Program.GetLoggerFactoryForLogLevel(LogLevel.Information); + factory.CreateLogger("TestCategory").LogInformation(LOG_MESSAGE); + }); + + AssertEveryEntryTimestamped(stdout, before, after); + StringAssert.Contains(stdout, LOG_MESSAGE); + StringAssert.Contains(stdout, "info:"); + Assert.AreEqual(string.Empty, stderr, $"Information must not be written to stderr but got: '{stderr}'"); + } + + /// + /// The startup logger factory in stdio mode keeps stdout free for JSON-RPC while + /// still timestamping the diagnostics it routes to stderr. + /// + [TestMethod] + public void GetLoggerFactoryForLogLevel_StdioMode_EmitsTimestampedEntryToStandardErrorOnly() + { + (string stdout, string stderr, DateTime before, DateTime after) = CaptureConsole(() => + { + using ILoggerFactory factory = Program.GetLoggerFactoryForLogLevel(LogLevel.Information, stdio: true); + factory.CreateLogger("TestCategory").LogInformation(LOG_MESSAGE); + }); + + Assert.AreEqual(string.Empty, stdout, $"stdio mode must keep stdout clean but got: '{stdout}'"); + AssertEveryEntryTimestamped(stderr, before, after); + StringAssert.Contains(stderr, LOG_MESSAGE); + StringAssert.Contains(stderr, "info:"); + } + + /// + /// The web host's logging configuration reuses the console provider registered by + /// Host.CreateDefaultBuilder(): each event must appear exactly once (a second + /// provider registration would duplicate every entry) and must be timestamped. + /// + [TestMethod] + public void ConfigureHostLogging_NormalMode_EmitsEachEntryOnceWithTimestamp() + { + (string stdout, string stderr, DateTime before, DateTime after) = CaptureConsole(() => + { + // AddConsole() mirrors the provider Host.CreateDefaultBuilder() registers + // before ConfigureLogging runs. + using ILoggerFactory factory = LoggerFactory.Create(builder => + { + builder.AddConsole(); + Program.ConfigureHostLogging(builder, runMcpStdio: false); + }); + + factory.CreateLogger("TestCategory").LogInformation(LOG_MESSAGE); + }); + + Assert.AreEqual(1, Regex.Matches(stdout, Regex.Escape(LOG_MESSAGE)).Count, + $"Expected the entry exactly once (no duplicate console provider) but got: '{stdout}'"); + AssertEveryEntryTimestamped(stdout, before, after); + Assert.AreEqual(string.Empty, stderr, $"Information must not be written to stderr but got: '{stderr}'"); + } + + /// + /// Only one console logger provider ends up registered for the web host. + /// + [TestMethod] + public void ConfigureHostLogging_NormalMode_RegistersSingleConsoleProvider() + { + ServiceCollection services = new(); + services.AddLogging(builder => + { + builder.AddConsole(); + Program.ConfigureHostLogging(builder, runMcpStdio: false); + }); + + int consoleProviderCount = services.Count(descriptor => + descriptor.ServiceType == typeof(ILoggerProvider) + && descriptor.ImplementationType == typeof(ConsoleLoggerProvider)); + + Assert.AreEqual(1, consoleProviderCount, + "Exactly one ConsoleLoggerProvider must be registered; a second one would duplicate every log entry."); + } + + /// + /// In stdio mode the console providers are cleared so nothing can corrupt the + /// JSON-RPC channel on stdout. + /// + [TestMethod] + public void ConfigureHostLogging_StdioMode_WritesNothingToConsole() + { + (string stdout, string stderr, _, _) = CaptureConsole(() => + { + using ILoggerFactory factory = LoggerFactory.Create(builder => + { + builder.AddConsole(); + Program.ConfigureHostLogging(builder, runMcpStdio: true); + }); + + factory.CreateLogger("TestCategory").LogInformation(LOG_MESSAGE); + }); + + Assert.AreEqual(string.Empty, stdout, $"stdio mode must keep stdout clean but got: '{stdout}'"); + Assert.AreEqual(string.Empty, stderr, $"stdio mode clears console providers but got: '{stderr}'"); + } + + /// + /// Runs with the ambient culture set to + /// and restores the previous culture afterwards. + /// The culture is only ambient state for the calling thread's execution context, + /// so the process-wide default is never modified. + /// + private static void RunUnderCulture(string cultureName, Action action) + { + CultureInfo originalCulture = CultureInfo.CurrentCulture; + CultureInfo originalUICulture = CultureInfo.CurrentUICulture; + try + { + CultureInfo culture = new(cultureName); + CultureInfo.CurrentCulture = culture; + CultureInfo.CurrentUICulture = culture; + action(); + } + finally + { + CultureInfo.CurrentCulture = originalCulture; + CultureInfo.CurrentUICulture = originalUICulture; + } + } + + /// + /// Guards against the regression tests below silently passing on a runtime built with + /// globalization-invariant mode, where every culture behaves like the invariant culture. + /// + private static void AssertCultureIsNonGregorian(string cultureName) + { + DateTime probe = DateTime.UtcNow; + string cultureRendering = string.Empty; + RunUnderCulture(cultureName, () => + cultureRendering = probe.ToString(BootstrapLogger.UTC_TIMESTAMP_FORMAT, CultureInfo.CurrentCulture)); + + Assert.AreNotEqual( + probe.ToString(BootstrapLogger.UTC_TIMESTAMP_FORMAT, CultureInfo.InvariantCulture), + cultureRendering, + $"Culture '{cultureName}' is expected to use a non-Gregorian calendar; without that this test cannot " + + "detect culture-sensitive timestamp formatting."); + } + + /// + /// The startup logger factory must emit the Gregorian, invariant-culture UTC prefix even + /// when the ambient culture uses a different calendar. The built-in "simple" console + /// formatter renders its timestamp with CultureInfo.CurrentCulture, so relying on its + /// TimestampFormat option would produce e.g. '2569-08-29T...' under th-TH. + /// + [DataTestMethod] + [DataRow("ar-SA", false, DisplayName = "ar-SA, normal mode")] + [DataRow("ar-SA", true, DisplayName = "ar-SA, stdio mode")] + [DataRow("th-TH", false, DisplayName = "th-TH, normal mode")] + [DataRow("th-TH", true, DisplayName = "th-TH, stdio mode")] + public void GetLoggerFactoryForLogLevel_NonGregorianCulture_EmitsInvariantUtcTimestamp(string cultureName, bool stdio) + { + AssertCultureIsNonGregorian(cultureName); + + (string stdout, string stderr, DateTime before, DateTime after) = CaptureConsole(() => + RunUnderCulture(cultureName, () => + { + using ILoggerFactory factory = Program.GetLoggerFactoryForLogLevel(LogLevel.Information, stdio: stdio); + factory.CreateLogger("TestCategory").LogInformation(LOG_MESSAGE); + })); + + string output = stdio ? stderr : stdout; + Assert.AreEqual(string.Empty, stdio ? stdout : stderr, + "Log entries must only be written to the stream the mode designates."); + AssertEveryEntryTimestamped(output, before, after); + StringAssert.Contains(output, LOG_MESSAGE); + } + + /// + /// The web host's logging pipeline must likewise emit the Gregorian, invariant-culture + /// UTC prefix under a non-Gregorian ambient culture, still exactly once per event. + /// + [DataTestMethod] + [DataRow("ar-SA")] + [DataRow("th-TH")] + public void ConfigureHostLogging_NonGregorianCulture_EmitsInvariantUtcTimestamp(string cultureName) + { + AssertCultureIsNonGregorian(cultureName); + + (string stdout, string stderr, DateTime before, DateTime after) = CaptureConsole(() => + RunUnderCulture(cultureName, () => + { + using ILoggerFactory factory = LoggerFactory.Create(builder => + { + builder.AddConsole(); + Program.ConfigureHostLogging(builder, runMcpStdio: false); + }); + + factory.CreateLogger("TestCategory").LogInformation(LOG_MESSAGE); + })); + + Assert.AreEqual(1, Regex.Matches(stdout, Regex.Escape(LOG_MESSAGE)).Count, + $"Expected the entry exactly once (no duplicate console provider) but got: '{stdout}'"); + AssertEveryEntryTimestamped(stdout, before, after); + Assert.AreEqual(string.Empty, stderr, $"Information must not be written to stderr but got: '{stderr}'"); + } + + /// + /// The bootstrap logger used for pre-dependency-injection diagnostics is subject to the + /// same requirement. + /// + [DataTestMethod] + [DataRow("ar-SA")] + [DataRow("th-TH")] + public void BootstrapLogger_NonGregorianCulture_EmitsInvariantUtcTimestamp(string cultureName) + { + AssertCultureIsNonGregorian(cultureName); + + (string stdout, _, DateTime before, DateTime after) = CaptureConsole(() => + RunUnderCulture(cultureName, () => BootstrapLogger.Instance.LogInformation(LOG_MESSAGE))); + + AssertEveryEntryTimestamped(stdout, before, after); + StringAssert.Contains(stdout, LOG_MESSAGE); + } + + /// + /// Migrated diagnostic: invalid X-Forwarded-* headers produce a timestamped warning + /// instead of a bare Console.WriteLine. + /// + [DataTestMethod] + [DataRow("X-Forwarded-Proto", "not a scheme", "X-Forwarded-Proto header", DisplayName = "Invalid forwarded scheme is timestamped")] + [DataRow("X-Forwarded-Host", "in valid host", "X-Forwarded-Host header", DisplayName = "Invalid forwarded host is timestamped")] + public void SqlPaginationUtil_InvalidForwardedHeader_LogsTimestampedWarning(string header, string value, string expectedText) + { + DefaultHttpContext httpContext = new(); + httpContext.Request.Headers[header] = value; + + (string stdout, _, DateTime before, DateTime after) = CaptureConsole(() => + { + if (header == "X-Forwarded-Proto") + { + SqlPaginationUtil.ResolveRequestScheme(httpContext.Request); + } + else + { + SqlPaginationUtil.ResolveRequestHost(httpContext.Request); + } + }); + + AssertEveryEntryTimestamped(stdout, before, after); + StringAssert.Contains(stdout, "warn:"); + StringAssert.Contains(stdout, expectedText); + } + + /// + /// Migrated diagnostic: the config file hash helper reports a missing file through + /// the bootstrap logger, so the entry is timestamped. + /// + [TestMethod] + public void FileUtilities_MissingFile_LogsTimestampedWarning() + { + string missingPath = Path.Combine(Path.GetTempPath(), $"dab-missing-{Guid.NewGuid():N}.json"); + FileSystem fileSystem = new(); + + (string stdout, _, DateTime before, DateTime after) = CaptureConsole(() => + { + Assert.ThrowsException( + () => FileUtilities.ComputeHash(fileSystem, missingPath)); + }); + + AssertEveryEntryTimestamped(stdout, before, after); + StringAssert.Contains(stdout, "warn:"); + StringAssert.Contains(stdout, missingPath); + } + + /// + /// Migrated diagnostic: startup/bootstrap failures are timestamped and, when the host + /// reserves stdout for JSON-RPC, routed to stderr. + /// + [TestMethod] + public void BootstrapLogger_StdErrRouting_EmitsTimestampedEntryOnStandardErrorOnly() + { + BootstrapLogger.WriteAllOutputToStandardError = true; + + (string stdout, string stderr, DateTime before, DateTime after) = CaptureConsole( + () => BootstrapLogger.Instance.LogInformation(LOG_MESSAGE)); + + Assert.AreEqual(string.Empty, stdout, $"stdout must stay clean but got: '{stdout}'"); + AssertEveryEntryTimestamped(stderr, before, after); + StringAssert.Contains(stderr, LOG_MESSAGE); + } + + /// + /// Minimal stand-in matching the shape + /// ConsoleLogger.LogRecords() hands to the formatter when replaying buffered entries. + /// + private sealed class TestBufferedLogRecord : BufferedLogRecord + { + public override DateTimeOffset Timestamp { get; } + + public override LogLevel LogLevel { get; } + + public override EventId EventId { get; } + + public override string? Exception { get; } + + public override string? FormattedMessage { get; } + + public TestBufferedLogRecord(DateTimeOffset timestamp, LogLevel logLevel, EventId eventId, string? message, string? exception) + { + Timestamp = timestamp; + LogLevel = logLevel; + EventId = eventId; + FormattedMessage = message; + Exception = exception; + } + } + + /// + /// Invokes the formatter exactly as ConsoleLogger.LogRecords() does for a buffered + /// entry: the state is the and both the formatter delegate + /// and LogEntry.Exception are null. + /// + private static string FormatBufferedRecord(BufferedLogRecord record, string category) + { + ServiceCollection services = new(); + services.AddLogging(builder => builder.AddUtcTimestampConsoleFormatter()); + using ServiceProvider provider = services.BuildServiceProvider(); + + ConsoleFormatter formatter = provider.GetRequiredService>() + .Single(f => f.Name == UtcTimestampConsoleFormatter.FORMATTER_NAME); + + LogEntry entry = new( + record.LogLevel, + category, + record.EventId, + record, + exception: null, + formatter: null!); + + StringWriter writer = new(); + formatter.Write(in entry, scopeProvider: null, writer); + return writer.ToString(); + } + + /// + /// A buffered entry must be stamped with the time the event originally occurred, not the + /// time it was flushed, and must still carry the invariant Gregorian UTC prefix. + /// + [DataTestMethod] + [DataRow("en-US")] + [DataRow("th-TH")] + public void Formatter_BufferedLogRecord_UsesOriginalTimestamp(string cultureName) + { + // A fixed instant well in the past, so a flush-time timestamp cannot coincide with it. + DateTimeOffset recorded = new(2021, 3, 4, 5, 6, 7, 89, TimeSpan.Zero); + TestBufferedLogRecord record = new(recorded, LogLevel.Warning, new EventId(42), LOG_MESSAGE, exception: null); + + string output = string.Empty; + RunUnderCulture(cultureName, () => output = FormatBufferedRecord(record, "TestCategory")); + + StringAssert.StartsWith(output, "2021-03-04T05:06:07.089Z ", + $"Buffered entry must be stamped with the record's own UTC timestamp but got: '{output}'"); + StringAssert.Contains(output, "warn:"); + StringAssert.Contains(output, "TestCategory[42]"); + StringAssert.Contains(output, LOG_MESSAGE); + } + + /// + /// A buffered entry stores its exception as a preformatted string on the record while + /// LogEntry.Exception is null, so reading only the latter would silently drop it. + /// + [TestMethod] + public void Formatter_BufferedLogRecord_WritesBufferedException() + { + const string EXCEPTION_TEXT = "System.InvalidOperationException: buffered boom"; + TestBufferedLogRecord record = new( + DateTimeOffset.UtcNow, LogLevel.Error, new EventId(7), LOG_MESSAGE, EXCEPTION_TEXT); + + string output = FormatBufferedRecord(record, "TestCategory"); + + StringAssert.Contains(output, EXCEPTION_TEXT, + $"Buffered exception must not be dropped but got: '{output}'"); + StringAssert.Contains(output, LOG_MESSAGE); + StringAssert.Contains(output, "fail:"); + } + + /// + /// Log messages can carry untrusted values, so terminal control characters must be escaped + /// rather than written through to the console (as the built-in formatter also does). + /// Tab, carriage return and line feed remain intact for log formatting. + /// + [TestMethod] + public void Formatter_ControlCharactersInMessage_AreEscaped() + { + TestBufferedLogRecord record = new( + DateTimeOffset.UtcNow, + LogLevel.Information, + new EventId(0), + "injected\u001b[31mred\u0007bell\tkept", + exception: null); + + string output = FormatBufferedRecord(record, "TestCategory"); + + Assert.IsFalse(output.Contains('\u001b'), $"ESC must be escaped but got: '{output}'"); + Assert.IsFalse(output.Contains('\u0007'), $"BEL must be escaped but got: '{output}'"); + StringAssert.Contains(output, "\\u001B"); + StringAssert.Contains(output, "\\u0007"); + StringAssert.Contains(output, "bell\tkept", "Tab must be preserved for log formatting."); + } + + /// + /// Matches a direct write to the console, e.g. Console.WriteLine(, + /// Console.Error.Write( or Console.Out.WriteLine(. + /// + private static readonly Regex _directConsoleWrite = + new(@"\bConsole\s*\.\s*(?:(?:Error|Out)\s*\.\s*)?Write(?:Line)?\s*\(", RegexOptions.Compiled); + + /// + /// Production source files permitted to write to the console directly, with the reason. + /// Everything else must log through or an injected + /// so the entry carries the invariant UTC millisecond prefix. + /// + private static readonly Dictionary _allowedDirectConsoleWriters = new(StringComparer.OrdinalIgnoreCase) + { + ["Cli/CustomLoggerProvider.cs"] = "Is the CLI console logger implementation; it writes the timestamp itself.", + ["Cli/Commands/AppNameOptions.cs"] = "Intentional command result (encoded/decoded app name), not a diagnostic.", + ["Cli/ConfigGenerator.cs"] = "Intentional command result (auto-entities simulation table), not a diagnostic." + }; + + /// + /// Guards the completeness of the direct-console inventory: every production source file + /// must route log-like diagnostics through a logger rather than Console.Write*. + /// This is what ties the Aspire AppHost (and any future call site) to the invariant UTC + /// prefix - the prefix itself is asserted by the BootstrapLogger tests above, so proving a + /// file has no bare console writes proves its diagnostics carry that prefix. + /// Intentional command output is allow-listed with a justification. + /// + [TestMethod] + public void ProductionSources_DoNotWriteDiagnosticsDirectlyToConsole() + { + DirectoryInfo sourceRoot = FindSourceRoot(); + + // Discovered rather than hard coded so a newly added production project is covered + // automatically instead of silently escaping the guard. + List productionProjects = sourceRoot.EnumerateDirectories() + .Where(directory => directory.EnumerateFiles("*.csproj").Any() + && !directory.Name.EndsWith(".Tests", StringComparison.OrdinalIgnoreCase)) + .OrderBy(directory => directory.Name, StringComparer.Ordinal) + .ToList(); + + // Sanity check the discovery itself, so the guard cannot pass by scanning nothing. + CollectionAssert.AreEqual( + new[] + { + "Aspire.AppHost", "Auth", "Azure.DataApiBuilder.Mcp", "Cli", + "Config", "Core", "Product", "Service", "Service.GraphQLBuilder" + }, + productionProjects.Select(directory => directory.Name).ToArray(), + "The set of scanned production projects changed. Update this list once the new " + + "project's console writes have been reviewed."); + + List violations = new(); + foreach (DirectoryInfo project in productionProjects) + { + foreach (string file in Directory.EnumerateFiles(project.FullName, "*.cs", SearchOption.AllDirectories)) + { + string relativePath = Path.GetRelativePath(sourceRoot.FullName, file).Replace('\\', '/'); + + // Generated and intermediate build output is not hand-written source. + if (relativePath.Contains("/obj/", StringComparison.Ordinal) + || relativePath.Contains("/bin/", StringComparison.Ordinal) + || _allowedDirectConsoleWriters.ContainsKey(relativePath)) + { + continue; + } + + string[] lines = File.ReadAllLines(file); + for (int i = 0; i < lines.Length; i++) + { + // Skip comments, which legitimately mention Console.WriteLine in prose. + string trimmed = lines[i].TrimStart(); + if (trimmed.StartsWith("//", StringComparison.Ordinal) + || trimmed.StartsWith("*", StringComparison.Ordinal)) + { + continue; + } + + if (_directConsoleWrite.IsMatch(lines[i])) + { + violations.Add($"{relativePath}({i + 1}): {trimmed}"); + } + } + } + } + + Assert.AreEqual(0, violations.Count, + "Log-like diagnostics must be emitted through a logger so they carry the invariant UTC timestamp prefix. " + + "If a write is intentional command output, add it to _allowedDirectConsoleWriters with a justification. " + + $"Found:{Environment.NewLine}{string.Join(Environment.NewLine, violations)}"); + } + + /// + /// The AppHost starts a local database container only when no connection string was + /// supplied, and says so. A previous inversion of the PostgreSQL guard made the + /// diagnostic state the opposite of its own condition (starting a container only when a + /// connection string *was* provided, then ignoring it). AppHost is top level statements + /// in an executable which builds and runs a distributed application, so the pairing is + /// asserted at the source level: every "no connection string" diagnostic must sit + /// directly inside an if (string.IsNullOrEmpty(databaseConnectionString)) guard. + /// + [TestMethod] + public void AppHost_StartsLocalDatabaseContainerOnlyWhenNoConnectionStringProvided() + { + DirectoryInfo sourceRoot = FindSourceRoot(); + string appHostPath = Path.Combine(sourceRoot.FullName, "Aspire.AppHost", "AppHost.cs"); + Assert.IsTrue(File.Exists(appHostPath), $"Expected '{appHostPath}' to exist."); + + string[] lines = File.ReadAllLines(appHostPath); + List diagnosticGuards = new(); + for (int i = 0; i < lines.Length; i++) + { + if (!lines[i].Contains("No connection string provided", StringComparison.Ordinal)) + { + continue; + } + + // Walk back to the nearest preceding line of code, which must be the guard. + string guard = string.Empty; + for (int j = i - 1; j >= 0; j--) + { + string candidate = lines[j].Trim(); + if (candidate.Length > 0 && candidate != "{") + { + guard = candidate; + break; + } + } + + diagnosticGuards.Add($"{Path.GetFileName(appHostPath)}({i + 1}) guarded by: {guard}"); + Assert.AreEqual( + "if (string.IsNullOrEmpty(databaseConnectionString))", + guard, + $"The container start diagnostic on line {i + 1} must be reached only when no " + + "connection string was provided, otherwise the message contradicts its own condition."); + } + + // Both the mssql and postgresql branches must carry the diagnostic, so neither can + // drop out of coverage by simply deleting its message. + Assert.AreEqual(2, diagnosticGuards.Count, + "Expected exactly one 'no connection string' diagnostic for each of the mssql and " + + $"postgresql branches. Found:{Environment.NewLine}{string.Join(Environment.NewLine, diagnosticGuards)}"); + } + + /// + /// Walks up from the test assembly location to the repository's 'src' directory, + /// identified by the solution file it contains. + /// + private static DirectoryInfo FindSourceRoot() + { + DirectoryInfo? directory = new(AppContext.BaseDirectory); + while (directory is not null) + { + if (File.Exists(Path.Combine(directory.FullName, "Azure.DataApiBuilder.sln"))) + { + return directory; + } + + directory = directory.Parent; + } + + throw new AssertFailedException( + $"Could not locate the 'src' directory (containing Azure.DataApiBuilder.sln) from '{AppContext.BaseDirectory}'."); + } + } +} diff --git a/src/Service/Program.cs b/src/Service/Program.cs index 76af52ba97..42ab46ad46 100644 --- a/src/Service/Program.cs +++ b/src/Service/Program.cs @@ -14,6 +14,7 @@ using Azure.DataApiBuilder.Core.Telemetry; using Azure.DataApiBuilder.Mcp.Core; using Azure.DataApiBuilder.Mcp.Telemetry; +using Azure.DataApiBuilder.Product; using Azure.DataApiBuilder.Service.Exceptions; using Azure.DataApiBuilder.Service.Telemetry; using Azure.DataApiBuilder.Service.Utilities; @@ -26,6 +27,7 @@ using Microsoft.Extensions.Hosting; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.ApplicationInsights; +using Microsoft.Extensions.Logging.Console; using OpenTelemetry.Exporter; using OpenTelemetry.Logs; using OpenTelemetry.Resources; @@ -80,7 +82,7 @@ public static void Main(string[] args) if (!ValidateAspNetCoreUrls()) { - Console.Error.WriteLine("Invalid ASPNETCORE_URLS format. e.g.: ASPNETCORE_URLS=\"http://localhost:5000;https://localhost:5001\""); + BootstrapLogger.Instance.LogError("Invalid ASPNETCORE_URLS format. e.g.: ASPNETCORE_URLS=\"http://localhost:5000;https://localhost:5001\""); Environment.ExitCode = -1; return; } @@ -106,6 +108,9 @@ public static bool StartEngine(string[] args, bool runMcpStdio, string? mcpRole) // MCP SDK uses Console.OpenStandardOutput() which gets the real stdout, unaffected by this redirect. if (runMcpStdio) { + // stdout is reserved for the JSON-RPC protocol stream. + BootstrapLogger.WriteAllOutputToStandardError = true; + // When LogLevel.None, redirect to null stream for ZERO output. // Otherwise redirect to stderr so logs don't pollute JSON-RPC. if (initialLogLevel == LogLevel.None) @@ -135,13 +140,13 @@ public static bool StartEngine(string[] args, bool runMcpStdio, string? mcpRole) { // Do not log the exception here because exceptions raised during startup // are already automatically written to the console. - Console.Error.WriteLine("Unable to launch the Data API builder engine."); + BootstrapLogger.Instance.LogError("Unable to launch the Data API builder engine."); return false; } // Catch all remaining unhandled exceptions which may be due to server host operation. catch (Exception ex) { - Console.Error.WriteLine($"Unable to launch the runtime due to: {ex}"); + BootstrapLogger.Instance.LogError($"Unable to launch the runtime due to: {ex}"); return false; } } @@ -176,37 +181,7 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st services.AddSingleton(_mcpNotificationWriter); } }) - .ConfigureLogging(logging => - { - // For MCP stdio mode, we need dynamic log level control via logging/setLevel. - // Set framework minimum to Trace so all logs pass through to the dynamic filter. - // The dynamic AddFilter() will do the actual filtering based on current level. - // 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); - } - else - { - logging.SetMinimumLevel(LogLevelProvider.CurrentLogLevel); - } - - // 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)); - } - }) + .ConfigureLogging(logging => ConfigureHostLogging(logging, runMcpStdio)) .ConfigureWebHostDefaults(webBuilder => { // LogLevelProvider was already initialized in StartEngine before CreateHostBuilder. @@ -220,6 +195,57 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st }); } + /// + /// Configures the web host's logging pipeline. + /// For MCP stdio mode all default providers are cleared (stdout is reserved for + /// JSON-RPC) and the framework minimum is lowered to Trace so the dynamic filter + /// alone decides what is emitted. Otherwise the console provider already registered + /// by is reused - no second provider + /// is added - and only its formatter options are adjusted so every entry is prefixed + /// with an ISO 8601 UTC timestamp. + /// + /// Logging builder supplied by the host. + /// True when running as an MCP stdio server. + public static void ConfigureHostLogging(ILoggingBuilder logging, bool runMcpStdio) + { + // For MCP stdio mode, we need dynamic log level control via logging/setLevel. + // Set framework minimum to Trace so all logs pass through to the dynamic filter. + // The dynamic AddFilter() will do the actual filtering based on current level. + // 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); + } + else + { + logging.SetMinimumLevel(LogLevelProvider.CurrentLogLevel); + + // The console provider registered by Host.CreateDefaultBuilder() is reused as-is; + // only its formatter is configured so no second provider is registered (which would + // emit every entry twice). ConsoleLoggerOptions.FormatterName must be set explicitly + // (AddUtcTimestampConsoleFormatter does so): when it is left unset the provider ignores + // the registered formatters and derives its behavior from ConsoleLoggerOptions' own + // (obsolete) properties instead, which would silently drop the timestamp. + logging.AddUtcTimestampConsoleFormatter(); + } + + // 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)); + } + } + /// /// Extracts the log level from the command line arguments and optionally from config. /// When --log-level is present, returns that value with CLI override flag set. @@ -464,7 +490,11 @@ public static ILoggerFactory GetLoggerFactoryForLogLevel( // When LogLevel.None, skip the console logger entirely for true silence. if (LogLevelProvider.CurrentLogLevel != LogLevel.None) { - builder.AddConsole(options => + builder.AddConsole(); + builder.AddUtcTimestampConsoleFormatter(); + // Route all levels to stderr to keep stdout clean for MCP JSON-RPC. + // Uses Services.Configure (not a second AddConsole) so no second provider is registered. + builder.Services.Configure(options => { options.LogToStandardErrorThreshold = LogLevel.Trace; }); @@ -473,6 +503,7 @@ public static ILoggerFactory GetLoggerFactoryForLogLevel( else { builder.AddConsole(); + builder.AddUtcTimestampConsoleFormatter(); } }); } @@ -491,7 +522,7 @@ private static void DisableHttpsRedirectionIfNeeded(string[] args) ParseResult result = GetParseResult(cmd, args); if (result.Tokens.Count - result.UnmatchedTokens.Count - result.UnparsedTokens.Count > 0) { - Console.WriteLine("Redirecting to https is disabled."); + BootstrapLogger.Instance.LogInformation("Redirecting to https is disabled."); IsHttpsRedirectionDisabled = true; return; } diff --git a/src/Service/Startup.cs b/src/Service/Startup.cs index b41550bf2e..05c130b12b 100644 --- a/src/Service/Startup.cs +++ b/src/Service/Startup.cs @@ -814,7 +814,7 @@ private void RefreshGraphQLSchema(IServiceCollection services) { // Re-add GraphQL services with updated config. RuntimeConfig runtimeConfig = _configProvider!.GetConfig(); - Console.WriteLine("Updating GraphQL service."); + _logger.LogInformation("Updating GraphQL service."); AddGraphQLService(services, runtimeConfig.Runtime?.GraphQL); } @@ -1008,7 +1008,7 @@ public void Configure(IApplicationBuilder app, IWebHostEnvironment env, RuntimeC IRequestExecutorManager requestExecutorManager = app.ApplicationServices.GetRequiredService(); _hotReloadEventHandler.Subscribe( "GRAPHQL_SCHEMA_EVICTION_ON_CONFIG_CHANGED", - (_, _) => EvictGraphQLSchema(requestExecutorManager)); + (_, _) => EvictGraphQLSchema(requestExecutorManager, _logger)); app.UseEndpoints(endpoints => { @@ -1073,9 +1073,9 @@ public void Configure(IApplicationBuilder app, IWebHostEnvironment env, RuntimeC /// /// Evicts the GraphQL schema from the request executor resolver. /// - private static void EvictGraphQLSchema(IRequestExecutorManager requestExecutorResolver) + private static void EvictGraphQLSchema(IRequestExecutorManager requestExecutorResolver, Microsoft.Extensions.Logging.ILogger logger) { - Console.WriteLine("Evicting old GraphQL schema."); + logger.LogInformation("Evicting old GraphQL schema."); requestExecutorResolver.EvictExecutor(); } diff --git a/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs b/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs new file mode 100644 index 0000000000..5ec4535d72 --- /dev/null +++ b/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs @@ -0,0 +1,345 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System; +using System.Globalization; +using System.IO; +using System.Text; +using Azure.DataApiBuilder.Product; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.DependencyInjection.Extensions; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Logging.Console; +using Microsoft.Extensions.Options; + +namespace Azure.DataApiBuilder.Service.Telemetry +{ + /// + /// Console formatter which reproduces the layout of the built-in "simple" console formatter + /// but prefixes every entry with an ISO 8601 UTC timestamp rendered with + /// : + /// + /// 2026-07-07T14:01:01.344Z info: Microsoft.AspNetCore.Hosting.Diagnostics[1] + /// Request starting HTTP/1.1 GET http://localhost:5000/graphql - - - + /// + /// The built-in formatter cannot be used for this because it renders the timestamp with + /// DateTimeOffset.ToString(TimestampFormat), which resolves against + /// . Its UseUtcTimestamp option only selects the + /// time zone, not the calendar or the digits, so on a machine using a non-Gregorian culture + /// (ar-SA, th-TH, fa-IR, ...) the built-in formatter emits e.g. 2569-08-29T05:29:44.113Z + /// instead of the required Gregorian 2026-08-29T05:29:44.113Z. + /// + public sealed class UtcTimestampConsoleFormatter : ConsoleFormatter, IDisposable + { + /// + /// Value to assign to to select this formatter. + /// + public const string FORMATTER_NAME = "dab-utc-simple"; + + /// + /// Separator written between the abbreviated log level and the category. + /// + private const string LOG_LEVEL_PADDING = ": "; + + /// + /// Indentation of the message lines, aligning them past "info: ". + /// + private static readonly string _messagePadding = new(' ', 4 + LOG_LEVEL_PADDING.Length); + + private static readonly string _newLineWithMessagePadding = Environment.NewLine + _messagePadding; + + private readonly IDisposable? _optionsReloadToken; + + private SimpleConsoleFormatterOptions _formatterOptions; + + public UtcTimestampConsoleFormatter(IOptionsMonitor options) + : base(FORMATTER_NAME) + { + _formatterOptions = options.CurrentValue; + _optionsReloadToken = options.OnChange(updatedOptions => _formatterOptions = updatedOptions); + } + + public void Dispose() => _optionsReloadToken?.Dispose(); + + /// + public override void Write(in LogEntry logEntry, IExternalScopeProvider? scopeProvider, TextWriter textWriter) + { + // Buffered entries are replayed later (ConsoleLogger.LogRecords passes a + // LogEntry whose Formatter and Exception are null), so the original + // event's timestamp, message and exception must be read off the record itself rather + // than recomputed at flush time. + if (logEntry.State is BufferedLogRecord bufferedRecord) + { + WriteInternal( + scopeProvider: null, + textWriter, + bufferedRecord.FormattedMessage ?? string.Empty, + bufferedRecord.LogLevel, + bufferedRecord.EventId.Id, + bufferedRecord.Exception, + logEntry.Category, + bufferedRecord.Timestamp); + return; + } + + string? message = logEntry.Formatter?.Invoke(logEntry.State, logEntry.Exception); + if (message is null && logEntry.Exception is null) + { + return; + } + + WriteInternal( + scopeProvider, + textWriter, + message ?? string.Empty, + logEntry.LogLevel, + logEntry.EventId.Id, + logEntry.Exception?.ToString(), + logEntry.Category, + DateTimeOffset.UtcNow); + } + + private void WriteInternal( + IExternalScopeProvider? scopeProvider, + TextWriter textWriter, + string message, + LogLevel logLevel, + int eventId, + string? exception, + string category, + DateTimeOffset stamp) + { + string? logLevelString = BootstrapLogger.GetAbbreviatedLogLevel(logLevel); + if (logLevelString is null) + { + return; + } + + // Untrusted values can reach the console through log messages, so neutralize the + // control characters which would otherwise drive terminal escape sequences. + message = SanitizeControlCharacters(message)!; + exception = SanitizeControlCharacters(exception); + category = SanitizeControlCharacters(category)!; + + SimpleConsoleFormatterOptions formatterOptions = _formatterOptions; + bool singleLine = formatterOptions.SingleLine; + + // The timestamp is rendered here (rather than through the formatter's TimestampFormat + // option) so that it is always UTC and always culture invariant. + textWriter.Write(stamp.UtcDateTime.ToString(BootstrapLogger.UTC_TIMESTAMP_FORMAT, CultureInfo.InvariantCulture)); + textWriter.Write(' '); + + if (EmitAnsiColorCodes(formatterOptions.ColorBehavior)) + { + WriteColoredLogLevel(textWriter, logLevel, logLevelString); + } + else + { + textWriter.Write(logLevelString); + } + + // Category and event id, e.g. ": Microsoft.AspNetCore.Hosting.Diagnostics[1]". + textWriter.Write(LOG_LEVEL_PADDING); + textWriter.Write(category); + textWriter.Write('['); + textWriter.Write(eventId.ToString(CultureInfo.InvariantCulture)); + textWriter.Write(']'); + + if (!singleLine) + { + textWriter.Write(Environment.NewLine); + } + + WriteScopeInformation(textWriter, scopeProvider, formatterOptions.IncludeScopes, singleLine); + WriteMessage(textWriter, message, singleLine); + + if (exception is not null) + { + WriteMessage(textWriter, exception, singleLine); + } + + if (singleLine) + { + textWriter.Write(Environment.NewLine); + } + } + + /// + /// Escapes the control characters which can drive terminal escape sequences when written to + /// a console - the C0 range (U+0000-U+001F), DEL (U+007F) and the C1 range (U+0080-U+009F) - + /// as \uXXXX. Tab, carriage return and line feed are preserved for log formatting. + /// Mirrors the sanitization the built-in console formatter applies. + /// + private static string? SanitizeControlCharacters(string? value) + { + if (string.IsNullOrEmpty(value)) + { + return value; + } + + int firstIndex = -1; + for (int i = 0; i < value.Length; i++) + { + if (ShouldEscape(value[i])) + { + firstIndex = i; + break; + } + } + + if (firstIndex < 0) + { + return value; + } + + StringBuilder sanitized = new(value.Length + 8); + sanitized.Append(value, 0, firstIndex); + for (int i = firstIndex; i < value.Length; i++) + { + char c = value[i]; + if (ShouldEscape(c)) + { + sanitized.Append("\\u").Append(((int)c).ToString("X4", CultureInfo.InvariantCulture)); + } + else + { + sanitized.Append(c); + } + } + + return sanitized.ToString(); + + static bool ShouldEscape(char c) + => c is not '\t' and not '\n' and not '\r' + && (c <= '\u001F' || (c >= '\u007F' && c <= '\u009F')); + } + + private static void WriteMessage(TextWriter textWriter, string? message, bool singleLine) + { + if (string.IsNullOrEmpty(message)) + { + return; + } + + if (singleLine) + { + textWriter.Write(' '); + textWriter.Write(message.Replace(Environment.NewLine, " ")); + } + else + { + textWriter.Write(_messagePadding); + textWriter.Write(message.Replace(Environment.NewLine, _newLineWithMessagePadding)); + textWriter.Write(Environment.NewLine); + } + } + + private static void WriteScopeInformation(TextWriter textWriter, IExternalScopeProvider? scopeProvider, bool includeScopes, bool singleLine) + { + if (!includeScopes || scopeProvider is null) + { + return; + } + + bool firstScope = true; + scopeProvider.ForEachScope((scope, state) => + { + if (firstScope) + { + state.Write(singleLine ? " => " : _messagePadding + "=> "); + firstScope = false; + } + else + { + state.Write(" => "); + } + + state.Write(scope); + }, textWriter); + + if (!firstScope && !singleLine) + { + textWriter.Write(Environment.NewLine); + } + } + + /// + /// Mirrors the built-in console formatter's decision on whether ANSI color codes may be + /// emitted, honoring the NO_COLOR convention and output redirection. + /// + private static bool EmitAnsiColorCodes(LoggerColorBehavior colorBehavior) + { + if (colorBehavior == LoggerColorBehavior.Disabled) + { + return false; + } + + if (colorBehavior == LoggerColorBehavior.Enabled) + { + return true; + } + + if (!string.IsNullOrEmpty(Environment.GetEnvironmentVariable("NO_COLOR"))) + { + return false; + } + + return !Console.IsOutputRedirected; + } + + /// + /// Writes the abbreviated log level using the same colors as the built-in console formatter. + /// + private static void WriteColoredLogLevel(TextWriter textWriter, LogLevel logLevel, string logLevelString) + { + const string RESET_FOREGROUND = "\u001b[39m\u001b[22m"; + const string RESET_BACKGROUND = "\u001b[49m"; + + (string Foreground, string Background) colors = logLevel switch + { + // White on dark red. + LogLevel.Critical => ("\u001b[1m\u001b[37m", "\u001b[41m"), + // Black on dark red. + LogLevel.Error => ("\u001b[30m", "\u001b[41m"), + // Yellow on black. + LogLevel.Warning => ("\u001b[1m\u001b[33m", "\u001b[40m"), + // Dark green on black. + LogLevel.Information => ("\u001b[32m", "\u001b[40m"), + // Gray on black. + _ => ("\u001b[37m", "\u001b[40m") + }; + + textWriter.Write(colors.Background); + textWriter.Write(colors.Foreground); + textWriter.Write(logLevelString); + textWriter.Write(RESET_FOREGROUND); + textWriter.Write(RESET_BACKGROUND); + } + } + + /// + /// Registration helpers for . + /// + public static class UtcTimestampConsoleFormatterExtensions + { + /// + /// Registers and selects it on the console logger + /// provider so every console entry is prefixed with a culture invariant ISO 8601 UTC timestamp. + /// This only registers a formatter - the caller remains responsible for registering the console + /// provider exactly once - so it can be applied to a pipeline which already has one (e.g. the + /// provider added by ) + /// without emitting duplicate entries. + /// + public static ILoggingBuilder AddUtcTimestampConsoleFormatter(this ILoggingBuilder builder) + { + builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton()); + builder.Services.Configure(options => + { + options.FormatterName = UtcTimestampConsoleFormatter.FORMATTER_NAME; + }); + + return builder; + } + } +}