From 1bc2a58ac8eb328283772dc1bff3fc983746ff35 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 8 Jul 2026 16:30:35 +0000 Subject: [PATCH 01/15] Initial plan From 566bf117fd9fd61b05b56be4567cf134854b355c Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 8 Jul 2026 16:38:59 +0000 Subject: [PATCH 02/15] feat: add UTC timestamps to console log entries --- src/Cli.Tests/CustomLoggerTests.cs | 4 ++-- src/Cli/CustomLoggerProvider.cs | 6 ++++-- src/Service/Program.cs | 16 +++++++++++++++- 3 files changed, 21 insertions(+), 5 deletions(-) diff --git a/src/Cli.Tests/CustomLoggerTests.cs b/src/Cli.Tests/CustomLoggerTests.cs index cce73f0f75..c02e218f0a 100644 --- a/src/Cli.Tests/CustomLoggerTests.cs +++ b/src/Cli.Tests/CustomLoggerTests.cs @@ -77,8 +77,8 @@ public void LogOutput_UsesAbbreviatedLogLevelLabels(LogLevel logLevel, string ex string actual = expectStderr ? stderr : stdout; string other = expectStderr ? stdout : stderr; - Assert.IsTrue(actual.StartsWith(expectedPrefix), - $"Expected output to start with '{expectedPrefix}' but got: '{actual}'"); + Assert.IsTrue(actual.Contains(expectedPrefix), + $"Expected output to contain '{expectedPrefix}' but got: '{actual}'"); StringAssert.Contains(actual, Message); Assert.AreEqual(string.Empty, other, $"Did not expect output on the other stream but got: '{other}'"); diff --git a/src/Cli/CustomLoggerProvider.cs b/src/Cli/CustomLoggerProvider.cs index a4625b0924..c5af88c7fc 100644 --- a/src/Cli/CustomLoggerProvider.cs +++ b/src/Cli/CustomLoggerProvider.cs @@ -124,13 +124,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("yyyy-MM-dd'T'HH:mm:ss.fff'Z'"); 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 +154,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("yyyy-MM-dd'T'HH:mm:ss.fff'Z'"); // 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 +163,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/Service/Program.cs b/src/Service/Program.cs index 76af52ba97..924ca81c4e 100644 --- a/src/Service/Program.cs +++ b/src/Service/Program.cs @@ -194,6 +194,11 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st else { logging.SetMinimumLevel(LogLevelProvider.CurrentLogLevel); + logging.AddSimpleConsole(options => + { + options.TimestampFormat = "yyyy-MM-dd'T'HH:mm:ss.fff'Z' "; + options.UseUtcTimestamp = true; + }); } // Add filter for dynamic log level changes (e.g., via MCP logging/setLevel) @@ -464,6 +469,11 @@ public static ILoggerFactory GetLoggerFactoryForLogLevel( // When LogLevel.None, skip the console logger entirely for true silence. if (LogLevelProvider.CurrentLogLevel != LogLevel.None) { + builder.AddSimpleConsole(options => + { + options.TimestampFormat = "yyyy-MM-dd'T'HH:mm:ss.fff'Z' "; + options.UseUtcTimestamp = true; + }); builder.AddConsole(options => { options.LogToStandardErrorThreshold = LogLevel.Trace; @@ -472,7 +482,11 @@ public static ILoggerFactory GetLoggerFactoryForLogLevel( } else { - builder.AddConsole(); + builder.AddSimpleConsole(options => + { + options.TimestampFormat = "yyyy-MM-dd'T'HH:mm:ss.fff'Z' "; + options.UseUtcTimestamp = true; + }); } }); } From 405f145ed2493bb791ff5e0b96d5726b62ec6371 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 8 Jul 2026 16:41:53 +0000 Subject: [PATCH 03/15] refactor: extract timestamp constant and clarify stdio console config --- src/Cli/CustomLoggerProvider.cs | 6 ++++-- src/Service/Program.cs | 5 ++++- 2 files changed, 8 insertions(+), 3 deletions(-) diff --git a/src/Cli/CustomLoggerProvider.cs b/src/Cli/CustomLoggerProvider.cs index c5af88c7fc..89fbe8b8eb 100644 --- a/src/Cli/CustomLoggerProvider.cs +++ b/src/Cli/CustomLoggerProvider.cs @@ -25,6 +25,8 @@ public ILogger CreateLogger(string categoryName) public class CustomConsoleLogger : ILogger { + private const string UtcTimestampFormat = "yyyy-MM-dd'T'HH:mm:ss.fff'Z'"; + private readonly LogLevel _minimumLogLevel; // Minimum LogLevel for CLI output. @@ -124,7 +126,7 @@ 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("yyyy-MM-dd'T'HH:mm:ss.fff'Z'"); + string mcpTimestamp = DateTime.UtcNow.ToString(UtcTimestampFormat); ConsoleColor mcpOriginalForeGroundColor = Console.ForegroundColor; ConsoleColor mcpOriginalBackGroundColor = Console.BackgroundColor; try @@ -154,7 +156,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("yyyy-MM-dd'T'HH:mm:ss.fff'Z'"); + string timestamp = DateTime.UtcNow.ToString(UtcTimestampFormat); // 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; diff --git a/src/Service/Program.cs b/src/Service/Program.cs index 924ca81c4e..ddef5851a2 100644 --- a/src/Service/Program.cs +++ b/src/Service/Program.cs @@ -26,6 +26,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; @@ -474,7 +475,9 @@ public static ILoggerFactory GetLoggerFactoryForLogLevel( options.TimestampFormat = "yyyy-MM-dd'T'HH:mm:ss.fff'Z' "; options.UseUtcTimestamp = true; }); - builder.AddConsole(options => + // Route all levels to stderr to keep stdout clean for MCP JSON-RPC. + // Uses Services.Configure (not AddConsole) so no second provider is registered. + builder.Services.Configure(options => { options.LogToStandardErrorThreshold = LogLevel.Trace; }); From 54c882f09c31d0927151c5359bbda5542a51e33f Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 13 Jul 2026 16:09:28 +0000 Subject: [PATCH 04/15] fix: address timestamp logging review feedback --- src/Cli.Tests/CustomLoggerTests.cs | 7 +++++-- src/Cli/CustomLoggerProvider.cs | 7 ++++--- src/Service/Program.cs | 2 +- 3 files changed, 10 insertions(+), 6 deletions(-) diff --git a/src/Cli.Tests/CustomLoggerTests.cs b/src/Cli.Tests/CustomLoggerTests.cs index c02e218f0a..7d66839e58 100644 --- a/src/Cli.Tests/CustomLoggerTests.cs +++ b/src/Cli.Tests/CustomLoggerTests.cs @@ -1,6 +1,8 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. +using System.Text.RegularExpressions; + namespace Cli.Tests; /// @@ -77,8 +79,9 @@ public void LogOutput_UsesAbbreviatedLogLevelLabels(LogLevel logLevel, string ex string actual = expectStderr ? stderr : stdout; string other = expectStderr ? stdout : stderr; - Assert.IsTrue(actual.Contains(expectedPrefix), - $"Expected output to contain '{expectedPrefix}' but got: '{actual}'"); + Assert.IsTrue( + Regex.IsMatch(actual, $@"^\d{{4}}-\d{{2}}-\d{{2}}T\d{{2}}:\d{{2}}:\d{{2}}\.\d{{3}}Z {Regex.Escape(expectedPrefix)}"), + $"Expected output to start with an ISO 8601 UTC timestamp followed 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}'"); diff --git a/src/Cli/CustomLoggerProvider.cs b/src/Cli/CustomLoggerProvider.cs index 89fbe8b8eb..532cd74f2c 100644 --- a/src/Cli/CustomLoggerProvider.cs +++ b/src/Cli/CustomLoggerProvider.cs @@ -1,6 +1,7 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. +using System.Globalization; using Microsoft.Extensions.Logging; /// @@ -25,7 +26,7 @@ public ILogger CreateLogger(string categoryName) public class CustomConsoleLogger : ILogger { - private const string UtcTimestampFormat = "yyyy-MM-dd'T'HH:mm:ss.fff'Z'"; + private const string UTC_TIMESTAMP_FORMAT = "yyyy-MM-dd'T'HH:mm:ss.fff'Z'"; private readonly LogLevel _minimumLogLevel; @@ -126,7 +127,7 @@ 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(UtcTimestampFormat); + string mcpTimestamp = DateTime.UtcNow.ToString(UTC_TIMESTAMP_FORMAT, CultureInfo.InvariantCulture); ConsoleColor mcpOriginalForeGroundColor = Console.ForegroundColor; ConsoleColor mcpOriginalBackGroundColor = Console.BackgroundColor; try @@ -156,7 +157,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(UtcTimestampFormat); + 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; diff --git a/src/Service/Program.cs b/src/Service/Program.cs index ddef5851a2..ca7186698d 100644 --- a/src/Service/Program.cs +++ b/src/Service/Program.cs @@ -195,7 +195,7 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st else { logging.SetMinimumLevel(LogLevelProvider.CurrentLogLevel); - logging.AddSimpleConsole(options => + logging.Services.Configure(options => { options.TimestampFormat = "yyyy-MM-dd'T'HH:mm:ss.fff'Z' "; options.UseUtcTimestamp = true; From 792a937763dbfefb508b34bb93bb0fdbe1175586 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Fri, 28 Aug 2026 23:37:09 +0000 Subject: [PATCH 05/15] Add centralized BootstrapLogger for timestamped console diagnostics Co-authored-by: aaronburtle <93220300+aaronburtle@users.noreply.github.com> --- src/Config/Utilities/BootstrapLogger.cs | 78 +++++++++++++++++++++++++ 1 file changed, 78 insertions(+) create mode 100644 src/Config/Utilities/BootstrapLogger.cs diff --git a/src/Config/Utilities/BootstrapLogger.cs b/src/Config/Utilities/BootstrapLogger.cs new file mode 100644 index 0000000000..280519b3aa --- /dev/null +++ b/src/Config/Utilities/BootstrapLogger.cs @@ -0,0 +1,78 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System.Globalization; +using Microsoft.Extensions.Logging; + +namespace Azure.DataApiBuilder.Config.Utilities; + +/// +/// 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. + /// + private 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" } + }; + + /// + /// 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}"); + } + } +} From d7fbf1b1503e7d0304d9023f8842cd60e8159cbd Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Fri, 28 Aug 2026 23:45:27 +0000 Subject: [PATCH 06/15] Route direct console diagnostics through loggers with UTC timestamps Co-authored-by: aaronburtle <93220300+aaronburtle@users.noreply.github.com> --- src/Cli/CustomLoggerProvider.cs | 3 +- src/Cli/Program.cs | 4 + src/Config/ConfigFileWatcher.cs | 9 +- src/Config/FileSystemRuntimeConfigLoader.cs | 8 +- src/Config/Utilities/BootstrapLogger.cs | 5 +- src/Config/Utilities/FileUtilities.cs | 5 +- .../Configurations/RuntimeConfigProvider.cs | 5 +- src/Core/Resolvers/SqlPaginationUtil.cs | 8 +- .../UnitTests/BootstrapLoggerTests.cs | 105 ++++++++++++++++++ src/Service/Program.cs | 24 ++-- src/Service/Startup.cs | 8 +- 11 files changed, 156 insertions(+), 28 deletions(-) create mode 100644 src/Service.Tests/UnitTests/BootstrapLoggerTests.cs diff --git a/src/Cli/CustomLoggerProvider.cs b/src/Cli/CustomLoggerProvider.cs index 532cd74f2c..e8e0e0473f 100644 --- a/src/Cli/CustomLoggerProvider.cs +++ b/src/Cli/CustomLoggerProvider.cs @@ -2,6 +2,7 @@ // Licensed under the MIT License. using System.Globalization; +using Azure.DataApiBuilder.Config.Utilities; using Microsoft.Extensions.Logging; /// @@ -26,7 +27,7 @@ public ILogger CreateLogger(string categoryName) public class CustomConsoleLogger : ILogger { - private const string UTC_TIMESTAMP_FORMAT = "yyyy-MM-dd'T'HH:mm:ss.fff'Z'"; + private const string UTC_TIMESTAMP_FORMAT = BootstrapLogger.UTC_TIMESTAMP_FORMAT; private readonly LogLevel _minimumLogLevel; diff --git a/src/Cli/Program.cs b/src/Cli/Program.cs index faba1ee6d5..2eb59703c7 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.Config.Utilities; 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..74a90f7b56 100644 --- a/src/Config/ConfigFileWatcher.cs +++ b/src/Config/ConfigFileWatcher.cs @@ -3,6 +3,7 @@ using System.IO.Abstractions; using Azure.DataApiBuilder.Config.Utilities; +using Microsoft.Extensions.Logging; namespace Azure.DataApiBuilder.Config; @@ -109,17 +110,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..7055728ec2 100644 --- a/src/Config/FileSystemRuntimeConfigLoader.cs +++ b/src/Config/FileSystemRuntimeConfigLoader.cs @@ -181,8 +181,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 +208,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/BootstrapLogger.cs b/src/Config/Utilities/BootstrapLogger.cs index 280519b3aa..2d75ed87cf 100644 --- a/src/Config/Utilities/BootstrapLogger.cs +++ b/src/Config/Utilities/BootstrapLogger.cs @@ -19,9 +19,10 @@ namespace Azure.DataApiBuilder.Config.Utilities; public static class BootstrapLogger { /// - /// ISO 8601 UTC timestamp with millisecond precision. + /// ISO 8601 UTC timestamp with millisecond precision. Shared by every console + /// logging path (engine, CLI and bootstrap) so all entries look identical. /// - private const string UTC_TIMESTAMP_FORMAT = "yyyy-MM-dd'T'HH:mm:ss.fff'Z'"; + 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. diff --git a/src/Config/Utilities/FileUtilities.cs b/src/Config/Utilities/FileUtilities.cs index 549d6dd720..eef037d10a 100644 --- a/src/Config/Utilities/FileUtilities.cs +++ b/src/Config/Utilities/FileUtilities.cs @@ -3,6 +3,7 @@ using System.IO.Abstractions; using System.Security.Cryptography; +using Microsoft.Extensions.Logging; namespace Azure.DataApiBuilder.Config.Utilities; @@ -61,13 +62,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..8bcd570f47 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.Config.Utilities; 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..3d95a661d6 100644 --- a/src/Core/Resolvers/SqlPaginationUtil.cs +++ b/src/Core/Resolvers/SqlPaginationUtil.cs @@ -6,6 +6,7 @@ using System.Text.Json; using System.Text.Json.Nodes; using System.Text.Json.Serialization; +using Azure.DataApiBuilder.Config.Utilities; using Azure.DataApiBuilder.Core.Configurations; using Azure.DataApiBuilder.Core.Models; using Azure.DataApiBuilder.Core.Parsers; @@ -15,6 +16,7 @@ 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/Service.Tests/UnitTests/BootstrapLoggerTests.cs b/src/Service.Tests/UnitTests/BootstrapLoggerTests.cs new file mode 100644 index 0000000000..122bbd2a16 --- /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.Config.Utilities; +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/Program.cs b/src/Service/Program.cs index ca7186698d..b2b28e7a9f 100644 --- a/src/Service/Program.cs +++ b/src/Service/Program.cs @@ -11,6 +11,7 @@ using System.Threading.Tasks; using Azure.DataApiBuilder.Config; using Azure.DataApiBuilder.Config.ObjectModel; +using Azure.DataApiBuilder.Config.Utilities; using Azure.DataApiBuilder.Core.Telemetry; using Azure.DataApiBuilder.Mcp.Core; using Azure.DataApiBuilder.Mcp.Telemetry; @@ -38,6 +39,12 @@ namespace Azure.DataApiBuilder.Service { public class Program { + /// + /// ISO 8601 UTC timestamp with millisecond precision, followed by the separator + /// the console formatter places between the timestamp and the log entry. + /// + private const string CONSOLE_TIMESTAMP_FORMAT = BootstrapLogger.UTC_TIMESTAMP_FORMAT + " "; + public static bool IsHttpsRedirectionDisabled { get; private set; } public static DynamicLogLevelProvider LogLevelProvider = new(); @@ -81,7 +88,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; } @@ -107,6 +114,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) @@ -136,13 +146,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; } } @@ -197,7 +207,7 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st logging.SetMinimumLevel(LogLevelProvider.CurrentLogLevel); logging.Services.Configure(options => { - options.TimestampFormat = "yyyy-MM-dd'T'HH:mm:ss.fff'Z' "; + options.TimestampFormat = CONSOLE_TIMESTAMP_FORMAT; options.UseUtcTimestamp = true; }); } @@ -472,7 +482,7 @@ public static ILoggerFactory GetLoggerFactoryForLogLevel( { builder.AddSimpleConsole(options => { - options.TimestampFormat = "yyyy-MM-dd'T'HH:mm:ss.fff'Z' "; + options.TimestampFormat = CONSOLE_TIMESTAMP_FORMAT; options.UseUtcTimestamp = true; }); // Route all levels to stderr to keep stdout clean for MCP JSON-RPC. @@ -487,7 +497,7 @@ public static ILoggerFactory GetLoggerFactoryForLogLevel( { builder.AddSimpleConsole(options => { - options.TimestampFormat = "yyyy-MM-dd'T'HH:mm:ss.fff'Z' "; + options.TimestampFormat = CONSOLE_TIMESTAMP_FORMAT; options.UseUtcTimestamp = true; }); } @@ -508,7 +518,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(); } From 0a43f4ce7a120eff0d9c56a13f8a925fc8a6e954 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sat, 29 Aug 2026 00:16:42 +0000 Subject: [PATCH 07/15] Add timestamp coverage for logger factories, host logging and migrated diagnostics Co-authored-by: aaronburtle <93220300+aaronburtle@users.noreply.github.com> --- src/Cli.Tests/CustomLoggerTests.cs | 112 +++++- .../UnitTests/ConsoleLogTimestampTests.cs | 328 ++++++++++++++++++ src/Service/Program.cs | 96 +++-- 3 files changed, 486 insertions(+), 50 deletions(-) create mode 100644 src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs diff --git a/src/Cli.Tests/CustomLoggerTests.cs b/src/Cli.Tests/CustomLoggerTests.cs index 7d66839e58..0435af4169 100644 --- a/src/Cli.Tests/CustomLoggerTests.cs +++ b/src/Cli.Tests/CustomLoggerTests.cs @@ -1,6 +1,7 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. +using System.Globalization; using System.Text.RegularExpressions; namespace Cli.Tests; @@ -31,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 { @@ -54,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() => @@ -74,14 +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( - Regex.IsMatch(actual, $@"^\d{{4}}-\d{{2}}-\d{{2}}T\d{{2}}:\d{{2}}:\d{{2}}\.\d{{3}}Z {Regex.Escape(expectedPrefix)}"), - $"Expected output to start with an ISO 8601 UTC timestamp followed by '{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}'"); @@ -97,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"); @@ -120,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 @@ -132,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}'"); } /// @@ -146,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}'"); } /// @@ -171,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/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs new file mode 100644 index 0000000000..81e1915aa8 --- /dev/null +++ b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs @@ -0,0 +1,328 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +#nullable enable + +using System; +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.Service.Telemetry; +using Microsoft.AspNetCore.Http; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +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}'"); + } + + /// + /// 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); + } + } +} diff --git a/src/Service/Program.cs b/src/Service/Program.cs index b2b28e7a9f..927504f08d 100644 --- a/src/Service/Program.cs +++ b/src/Service/Program.cs @@ -187,42 +187,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); - logging.Services.Configure(options => - { - options.TimestampFormat = CONSOLE_TIMESTAMP_FORMAT; - options.UseUtcTimestamp = true; - }); - } - - // 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. @@ -236,6 +201,65 @@ 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 options are configured so no second provider is registered (which would + // emit every entry twice). ConsoleLoggerOptions.FormatterName must be set explicitly: + // when it is left unset the provider ignores SimpleConsoleFormatterOptions and derives + // the formatter options from ConsoleLoggerOptions' own (obsolete) properties instead, + // which would silently drop the timestamp. + logging.Services.Configure(options => + { + options.FormatterName = ConsoleFormatterNames.Simple; + }); + logging.Services.Configure(options => + { + options.TimestampFormat = CONSOLE_TIMESTAMP_FORMAT; + options.UseUtcTimestamp = true; + }); + } + + // 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. From 7d2449932ba5563ff22b3218b952ae85bcd1546c Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sat, 29 Aug 2026 06:06:01 +0000 Subject: [PATCH 08/15] Format console log timestamps with invariant culture via custom formatter Co-authored-by: aaronburtle <93220300+aaronburtle@users.noreply.github.com> --- src/Config/Utilities/BootstrapLogger.cs | 7 + .../UnitTests/ConsoleLogTimestampTests.cs | 118 +++++++++ src/Service/Program.cs | 42 +-- .../Telemetry/UtcTimestampConsoleFormatter.cs | 249 ++++++++++++++++++ 4 files changed, 385 insertions(+), 31 deletions(-) create mode 100644 src/Service/Telemetry/UtcTimestampConsoleFormatter.cs diff --git a/src/Config/Utilities/BootstrapLogger.cs b/src/Config/Utilities/BootstrapLogger.cs index 2d75ed87cf..6fa5de8bc9 100644 --- a/src/Config/Utilities/BootstrapLogger.cs +++ b/src/Config/Utilities/BootstrapLogger.cs @@ -37,6 +37,13 @@ public static class BootstrapLogger { 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. diff --git a/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs index 81e1915aa8..884a7524d5 100644 --- a/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs +++ b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs @@ -258,6 +258,124 @@ public void ConfigureHostLogging_StdioMode_WritesNothingToConsole() 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. diff --git a/src/Service/Program.cs b/src/Service/Program.cs index 927504f08d..0b2360e529 100644 --- a/src/Service/Program.cs +++ b/src/Service/Program.cs @@ -39,12 +39,6 @@ namespace Azure.DataApiBuilder.Service { public class Program { - /// - /// ISO 8601 UTC timestamp with millisecond precision, followed by the separator - /// the console formatter places between the timestamp and the log entry. - /// - private const string CONSOLE_TIMESTAMP_FORMAT = BootstrapLogger.UTC_TIMESTAMP_FORMAT + " "; - public static bool IsHttpsRedirectionDisabled { get; private set; } public static DynamicLogLevelProvider LogLevelProvider = new(); @@ -232,20 +226,12 @@ public static void ConfigureHostLogging(ILoggingBuilder logging, bool runMcpStdi logging.SetMinimumLevel(LogLevelProvider.CurrentLogLevel); // The console provider registered by Host.CreateDefaultBuilder() is reused as-is; - // only its options are configured so no second provider is registered (which would - // emit every entry twice). ConsoleLoggerOptions.FormatterName must be set explicitly: - // when it is left unset the provider ignores SimpleConsoleFormatterOptions and derives - // the formatter options from ConsoleLoggerOptions' own (obsolete) properties instead, - // which would silently drop the timestamp. - logging.Services.Configure(options => - { - options.FormatterName = ConsoleFormatterNames.Simple; - }); - logging.Services.Configure(options => - { - options.TimestampFormat = CONSOLE_TIMESTAMP_FORMAT; - options.UseUtcTimestamp = true; - }); + // 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) @@ -504,13 +490,10 @@ public static ILoggerFactory GetLoggerFactoryForLogLevel( // When LogLevel.None, skip the console logger entirely for true silence. if (LogLevelProvider.CurrentLogLevel != LogLevel.None) { - builder.AddSimpleConsole(options => - { - options.TimestampFormat = CONSOLE_TIMESTAMP_FORMAT; - options.UseUtcTimestamp = true; - }); + builder.AddConsole(); + builder.AddUtcTimestampConsoleFormatter(); // Route all levels to stderr to keep stdout clean for MCP JSON-RPC. - // Uses Services.Configure (not AddConsole) so no second provider is registered. + // Uses Services.Configure (not a second AddConsole) so no second provider is registered. builder.Services.Configure(options => { options.LogToStandardErrorThreshold = LogLevel.Trace; @@ -519,11 +502,8 @@ public static ILoggerFactory GetLoggerFactoryForLogLevel( } else { - builder.AddSimpleConsole(options => - { - options.TimestampFormat = CONSOLE_TIMESTAMP_FORMAT; - options.UseUtcTimestamp = true; - }); + builder.AddConsole(); + builder.AddUtcTimestampConsoleFormatter(); } }); } diff --git a/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs b/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs new file mode 100644 index 0000000000..d7422ae23f --- /dev/null +++ b/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs @@ -0,0 +1,249 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System; +using System.Globalization; +using System.IO; +using Azure.DataApiBuilder.Config.Utilities; +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) + { + string? message = logEntry.Formatter?.Invoke(logEntry.State, logEntry.Exception); + if (message is null && logEntry.Exception is null) + { + return; + } + + string? logLevelString = BootstrapLogger.GetAbbreviatedLogLevel(logEntry.LogLevel); + if (logLevelString is null) + { + return; + } + + SimpleConsoleFormatterOptions formatterOptions = _formatterOptions; + bool singleLine = formatterOptions.SingleLine; + + // The timestamp is generated here (rather than through the formatter's TimestampFormat + // option) so that it is always UTC and always culture invariant. + textWriter.Write(DateTime.UtcNow.ToString(BootstrapLogger.UTC_TIMESTAMP_FORMAT, CultureInfo.InvariantCulture)); + textWriter.Write(' '); + + if (EmitAnsiColorCodes(formatterOptions.ColorBehavior)) + { + WriteColoredLogLevel(textWriter, logEntry.LogLevel, logLevelString); + } + else + { + textWriter.Write(logLevelString); + } + + // Category and event id, e.g. ": Microsoft.AspNetCore.Hosting.Diagnostics[1]". + textWriter.Write(LOG_LEVEL_PADDING); + textWriter.Write(logEntry.Category); + textWriter.Write('['); + textWriter.Write(logEntry.EventId.Id.ToString(CultureInfo.InvariantCulture)); + textWriter.Write(']'); + + if (!singleLine) + { + textWriter.Write(Environment.NewLine); + } + + WriteScopeInformation(textWriter, scopeProvider, formatterOptions.IncludeScopes, singleLine); + WriteMessage(textWriter, message, singleLine); + + if (logEntry.Exception is not null) + { + WriteMessage(textWriter, logEntry.Exception.ToString(), singleLine); + } + + if (singleLine) + { + textWriter.Write(Environment.NewLine); + } + } + + 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; + } + } +} From 5a7e03863f9178024f3c4c9dfa43a6a3556aee83 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sat, 29 Aug 2026 06:16:56 +0000 Subject: [PATCH 09/15] Route Aspire AppHost diagnostics through BootstrapLogger and guard the inventory Co-authored-by: aaronburtle <93220300+aaronburtle@users.noreply.github.com> --- src/Aspire.AppHost/AppHost.cs | 8 +- src/Aspire.AppHost/Aspire.AppHost.csproj | 3 + .../UnitTests/ConsoleLogTimestampTests.cs | 102 ++++++++++++++++++ 3 files changed, 110 insertions(+), 3 deletions(-) diff --git a/src/Aspire.AppHost/AppHost.cs b/src/Aspire.AppHost/AppHost.cs index 428b75a499..6150f25452 100644 --- a/src/Aspire.AppHost/AppHost.cs +++ b/src/Aspire.AppHost/AppHost.cs @@ -1,4 +1,6 @@ +using Azure.DataApiBuilder.Config.Utilities; 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..a6a6c16567 100644 --- a/src/Aspire.AppHost/Aspire.AppHost.csproj +++ b/src/Aspire.AppHost/Aspire.AppHost.csproj @@ -22,6 +22,9 @@ + + diff --git a/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs index 884a7524d5..e1243d56b8 100644 --- a/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs +++ b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs @@ -4,6 +4,7 @@ #nullable enable using System; +using System.Collections.Generic; using System.Globalization; using System.IO; using System.IO.Abstractions; @@ -442,5 +443,106 @@ public void BootstrapLogger_StdErrRouting_EmitsTimestampedEntryOnStandardErrorOn AssertEveryEntryTimestamped(stderr, before, after); StringAssert.Contains(stderr, LOG_MESSAGE); } + + /// + /// 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(); + string[] productionProjects = + { + "Aspire.AppHost", "Auth", "Azure.DataApiBuilder.Mcp", "Cli", + "Config", "Core", "Service", "Service.GraphQLBuilder" + }; + + List violations = new(); + foreach (string project in productionProjects) + { + string projectPath = Path.Combine(sourceRoot.FullName, project); + Assert.IsTrue(Directory.Exists(projectPath), $"Expected production project directory '{projectPath}' to exist."); + + foreach (string file in Directory.EnumerateFiles(projectPath, "*.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)}"); + } + + /// + /// 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}'."); + } } } From 360c0583e05ee7f6854897fdf79a77b689e4d8bf Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sat, 29 Aug 2026 11:28:34 +0000 Subject: [PATCH 10/15] Preserve BufferedLogRecord semantics and sanitize control chars in console formatter Co-authored-by: aaronburtle <93220300+aaronburtle@users.noreply.github.com> --- .../UnitTests/ConsoleLogTimestampTests.cs | 120 ++++++++++++++++++ .../Telemetry/UtcTimestampConsoleFormatter.cs | 112 ++++++++++++++-- 2 files changed, 224 insertions(+), 8 deletions(-) diff --git a/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs index e1243d56b8..0033a58eee 100644 --- a/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs +++ b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs @@ -16,6 +16,7 @@ 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; @@ -444,6 +445,125 @@ public void BootstrapLogger_StdErrRouting_EmitsTimestampedEntryOnStandardErrorOn 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(. diff --git a/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs b/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs index d7422ae23f..07e375583d 100644 --- a/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs +++ b/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs @@ -4,6 +4,7 @@ using System; using System.Globalization; using System.IO; +using System.Text; using Azure.DataApiBuilder.Config.Utilities; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.DependencyInjection.Extensions; @@ -64,29 +65,74 @@ public UtcTimestampConsoleFormatter(IOptionsMonitor 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; } - string? logLevelString = BootstrapLogger.GetAbbreviatedLogLevel(logEntry.LogLevel); + 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 generated here (rather than through the formatter's TimestampFormat + // 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(DateTime.UtcNow.ToString(BootstrapLogger.UTC_TIMESTAMP_FORMAT, CultureInfo.InvariantCulture)); + textWriter.Write(stamp.UtcDateTime.ToString(BootstrapLogger.UTC_TIMESTAMP_FORMAT, CultureInfo.InvariantCulture)); textWriter.Write(' '); if (EmitAnsiColorCodes(formatterOptions.ColorBehavior)) { - WriteColoredLogLevel(textWriter, logEntry.LogLevel, logLevelString); + WriteColoredLogLevel(textWriter, logLevel, logLevelString); } else { @@ -95,9 +141,9 @@ public override void Write(in LogEntry logEntry, IExternalScopeP // Category and event id, e.g. ": Microsoft.AspNetCore.Hosting.Diagnostics[1]". textWriter.Write(LOG_LEVEL_PADDING); - textWriter.Write(logEntry.Category); + textWriter.Write(category); textWriter.Write('['); - textWriter.Write(logEntry.EventId.Id.ToString(CultureInfo.InvariantCulture)); + textWriter.Write(eventId.ToString(CultureInfo.InvariantCulture)); textWriter.Write(']'); if (!singleLine) @@ -108,9 +154,9 @@ public override void Write(in LogEntry logEntry, IExternalScopeP WriteScopeInformation(textWriter, scopeProvider, formatterOptions.IncludeScopes, singleLine); WriteMessage(textWriter, message, singleLine); - if (logEntry.Exception is not null) + if (exception is not null) { - WriteMessage(textWriter, logEntry.Exception.ToString(), singleLine); + WriteMessage(textWriter, exception, singleLine); } if (singleLine) @@ -119,6 +165,56 @@ public override void Write(in LogEntry logEntry, IExternalScopeP } } + /// + /// 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)) From 59dd5a1697e3a6d8022f570beb892ac107d5a70d Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Sat, 29 Aug 2026 11:47:21 +0000 Subject: [PATCH 11/15] Move BootstrapLogger to dependency-light Product project and widen console guard Co-authored-by: aaronburtle <93220300+aaronburtle@users.noreply.github.com> --- src/Aspire.AppHost/AppHost.cs | 2 +- src/Aspire.AppHost/Aspire.AppHost.csproj | 6 +- src/Cli/CustomLoggerProvider.cs | 2 +- src/Cli/Program.cs | 2 +- src/Config/ConfigFileWatcher.cs | 1 + src/Config/FileSystemRuntimeConfigLoader.cs | 1 + src/Config/Utilities/FileUtilities.cs | 1 + .../Configurations/RuntimeConfigProvider.cs | 2 +- src/Core/Resolvers/SqlPaginationUtil.cs | 2 +- src/Directory.Packages.props | 1 + .../Azure.DataApiBuilder.Product.csproj | 7 ++ .../Utilities => Product}/BootstrapLogger.cs | 2 +- .../UnitTests/BootstrapLoggerTests.cs | 2 +- .../UnitTests/ConsoleLogTimestampTests.cs | 84 ++++++++++++++++--- src/Service/Program.cs | 2 +- .../Telemetry/UtcTimestampConsoleFormatter.cs | 2 +- 16 files changed, 98 insertions(+), 21 deletions(-) rename src/{Config/Utilities => Product}/BootstrapLogger.cs (98%) diff --git a/src/Aspire.AppHost/AppHost.cs b/src/Aspire.AppHost/AppHost.cs index 6150f25452..b51bffb922 100644 --- a/src/Aspire.AppHost/AppHost.cs +++ b/src/Aspire.AppHost/AppHost.cs @@ -1,4 +1,4 @@ -using Azure.DataApiBuilder.Config.Utilities; +using Azure.DataApiBuilder.Product; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; diff --git a/src/Aspire.AppHost/Aspire.AppHost.csproj b/src/Aspire.AppHost/Aspire.AppHost.csproj index a6a6c16567..c88765b35b 100644 --- a/src/Aspire.AppHost/Aspire.AppHost.csproj +++ b/src/Aspire.AppHost/Aspire.AppHost.csproj @@ -23,8 +23,10 @@ - + the shared BootstrapLogger and emit the same timestamped console format as the engine. + Product is dependency light (ILogger abstractions only), so this does not pull the + engine's Azure dependency graph into AppHost and cause assembly version conflicts. --> + diff --git a/src/Cli/CustomLoggerProvider.cs b/src/Cli/CustomLoggerProvider.cs index e8e0e0473f..99a596df6f 100644 --- a/src/Cli/CustomLoggerProvider.cs +++ b/src/Cli/CustomLoggerProvider.cs @@ -2,7 +2,7 @@ // Licensed under the MIT License. using System.Globalization; -using Azure.DataApiBuilder.Config.Utilities; +using Azure.DataApiBuilder.Product; using Microsoft.Extensions.Logging; /// diff --git a/src/Cli/Program.cs b/src/Cli/Program.cs index 2eb59703c7..8983eeee93 100644 --- a/src/Cli/Program.cs +++ b/src/Cli/Program.cs @@ -3,7 +3,7 @@ using System.IO.Abstractions; using Azure.DataApiBuilder.Config; -using Azure.DataApiBuilder.Config.Utilities; +using Azure.DataApiBuilder.Product; using Cli.Commands; using CommandLine; using Microsoft.Extensions.Logging; diff --git a/src/Config/ConfigFileWatcher.cs b/src/Config/ConfigFileWatcher.cs index 74a90f7b56..4867fc10bf 100644 --- a/src/Config/ConfigFileWatcher.cs +++ b/src/Config/ConfigFileWatcher.cs @@ -3,6 +3,7 @@ using System.IO.Abstractions; using Azure.DataApiBuilder.Config.Utilities; +using Azure.DataApiBuilder.Product; using Microsoft.Extensions.Logging; namespace Azure.DataApiBuilder.Config; diff --git a/src/Config/FileSystemRuntimeConfigLoader.cs b/src/Config/FileSystemRuntimeConfigLoader.cs index 7055728ec2..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; diff --git a/src/Config/Utilities/FileUtilities.cs b/src/Config/Utilities/FileUtilities.cs index eef037d10a..fd190e4b0b 100644 --- a/src/Config/Utilities/FileUtilities.cs +++ b/src/Config/Utilities/FileUtilities.cs @@ -3,6 +3,7 @@ using System.IO.Abstractions; using System.Security.Cryptography; +using Azure.DataApiBuilder.Product; using Microsoft.Extensions.Logging; namespace Azure.DataApiBuilder.Config.Utilities; diff --git a/src/Core/Configurations/RuntimeConfigProvider.cs b/src/Core/Configurations/RuntimeConfigProvider.cs index 8bcd570f47..1932e74f33 100644 --- a/src/Core/Configurations/RuntimeConfigProvider.cs +++ b/src/Core/Configurations/RuntimeConfigProvider.cs @@ -8,7 +8,7 @@ using Azure.DataApiBuilder.Config; using Azure.DataApiBuilder.Config.NamingPolicies; using Azure.DataApiBuilder.Config.ObjectModel; -using Azure.DataApiBuilder.Config.Utilities; +using Azure.DataApiBuilder.Product; using Azure.DataApiBuilder.Service.Exceptions; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Primitives; diff --git a/src/Core/Resolvers/SqlPaginationUtil.cs b/src/Core/Resolvers/SqlPaginationUtil.cs index 3d95a661d6..19c2adfd4b 100644 --- a/src/Core/Resolvers/SqlPaginationUtil.cs +++ b/src/Core/Resolvers/SqlPaginationUtil.cs @@ -6,11 +6,11 @@ using System.Text.Json; using System.Text.Json.Nodes; using System.Text.Json.Serialization; -using Azure.DataApiBuilder.Config.Utilities; using Azure.DataApiBuilder.Core.Configurations; 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; 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/Config/Utilities/BootstrapLogger.cs b/src/Product/BootstrapLogger.cs similarity index 98% rename from src/Config/Utilities/BootstrapLogger.cs rename to src/Product/BootstrapLogger.cs index 6fa5de8bc9..e3b3a39597 100644 --- a/src/Config/Utilities/BootstrapLogger.cs +++ b/src/Product/BootstrapLogger.cs @@ -4,7 +4,7 @@ using System.Globalization; using Microsoft.Extensions.Logging; -namespace Azure.DataApiBuilder.Config.Utilities; +namespace Azure.DataApiBuilder.Product; /// /// Centralized console logger used for diagnostics which can't be routed through diff --git a/src/Service.Tests/UnitTests/BootstrapLoggerTests.cs b/src/Service.Tests/UnitTests/BootstrapLoggerTests.cs index 122bbd2a16..110312584a 100644 --- a/src/Service.Tests/UnitTests/BootstrapLoggerTests.cs +++ b/src/Service.Tests/UnitTests/BootstrapLoggerTests.cs @@ -6,7 +6,7 @@ using System; using System.IO; using System.Text.RegularExpressions; -using Azure.DataApiBuilder.Config.Utilities; +using Azure.DataApiBuilder.Product; using Microsoft.Extensions.Logging; using Microsoft.VisualStudio.TestTools.UnitTesting; diff --git a/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs index 0033a58eee..08a3999603 100644 --- a/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs +++ b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs @@ -12,6 +12,7 @@ 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; @@ -595,19 +596,30 @@ public void Formatter_ControlCharactersInMessage_AreEscaped() public void ProductionSources_DoNotWriteDiagnosticsDirectlyToConsole() { DirectoryInfo sourceRoot = FindSourceRoot(); - string[] productionProjects = - { - "Aspire.AppHost", "Auth", "Azure.DataApiBuilder.Mcp", "Cli", - "Config", "Core", "Service", "Service.GraphQLBuilder" - }; + + // 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 (string project in productionProjects) + foreach (DirectoryInfo project in productionProjects) { - string projectPath = Path.Combine(sourceRoot.FullName, project); - Assert.IsTrue(Directory.Exists(projectPath), $"Expected production project directory '{projectPath}' to exist."); - - foreach (string file in Directory.EnumerateFiles(projectPath, "*.cs", SearchOption.AllDirectories)) + foreach (string file in Directory.EnumerateFiles(project.FullName, "*.cs", SearchOption.AllDirectories)) { string relativePath = Path.GetRelativePath(sourceRoot.FullName, file).Replace('\\', '/'); @@ -644,6 +656,58 @@ public void ProductionSources_DoNotWriteDiagnosticsDirectlyToConsole() + $"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. diff --git a/src/Service/Program.cs b/src/Service/Program.cs index 0b2360e529..42ab46ad46 100644 --- a/src/Service/Program.cs +++ b/src/Service/Program.cs @@ -11,10 +11,10 @@ using System.Threading.Tasks; using Azure.DataApiBuilder.Config; using Azure.DataApiBuilder.Config.ObjectModel; -using Azure.DataApiBuilder.Config.Utilities; 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; diff --git a/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs b/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs index 07e375583d..5ec4535d72 100644 --- a/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs +++ b/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs @@ -5,7 +5,7 @@ using System.Globalization; using System.IO; using System.Text; -using Azure.DataApiBuilder.Config.Utilities; +using Azure.DataApiBuilder.Product; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.DependencyInjection.Extensions; using Microsoft.Extensions.Logging; From 2cecd44d51153abd449f8244a8943fa90384bc44 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 21 Sep 2026 18:25:26 +0000 Subject: [PATCH 12/15] Capture hot-reload console diagnostics before the logger provider is constructed Co-authored-by: aaronburtle <93220300+aaronburtle@users.noreply.github.com> --- .../HotReload/ConfigurationHotReloadTests.cs | 240 ++++++++++++------ 1 file changed, 168 insertions(+), 72 deletions(-) diff --git a/src/Service.Tests/Configuration/HotReload/ConfigurationHotReloadTests.cs b/src/Service.Tests/Configuration/HotReload/ConfigurationHotReloadTests.cs index d85c3ddf01..cc5ee03985 100644 --- a/src/Service.Tests/Configuration/HotReload/ConfigurationHotReloadTests.cs +++ b/src/Service.Tests/Configuration/HotReload/ConfigurationHotReloadTests.cs @@ -6,6 +6,7 @@ using System.Net; using System.Net.Http; using System.Net.Http.Json; +using System.Text; using System.Text.Json; using System.Threading.Tasks; using Azure.DataApiBuilder.Config.ObjectModel; @@ -25,7 +26,8 @@ public class ConfigurationHotReloadTests private static TestServer _testServer; private static HttpClient _testClient; private static RuntimeConfigProvider _configProvider; - private static StringWriter _writer; + private static CapturingTextWriter _writer; + private static TextWriter _originalConsoleOut; private static readonly object _writerLock = new(); private const string CONFIG_FILE_NAME = "hot-reload.dab-config.json"; private const string GQL_QUERY_NAME = "books"; @@ -219,6 +221,11 @@ public static async Task ClassInitializeAsync(TestContext context) // Arrange GenerateConfigFile(connectionString: $"{ConfigurationTests.GetConnectionStringFromEnvironmentConfig(TestCategory.MSSQL).Replace("\\", "\\\\")}"); + // Capture the console before the test server is created. The engine resolves its + // hot-reload diagnostics through a console logger provider which binds to Console.Out + // at construction time, so capturing afterwards would miss every entry it emits. + StartCapturingConsole(); + int maxRetries = 3; int retryDelayMs = 2000; Exception lastException = null; @@ -281,7 +288,9 @@ public static async Task ClassInitializeAsync(TestContext context) } } - // If we got here, all retries failed + // If we got here, all retries failed. Restore the console so a failed class + // initialization cannot leave the redirect in place for the rest of the run. + StopCapturingConsole(); throw new Exception($"Failed to initialize test server after {maxRetries} attempts. Last error: {lastException?.Message}", lastException); } @@ -303,16 +312,135 @@ public static void ClassCleanup() { Console.WriteLine($"Error during test cleanup: {ex.Message}"); } + finally + { + StopCapturingConsole(); + } } /// - /// Thread-safe helper to check if the writer contains a specific message + /// Redirects the console to the capture writer. Must be called before the test server + /// (and therefore the console logger provider) is constructed: the provider resolves + /// once at construction and holds that writer for its lifetime, + /// so a later redirect is never observed by it. For the same reason the writer instance is + /// created once and only its buffer is cleared between tests - replacing the instance would + /// orphan the provider on the previous writer. /// - private static bool WriterContains(string message) + private static void StartCapturingConsole() { lock (_writerLock) { - return _writer.ToString().Contains(message); + _originalConsoleOut = Console.Out; + _writer = new CapturingTextWriter(_originalConsoleOut); + Console.SetOut(_writer); + } + } + + /// + /// Restores the console stream captured by . + /// + private static void StopCapturingConsole() + { + lock (_writerLock) + { + if (_originalConsoleOut is not null) + { + Console.SetOut(_originalConsoleOut); + _originalConsoleOut = null; + } + } + } + + /// + /// Thread-safe snapshot of the diagnostics captured so far. + /// + private static string GetCapturedLogs() + { + return _writer.GetCapturedText(); + } + + /// + /// Thread-safe reset of the captured diagnostics, used to separate the output of two + /// consecutive hot reloads within a single test. Clears the existing writer's buffer + /// rather than replacing the writer, so the console logger provider keeps writing + /// into the writer this class observes. + /// + private static void ClearCapturedLogs() + { + _writer.ClearCapturedText(); + } + + /// + /// Thread-safe helper to check if the captured diagnostics contain a specific message. + /// + private static bool CapturedLogsContain(string message) + { + return GetCapturedLogs().Contains(message); + } + + /// + /// Buffers everything written to the console while still forwarding it to the original + /// stream, so redirecting the console for assertions does not hide test output from CI. + /// + private sealed class CapturingTextWriter : TextWriter + { + private readonly TextWriter _inner; + private readonly StringBuilder _buffer = new(); + private readonly object _bufferLock = new(); + + public CapturingTextWriter(TextWriter inner) + { + _inner = inner; + } + + public override Encoding Encoding => _inner.Encoding; + + public override void Write(char value) + { + lock (_bufferLock) + { + _buffer.Append(value); + } + + _inner.Write(value); + } + + public override void Write(string value) + { + lock (_bufferLock) + { + _buffer.Append(value); + } + + _inner.Write(value); + } + + public override void WriteLine(string value) + { + lock (_bufferLock) + { + _buffer.AppendLine(value); + } + + _inner.WriteLine(value); + } + + public override void Flush() => _inner.Flush(); + + public string GetCapturedText() + { + lock (_bufferLock) + { + return _buffer.ToString(); + } + } + + public void ClearCapturedText() + { + lock (_bufferLock) + { + _buffer.Clear(); + } } } @@ -325,8 +453,7 @@ private static bool WriterContains(string message) public async Task HotReloadConfigRuntimePathsEndToEndTest() { // Arrange - _writer = new StringWriter(); - Console.SetOut(_writer); + ClearCapturedLogs(); string restBookContents = $"{{\"value\":{_bookDBOContents}}}"; string restPath = "restApi"; @@ -347,7 +474,7 @@ public async Task HotReloadConfigRuntimePathsEndToEndTest() // Wait for hot-reload to complete successfully await WaitForConditionAsync( - () => WriterContains(HOT_RELOAD_SUCCESS_MESSAGE), + () => CapturedLogsContain(HOT_RELOAD_SUCCESS_MESSAGE), TimeSpan.FromSeconds(HOT_RELOAD_TIMEOUT_SECONDS), TimeSpan.FromMilliseconds(500)); @@ -383,8 +510,7 @@ await WaitForConditionAsync( public async Task HotReloadConfigRuntimeRestEnabledEndToEndTest() { // Arrange - _writer = new StringWriter(); - Console.SetOut(_writer); + ClearCapturedLogs(); string restEnabled = "false"; @@ -394,7 +520,7 @@ public async Task HotReloadConfigRuntimeRestEnabledEndToEndTest() // Wait for hot-reload to complete successfully await WaitForConditionAsync( - () => WriterContains(HOT_RELOAD_SUCCESS_MESSAGE), + () => CapturedLogsContain(HOT_RELOAD_SUCCESS_MESSAGE), TimeSpan.FromSeconds(HOT_RELOAD_TIMEOUT_SECONDS), TimeSpan.FromMilliseconds(500)); @@ -415,8 +541,7 @@ await WaitForConditionAsync( public async Task HotReloadConfigRuntimeGQLEnabledEndToEndTest() { // Arrange - _writer = new StringWriter(); - Console.SetOut(_writer); + ClearCapturedLogs(); string gQLEnabled = "false"; string query = GQL_QUERY; @@ -434,7 +559,7 @@ public async Task HotReloadConfigRuntimeGQLEnabledEndToEndTest() // Wait for hot-reload to complete successfully await WaitForConditionAsync( - () => WriterContains(HOT_RELOAD_SUCCESS_MESSAGE), + () => CapturedLogsContain(HOT_RELOAD_SUCCESS_MESSAGE), TimeSpan.FromSeconds(HOT_RELOAD_TIMEOUT_SECONDS), TimeSpan.FromMilliseconds(500)); @@ -456,8 +581,7 @@ await WaitForConditionAsync( public async Task HotReloadEntityGQLEnabledFlag() { // Arrange - _writer = new StringWriter(); - Console.SetOut(_writer); + ClearCapturedLogs(); string gQLEntityEnabled = "false"; string query = @"{ @@ -480,7 +604,7 @@ public async Task HotReloadEntityGQLEnabledFlag() // Wait for hot-reload to complete successfully await WaitForConditionAsync( - () => WriterContains(HOT_RELOAD_SUCCESS_MESSAGE), + () => CapturedLogsContain(HOT_RELOAD_SUCCESS_MESSAGE), TimeSpan.FromSeconds(HOT_RELOAD_TIMEOUT_SECONDS), TimeSpan.FromMilliseconds(500)); @@ -503,8 +627,7 @@ await WaitForConditionAsync( public async Task HotReloadConfigAddEntity() { // Arrange - _writer = new StringWriter(); - Console.SetOut(_writer); + ClearCapturedLogs(); string newEntityName = "Author"; string newEntitySource = "authors"; @@ -520,7 +643,7 @@ public async Task HotReloadConfigAddEntity() // Wait for hot-reload to complete successfully await WaitForConditionAsync( - () => WriterContains(HOT_RELOAD_SUCCESS_MESSAGE), + () => CapturedLogsContain(HOT_RELOAD_SUCCESS_MESSAGE), TimeSpan.FromSeconds(HOT_RELOAD_TIMEOUT_SECONDS), TimeSpan.FromMilliseconds(500)); @@ -589,8 +712,7 @@ await WaitForConditionAsync( public async Task HotReloadConfigUpdateMappings() { // Arrange - _writer = new StringWriter(); - Console.SetOut(_writer); + ClearCapturedLogs(); string newMappingFieldName = "bookTitle"; // Update the configuration with new mappings @@ -601,7 +723,7 @@ public async Task HotReloadConfigUpdateMappings() // Wait for hot-reload to complete successfully await WaitForConditionAsync( - () => WriterContains(HOT_RELOAD_SUCCESS_MESSAGE), + () => CapturedLogsContain(HOT_RELOAD_SUCCESS_MESSAGE), TimeSpan.FromSeconds(HOT_RELOAD_TIMEOUT_SECONDS), TimeSpan.FromMilliseconds(500)); @@ -669,8 +791,7 @@ await WaitForConditionAsync( public async Task HotReloadConfigDataSource() { // Arrange - _writer = new StringWriter(); - Console.SetOut(_writer); + ClearCapturedLogs(); RuntimeConfig previousRuntimeConfig = _configProvider.GetConfig(); MsSqlOptions previousSessionContext = previousRuntimeConfig.DataSource.GetTypedOptions(); @@ -685,7 +806,7 @@ public async Task HotReloadConfigDataSource() // Wait for hot-reload to complete successfully await WaitForConditionAsync( - () => WriterContains(HOT_RELOAD_SUCCESS_MESSAGE), + () => CapturedLogsContain(HOT_RELOAD_SUCCESS_MESSAGE), TimeSpan.FromSeconds(HOT_RELOAD_TIMEOUT_SECONDS), TimeSpan.FromMilliseconds(500)); @@ -712,8 +833,7 @@ await WaitForConditionAsync( public async Task HotReloadLogLevel() { // Arrange - _writer = new StringWriter(); - Console.SetOut(_writer); + ClearCapturedLogs(); LogLevel expectedLogLevel = LogLevel.Trace; string expectedFilter = "trace"; @@ -727,7 +847,7 @@ public async Task HotReloadLogLevel() // Wait for hot-reload to complete successfully await WaitForConditionAsync( - () => WriterContains(HOT_RELOAD_SUCCESS_MESSAGE), + () => CapturedLogsContain(HOT_RELOAD_SUCCESS_MESSAGE), TimeSpan.FromSeconds(HOT_RELOAD_TIMEOUT_SECONDS), TimeSpan.FromMilliseconds(500)); @@ -749,40 +869,31 @@ await WaitForConditionAsync( public async Task HotReloadConfigConnectionString() { // Arrange - _writer = new StringWriter(); - Console.SetOut(_writer); + ClearCapturedLogs(); // Act // Hot Reload should fail here GenerateConfigFile( connectionString: $"WrongConnectionString"); await WaitForConditionAsync( - () => WriterContains(HOT_RELOAD_FAILURE_MESSAGE), + () => CapturedLogsContain(HOT_RELOAD_FAILURE_MESSAGE), TimeSpan.FromSeconds(HOT_RELOAD_TIMEOUT_SECONDS), TimeSpan.FromMilliseconds(500)); // Log that shows that hot-reload was not able to validate properly - string failedConfigLog; - lock (_writerLock) - { - failedConfigLog = _writer.ToString(); - _writer.GetStringBuilder().Clear(); - } + string failedConfigLog = GetCapturedLogs(); + ClearCapturedLogs(); // Hot Reload should succeed here GenerateConfigFile( connectionString: $"{ConfigurationTests.GetConnectionStringFromEnvironmentConfig(TestCategory.MSSQL).Replace("\\", "\\\\")}"); await WaitForConditionAsync( - () => WriterContains(HOT_RELOAD_SUCCESS_MESSAGE), + () => CapturedLogsContain(HOT_RELOAD_SUCCESS_MESSAGE), TimeSpan.FromSeconds(HOT_RELOAD_TIMEOUT_SECONDS), TimeSpan.FromMilliseconds(500)); // Log that shows that hot-reload validated properly - string succeedConfigLog; - lock (_writerLock) - { - succeedConfigLog = _writer.ToString(); - } + string succeedConfigLog = GetCapturedLogs(); // After hot-reload, the engine may still be re-initializing metadata providers. // Poll the REST endpoint to allow time for the engine to become fully ready. @@ -803,8 +914,7 @@ await WaitForConditionAsync( public async Task HotReloadAutoentities() { // Arrange - _writer = new StringWriter(); - Console.SetOut(_writer); + ClearCapturedLogs(); // Act HttpResponseMessage restResult = await _testClient.GetAsync($"rest/autoentity_books"); @@ -813,7 +923,7 @@ public async Task HotReloadAutoentities() connectionString: $"{ConfigurationTests.GetConnectionStringFromEnvironmentConfig(TestCategory.MSSQL).Replace("\\", "\\\\")}", autoentityName: "HotReload_{object}"); await WaitForConditionAsync( - () => WriterContains(HOT_RELOAD_SUCCESS_MESSAGE), + () => CapturedLogsContain(HOT_RELOAD_SUCCESS_MESSAGE), TimeSpan.FromSeconds(HOT_RELOAD_TIMEOUT_SECONDS), TimeSpan.FromMilliseconds(500)); @@ -846,8 +956,7 @@ await WaitForConditionAsync( public async Task HotReloadConfigDatabaseType() { // Arrange - _writer = new StringWriter(); - Console.SetOut(_writer); + ClearCapturedLogs(); // Act // Hot Reload should fail here @@ -855,33 +964,25 @@ public async Task HotReloadConfigDatabaseType() databaseType: DatabaseType.PostgreSQL, connectionString: $"{ConfigurationTests.GetConnectionStringFromEnvironmentConfig(TestCategory.POSTGRESQL).Replace("\\", "\\\\")}"); await WaitForConditionAsync( - () => WriterContains(HOT_RELOAD_FAILURE_MESSAGE), + () => CapturedLogsContain(HOT_RELOAD_FAILURE_MESSAGE), TimeSpan.FromSeconds(HOT_RELOAD_TIMEOUT_SECONDS), TimeSpan.FromMilliseconds(500)); // Log that shows that hot-reload was not able to validate properly - string failedConfigLog; - lock (_writerLock) - { - failedConfigLog = _writer.ToString(); - _writer.GetStringBuilder().Clear(); - } + string failedConfigLog = GetCapturedLogs(); + ClearCapturedLogs(); // Hot Reload should succeed here GenerateConfigFile( databaseType: DatabaseType.MSSQL, connectionString: $"{ConfigurationTests.GetConnectionStringFromEnvironmentConfig(TestCategory.MSSQL).Replace("\\", "\\\\")}"); await WaitForConditionAsync( - () => WriterContains(HOT_RELOAD_SUCCESS_MESSAGE), + () => CapturedLogsContain(HOT_RELOAD_SUCCESS_MESSAGE), TimeSpan.FromSeconds(HOT_RELOAD_TIMEOUT_SECONDS), TimeSpan.FromMilliseconds(500)); // Log that shows that hot-reload validated properly - string succeedConfigLog; - lock (_writerLock) - { - succeedConfigLog = _writer.ToString(); - } + string succeedConfigLog = GetCapturedLogs(); // After hot-reload, the engine may still be re-initializing metadata providers. // Poll the REST endpoint to allow time for the engine to become fully ready. @@ -906,8 +1007,7 @@ await WaitForConditionAsync( public async Task HotReloadValidationFail() { // Arrange - _writer = new StringWriter(); - Console.SetOut(_writer); + ClearCapturedLogs(); RuntimeConfig lkgRuntimeConfig = _configProvider.GetConfig(); Assert.IsNotNull(lkgRuntimeConfig); @@ -927,7 +1027,7 @@ public async Task HotReloadValidationFail() // Wait for hot-reload to fail await WaitForConditionAsync( - () => WriterContains(HOT_RELOAD_FAILURE_MESSAGE), + () => CapturedLogsContain(HOT_RELOAD_FAILURE_MESSAGE), TimeSpan.FromSeconds(HOT_RELOAD_TIMEOUT_SECONDS), TimeSpan.FromMilliseconds(500)); @@ -956,8 +1056,7 @@ await WaitForConditionAsync( public async Task HotReloadParsingFail() { // Arrange - _writer = new StringWriter(); - Console.SetOut(_writer); + ClearCapturedLogs(); RuntimeConfig lkgRuntimeConfig = _configProvider.GetConfig(); Assert.IsNotNull(lkgRuntimeConfig); @@ -974,7 +1073,7 @@ public async Task HotReloadParsingFail() // Wait for hot-reload to fail (parsing error should trigger failure message) await WaitForConditionAsync( - () => WriterContains(HOT_RELOAD_FAILURE_MESSAGE), + () => CapturedLogsContain(HOT_RELOAD_FAILURE_MESSAGE), TimeSpan.FromSeconds(HOT_RELOAD_TIMEOUT_SECONDS), TimeSpan.FromMilliseconds(500)); @@ -1014,10 +1113,7 @@ private static async Task WaitForConditionAsync(Func condition, TimeSpan t } Console.WriteLine($"Hot-reload timeout after {stopwatch.Elapsed.TotalSeconds:F2} seconds ({attemptCount} attempts)"); - lock (_writerLock) - { - Console.WriteLine($"Console output captured:\n{_writer.ToString()}"); - } + Console.WriteLine($"Hot-reload diagnostics captured:\n{GetCapturedLogs()}"); throw new TimeoutException("The condition was not met within the timeout period."); } From 81e99d519741407564d818c39f51622836456a86 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 21 Sep 2026 18:35:26 +0000 Subject: [PATCH 13/15] fix: preserve explicitly configured console formatter (json/systemd) Co-authored-by: aaronburtle <93220300+aaronburtle@users.noreply.github.com> --- .../UnitTests/ConsoleLogTimestampTests.cs | 185 +++++++++++++++++- src/Service/Program.cs | 8 +- .../Telemetry/UtcTimestampConsoleFormatter.cs | 48 ++++- 3 files changed, 235 insertions(+), 6 deletions(-) diff --git a/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs index 08a3999603..85e018287c 100644 --- a/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs +++ b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs @@ -9,16 +9,19 @@ using System.IO; using System.IO.Abstractions; using System.Linq; +using System.Text.Json; 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.Configuration; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Logging.Console; +using Microsoft.Extensions.Options; using Microsoft.VisualStudio.TestTools.UnitTesting; namespace Azure.DataApiBuilder.Service.Tests.UnitTests @@ -81,7 +84,16 @@ private static void AssertStartsWithUtcTimestamp(string output, DateTime before, 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; + AssertIsUtcTimestamp(match.Groups["ts"].Value, before, after); + } + + /// + /// Asserts that is an ISO 8601 UTC value with exactly + /// three fractional-second digits, falling within the window captured around the + /// logging call. + /// + private static void AssertIsUtcTimestamp(string timestamp, DateTime before, DateTime after) + { 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, @@ -239,6 +251,177 @@ public void ConfigureHostLogging_NormalMode_RegistersSingleConsoleProvider() "Exactly one ConsoleLoggerProvider must be registered; a second one would duplicate every log entry."); } + /// + /// Builds a logging pipeline shaped like the web host's: the "Logging" configuration + /// section is bound (as Host.CreateDefaultBuilder does), the console provider is + /// registered once, and then DAB's logging configuration is applied on top. + /// + private static ILoggerFactory CreateHostLoggerFactory(Dictionary settings) + { + IConfigurationRoot configuration = new ConfigurationBuilder() + .AddInMemoryCollection(settings) + .Build(); + + return LoggerFactory.Create(builder => + { + builder.AddConfiguration(configuration.GetSection("Logging")); + builder.AddConsole(); + Program.ConfigureHostLogging(builder, runMcpStdio: false); + }); + } + + /// + /// Resolves the console logger options produced by the web host's logging pipeline + /// for the supplied configuration. + /// + private static ConsoleLoggerOptions GetConsoleLoggerOptions(Dictionary settings) + { + IConfigurationRoot configuration = new ConfigurationBuilder() + .AddInMemoryCollection(settings) + .Build(); + + ServiceCollection services = new(); + services.AddLogging(builder => + { + builder.AddConfiguration(configuration.GetSection("Logging")); + builder.AddConsole(); + Program.ConfigureHostLogging(builder, runMcpStdio: false); + }); + + using ServiceProvider provider = services.BuildServiceProvider(); + return provider.GetRequiredService>().CurrentValue; + } + + /// + /// When no console format is configured - or the default "simple" format is selected - + /// DAB's UTC timestamp formatter is used. + /// + [DataTestMethod] + [DataRow(null, DisplayName = "FormatterName unset")] + [DataRow("simple", DisplayName = "FormatterName=simple")] + [DataRow("Simple", DisplayName = "FormatterName=Simple (case-insensitive)")] + public void ConfigureHostLogging_DefaultFormatter_SelectsUtcTimestampFormatter(string? formatterName) + { + Dictionary settings = new(); + if (formatterName is not null) + { + settings["Logging:Console:FormatterName"] = formatterName; + } + + Assert.AreEqual( + UtcTimestampConsoleFormatter.FORMATTER_NAME, + GetConsoleLoggerOptions(settings).FormatterName, + "The DAB formatter must be selected when no explicit console format is configured."); + } + + /// + /// A deployment which explicitly selects the "json" console format keeps machine + /// readable JSON records - structured log collectors depend on that contract - and + /// those records carry the UTC timestamp required by the logging contract. + /// + [TestMethod] + public void ConfigureHostLogging_ExplicitJsonFormatter_EmitsTimestampedJsonRecord() + { + Dictionary settings = new() { ["Logging:Console:FormatterName"] = "json" }; + + Assert.AreEqual("json", GetConsoleLoggerOptions(settings).FormatterName, + "An explicitly configured console format must not be overridden."); + + (string stdout, _, DateTime before, DateTime after) = CaptureConsole(() => + { + using ILoggerFactory factory = CreateHostLoggerFactory(settings); + factory.CreateLogger("TestCategory").LogInformation(LOG_MESSAGE); + }); + + string record = stdout.Split('\n').First(line => !string.IsNullOrWhiteSpace(line)); + + JsonDocument document; + try + { + document = JsonDocument.Parse(record); + } + catch (JsonException exception) + { + throw new AssertFailedException( + $"The 'json' console format must emit a JSON record but got: '{record}'", exception); + } + + using (document) + { + JsonElement root = document.RootElement; + Assert.AreEqual("Information", root.GetProperty("LogLevel").GetString()); + Assert.AreEqual("TestCategory", root.GetProperty("Category").GetString()); + Assert.AreEqual(LOG_MESSAGE, root.GetProperty("Message").GetString()); + + Assert.IsTrue(root.TryGetProperty("Timestamp", out JsonElement timestamp), + $"The JSON record must carry a Timestamp property but got: '{record}'"); + AssertIsUtcTimestamp(timestamp.GetString()!, before, after); + } + } + + /// + /// A deployment which explicitly selects the "systemd" console format keeps the + /// syslog priority prefix - journald severity extraction depends on it - and the + /// records carry the UTC timestamp required by the logging contract. + /// + [TestMethod] + public void ConfigureHostLogging_ExplicitSystemdFormatter_EmitsTimestampedSystemdRecord() + { + Dictionary settings = new() { ["Logging:Console:FormatterName"] = "systemd" }; + + Assert.AreEqual("systemd", GetConsoleLoggerOptions(settings).FormatterName, + "An explicitly configured console format must not be overridden."); + + (string stdout, _, DateTime before, DateTime after) = CaptureConsole(() => + { + using ILoggerFactory factory = CreateHostLoggerFactory(settings); + factory.CreateLogger("TestCategory").LogInformation(LOG_MESSAGE); + }); + + string record = stdout.Split('\n').First(line => !string.IsNullOrWhiteSpace(line)); + + // "<6>" is the syslog priority for Information. + Match match = Regex.Match(record, @"^<(?\d)>(?\S+?Z)"); + Assert.IsTrue(match.Success, + $"The 'systemd' console format must emit 'timestamp...' but got: '{record}'"); + Assert.AreEqual("6", match.Groups["priority"].Value, + $"Information must map to syslog priority 6 but got: '{record}'"); + AssertIsUtcTimestamp(match.Groups["ts"].Value, before, after); + StringAssert.Contains(record, LOG_MESSAGE); + } + + /// + /// A timestamp format configured by the deployment takes precedence over the + /// default DAB format. + /// + [TestMethod] + public void ConfigureHostLogging_ExplicitTimestampFormat_IsPreserved() + { + Dictionary settings = new() + { + ["Logging:Console:FormatterName"] = "json", + ["Logging:Console:FormatterOptions:TimestampFormat"] = "HH:mm:ss", + }; + + IConfigurationRoot configuration = new ConfigurationBuilder() + .AddInMemoryCollection(settings) + .Build(); + + ServiceCollection services = new(); + services.AddLogging(builder => + { + builder.AddConfiguration(configuration.GetSection("Logging")); + builder.AddConsole(); + Program.ConfigureHostLogging(builder, runMcpStdio: false); + }); + + using ServiceProvider provider = services.BuildServiceProvider(); + Assert.AreEqual( + "HH:mm:ss", + provider.GetRequiredService>().CurrentValue.TimestampFormat, + "An explicitly configured timestamp format must not be overridden."); + } + /// /// In stdio mode the console providers are cleared so nothing can corrupt the /// JSON-RPC channel on stdout. diff --git a/src/Service/Program.cs b/src/Service/Program.cs index 42ab46ad46..c7812d1615 100644 --- a/src/Service/Program.cs +++ b/src/Service/Program.cs @@ -228,9 +228,11 @@ public static void ConfigureHostLogging(ILoggingBuilder logging, bool runMcpStdi // 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. + // when no console format was configured (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. An explicitly configured "json"/"systemd" format is + // preserved and timestamped through that format's own options. logging.AddUtcTimestampConsoleFormatter(); } diff --git a/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs b/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs index 5ec4535d72..ceaf24d3ba 100644 --- a/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs +++ b/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs @@ -331,15 +331,59 @@ public static class UtcTimestampConsoleFormatterExtensions /// provider added by ) /// without emitting duplicate entries. /// + /// + /// The formatter is only selected when no console format was explicitly requested, or when the + /// default "simple" format was requested. A deployment which opts into "json" or "systemd" (via + /// Logging:Console:FormatterName) keeps that output contract, because structured log + /// collectors and systemd severity extraction depend on it. Those formats render their own + /// timestamp, which the built-in formatters omit entirely unless + /// is set, so the shared UTC format is + /// applied to them as well. + /// public static ILoggingBuilder AddUtcTimestampConsoleFormatter(this ILoggingBuilder builder) { builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton()); - builder.Services.Configure(options => + + // PostConfigure runs after the "Logging:Console" configuration binding, so an explicitly + // configured FormatterName is visible here and is left untouched. + builder.Services.PostConfigure(options => { - options.FormatterName = UtcTimestampConsoleFormatter.FORMATTER_NAME; + if (string.IsNullOrEmpty(options.FormatterName) || + string.Equals(options.FormatterName, ConsoleFormatterNames.Simple, StringComparison.OrdinalIgnoreCase)) + { + options.FormatterName = UtcTimestampConsoleFormatter.FORMATTER_NAME; + } }); + // "json" uses JsonConsoleFormatterOptions, "systemd" uses ConsoleFormatterOptions. Neither + // shares an options type with the "simple" formatter (SimpleConsoleFormatterOptions), so + // configuring them here cannot affect the DAB formatter above. + builder.Services.PostConfigure(ApplyUtcTimestampFormat); + builder.Services.PostConfigure(ApplyUtcTimestampFormat); + return builder; } + + /// + /// Applies the shared UTC timestamp format to a built-in console formatter, unless the + /// deployment already configured a timestamp format of its own. + /// + /// + /// The built-in "json" and "systemd" formatters render this format through + /// DateTimeOffset.ToString(TimestampFormat), which resolves against + /// . On a host whose culture uses a non-Gregorian + /// calendar they therefore emit that calendar's year. Making those formats culture invariant + /// would require reimplementing them, so it is deliberately not done here: they are opt-in + /// formats whose output contract belongs to the log collector consuming them. The default + /// console format, which owns, is invariant. + /// + private static void ApplyUtcTimestampFormat(ConsoleFormatterOptions options) + { + if (string.IsNullOrEmpty(options.TimestampFormat)) + { + options.TimestampFormat = BootstrapLogger.UTC_TIMESTAMP_FORMAT; + options.UseUtcTimestamp = true; + } + } } } From 2105d2a1e36608e62815381eef2ba6f315c8079d Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 23 Sep 2026 07:59:00 +0000 Subject: [PATCH 14/15] fix: reattach hot-reload console capture per test under MSTest lifecycle Co-authored-by: aaronburtle <93220300+aaronburtle@users.noreply.github.com> --- .../HotReload/ConfigurationHotReloadTests.cs | 115 +++++++++++++++++- 1 file changed, 109 insertions(+), 6 deletions(-) diff --git a/src/Service.Tests/Configuration/HotReload/ConfigurationHotReloadTests.cs b/src/Service.Tests/Configuration/HotReload/ConfigurationHotReloadTests.cs index cc5ee03985..82059e97ff 100644 --- a/src/Service.Tests/Configuration/HotReload/ConfigurationHotReloadTests.cs +++ b/src/Service.Tests/Configuration/HotReload/ConfigurationHotReloadTests.cs @@ -28,6 +28,8 @@ public class ConfigurationHotReloadTests private static RuntimeConfigProvider _configProvider; private static CapturingTextWriter _writer; private static TextWriter _originalConsoleOut; + private static TextWriter _installedConsoleOut; + private static TextWriter _runnerConsoleOut; private static readonly object _writerLock = new(); private const string CONFIG_FILE_NAME = "hot-reload.dab-config.json"; private const string GQL_QUERY_NAME = "books"; @@ -332,10 +334,23 @@ private static void StartCapturingConsole() { _originalConsoleOut = Console.Out; _writer = new CapturingTextWriter(_originalConsoleOut); - Console.SetOut(_writer); + InstallCaptureWriter(); } } + /// + /// Points at the capture writer and remembers the wrapper the + /// console hands back, so a later replacement by the test runner can be detected. + /// wraps the writer in a synchronized decorator, which is why + /// the installed value has to be recorded rather than compared against + /// directly. + /// + private static void InstallCaptureWriter() + { + Console.SetOut(_writer); + _installedConsoleOut = Console.Out; + } + /// /// Restores the console stream captured by . /// @@ -347,10 +362,73 @@ private static void StopCapturingConsole() { Console.SetOut(_originalConsoleOut); _originalConsoleOut = null; + _installedConsoleOut = null; } } } + /// + /// Reattaches the capture writer for the duration of a test. + /// + /// + /// MSTest installs its own around every test method so that console + /// output can be attributed to that test, which undoes the class-level redirect. The two + /// diagnostics these tests assert on reach the console by different routes and are affected + /// differently: entries written through an injected ILogger go to the writer the console + /// logger provider captured at construction (the capture writer), while BootstrapLogger + /// resolves on every write and therefore follows the runner's + /// replacement. Without this reattach only the former is observed, so the tests that wait for a + /// hot-reload success message time out. + /// The provider-bound writer instance is reused rather than replaced - a new instance would + /// leave the provider writing into the previous one. + /// + [TestInitialize] + public void AttachCapturingConsole() + { + lock (_writerLock) + { + if (_writer is null) + { + return; + } + + TextWriter runnerWriter = Console.Out; + if (ReferenceEquals(runnerWriter, _installedConsoleOut)) + { + // The capture writer is still installed; nothing to reattach. + return; + } + + // Forward to the runner's per-test writer so console output stays attributed to + // this test instead of being diverted to the stream captured at class initialization. + _runnerConsoleOut = runnerWriter; + _writer.SetForwardTarget(runnerWriter); + InstallCaptureWriter(); + } + } + + /// + /// Restores the per-test writer installed by the test runner, leaving the runner free to + /// dispose it, and points the capture writer back at the stream captured at class + /// initialization so late writes from the logger's background thread stay valid. + /// + [TestCleanup] + public void DetachCapturingConsole() + { + lock (_writerLock) + { + if (_runnerConsoleOut is null) + { + return; + } + + _writer?.SetForwardTarget(_originalConsoleOut ?? TextWriter.Null); + Console.SetOut(_runnerConsoleOut); + _runnerConsoleOut = null; + _installedConsoleOut = null; + } + } + /// /// Thread-safe snapshot of the diagnostics captured so far. /// @@ -384,9 +462,9 @@ private static bool CapturedLogsContain(string message) /// private sealed class CapturingTextWriter : TextWriter { - private readonly TextWriter _inner; private readonly StringBuilder _buffer = new(); private readonly object _bufferLock = new(); + private volatile TextWriter _inner; public CapturingTextWriter(TextWriter inner) { @@ -395,6 +473,31 @@ public CapturingTextWriter(TextWriter inner) public override Encoding Encoding => _inner.Encoding; + /// + /// Redirects the tee target without replacing this instance, so the console logger + /// provider - which holds this writer for its lifetime - keeps feeding the same buffer. + /// + public void SetForwardTarget(TextWriter inner) + { + _inner = inner; + } + + /// + /// Forwards to the current tee target. The console logger writes from a background + /// thread, so a write can race with the test runner disposing its per-test writer; + /// that must not fail the test because the buffer has already been updated. + /// + private void Forward(Action write) + { + try + { + write(_inner); + } + catch (ObjectDisposedException) + { + } + } + public override void Write(char value) { lock (_bufferLock) @@ -402,7 +505,7 @@ public override void Write(char value) _buffer.Append(value); } - _inner.Write(value); + Forward(writer => writer.Write(value)); } public override void Write(string value) @@ -412,7 +515,7 @@ public override void Write(string value) _buffer.Append(value); } - _inner.Write(value); + Forward(writer => writer.Write(value)); } public override void WriteLine(string value) @@ -422,10 +525,10 @@ public override void WriteLine(string value) _buffer.AppendLine(value); } - _inner.WriteLine(value); + Forward(writer => writer.WriteLine(value)); } - public override void Flush() => _inner.Flush(); + public override void Flush() => Forward(writer => writer.Flush()); public string GetCapturedText() { From d3364553c0d71a87a30a85a7d317f7676d4b431e Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 23 Sep 2026 08:14:59 +0000 Subject: [PATCH 15/15] fix: invariant UTC timestamps for json/systemd console formats and legacy ConsoleLoggerOptions support Co-authored-by: aaronburtle <93220300+aaronburtle@users.noreply.github.com> --- .../UnitTests/ConsoleLogTimestampTests.cs | 167 ++++++++++-- .../Telemetry/ConsoleFormatterShared.cs | 112 ++++++++ .../Telemetry/UtcTimestampConsoleFormatter.cs | 218 ++++++++------- .../UtcTimestampJsonConsoleFormatter.cs | 256 ++++++++++++++++++ .../UtcTimestampSystemdConsoleFormatter.cs | 180 ++++++++++++ 5 files changed, 812 insertions(+), 121 deletions(-) create mode 100644 src/Service/Telemetry/ConsoleFormatterShared.cs create mode 100644 src/Service/Telemetry/UtcTimestampJsonConsoleFormatter.cs create mode 100644 src/Service/Telemetry/UtcTimestampSystemdConsoleFormatter.cs diff --git a/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs index 85e018287c..517f7b78a8 100644 --- a/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs +++ b/src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs @@ -38,6 +38,8 @@ public class ConsoleLogTimestampTests { private const string LOG_MESSAGE = "timestamp probe message"; + private const string SCOPE_MESSAGE = "timestamp probe scope"; + /// /// Matches the timestamp prefix: exactly three fractional-second digits followed /// by a literal 'Z'. The trailing 'Z' immediately after the third digit is what @@ -319,19 +321,31 @@ public void ConfigureHostLogging_DefaultFormatter_SelectsUtcTimestampFormatter(s /// readable JSON records - structured log collectors depend on that contract - and /// those records carry the UTC timestamp required by the logging contract. /// - [TestMethod] - public void ConfigureHostLogging_ExplicitJsonFormatter_EmitsTimestampedJsonRecord() + [DataTestMethod] + [DataRow("en-US")] + [DataRow("th-TH")] + [DataRow("ar-SA")] + [DataRow("fi-FI")] + public void ConfigureHostLogging_ExplicitJsonFormatter_EmitsTimestampedJsonRecord(string cultureName) { + if (cultureName != "en-US") + { + AssertCultureAffectsTimestampRendering(cultureName); + } + Dictionary settings = new() { ["Logging:Console:FormatterName"] = "json" }; - Assert.AreEqual("json", GetConsoleLoggerOptions(settings).FormatterName, - "An explicitly configured console format must not be overridden."); + Assert.AreEqual( + UtcTimestampJsonConsoleFormatter.FORMATTER_NAME, + GetConsoleLoggerOptions(settings).FormatterName, + "The 'json' console format must map to the DAB formatter emitting the same record structure."); (string stdout, _, DateTime before, DateTime after) = CaptureConsole(() => - { - using ILoggerFactory factory = CreateHostLoggerFactory(settings); - factory.CreateLogger("TestCategory").LogInformation(LOG_MESSAGE); - }); + RunUnderCulture(cultureName, () => + { + using ILoggerFactory factory = CreateHostLoggerFactory(settings); + factory.CreateLogger("TestCategory").LogInformation(LOG_MESSAGE); + })); string record = stdout.Split('\n').First(line => !string.IsNullOrWhiteSpace(line)); @@ -364,19 +378,31 @@ public void ConfigureHostLogging_ExplicitJsonFormatter_EmitsTimestampedJsonRecor /// syslog priority prefix - journald severity extraction depends on it - and the /// records carry the UTC timestamp required by the logging contract. /// - [TestMethod] - public void ConfigureHostLogging_ExplicitSystemdFormatter_EmitsTimestampedSystemdRecord() + [DataTestMethod] + [DataRow("en-US")] + [DataRow("th-TH")] + [DataRow("ar-SA")] + [DataRow("fi-FI")] + public void ConfigureHostLogging_ExplicitSystemdFormatter_EmitsTimestampedSystemdRecord(string cultureName) { + if (cultureName != "en-US") + { + AssertCultureAffectsTimestampRendering(cultureName); + } + Dictionary settings = new() { ["Logging:Console:FormatterName"] = "systemd" }; - Assert.AreEqual("systemd", GetConsoleLoggerOptions(settings).FormatterName, - "An explicitly configured console format must not be overridden."); + Assert.AreEqual( + UtcTimestampSystemdConsoleFormatter.FORMATTER_NAME, + GetConsoleLoggerOptions(settings).FormatterName, + "The 'systemd' console format must map to the DAB formatter emitting the same record structure."); (string stdout, _, DateTime before, DateTime after) = CaptureConsole(() => - { - using ILoggerFactory factory = CreateHostLoggerFactory(settings); - factory.CreateLogger("TestCategory").LogInformation(LOG_MESSAGE); - }); + RunUnderCulture(cultureName, () => + { + using ILoggerFactory factory = CreateHostLoggerFactory(settings); + factory.CreateLogger("TestCategory").LogInformation(LOG_MESSAGE); + })); string record = stdout.Split('\n').First(line => !string.IsNullOrWhiteSpace(line)); @@ -420,6 +446,100 @@ public void ConfigureHostLogging_ExplicitTimestampFormat_IsPreserved() "HH:mm:ss", provider.GetRequiredService>().CurrentValue.TimestampFormat, "An explicitly configured timestamp format must not be overridden."); + + (string stdout, _, _, _) = CaptureConsole(() => + { + using ILoggerFactory factory = CreateHostLoggerFactory(settings); + factory.CreateLogger("TestCategory").LogInformation(LOG_MESSAGE); + }); + + string record = stdout.Split('\n').First(line => !string.IsNullOrWhiteSpace(line)); + using JsonDocument document = JsonDocument.Parse(record); + string timestamp = document.RootElement.GetProperty("Timestamp").GetString()!; + Assert.IsTrue( + Regex.IsMatch(timestamp, @"^\d{2}:\d{2}:\d{2}$"), + $"The configured timestamp format must be used verbatim but got: '{timestamp}'"); + } + + /// + /// The console format can also be selected through the legacy + /// member, which the console logger provider only + /// honors while no formatter name is set. Selecting a DAB formatter sets that property, so + /// the legacy selection has to be resolved before it - a deployment configuring + /// 'Logging:Console:Format=Systemd' must keep its syslog priority prefixed records. + /// + [TestMethod] + public void ConfigureHostLogging_LegacyFormatSystemd_EmitsTimestampedSystemdRecord() + { + Dictionary settings = new() { ["Logging:Console:Format"] = "Systemd" }; + + Assert.AreEqual( + UtcTimestampSystemdConsoleFormatter.FORMATTER_NAME, + GetConsoleLoggerOptions(settings).FormatterName, + "The legacy 'Systemd' console format must map to the DAB systemd formatter."); + + (string stdout, _, DateTime before, DateTime after) = CaptureConsole(() => + { + using ILoggerFactory factory = CreateHostLoggerFactory(settings); + factory.CreateLogger("TestCategory").LogInformation(LOG_MESSAGE); + }); + + string record = stdout.Split('\n').First(line => !string.IsNullOrWhiteSpace(line)); + + // "<6>" is the syslog priority for Information. + Match match = Regex.Match(record, @"^<(?\d)>(?\S+?Z)"); + Assert.IsTrue(match.Success, + $"The legacy 'Systemd' console format must emit 'timestamp...' but got: '{record}'"); + Assert.AreEqual("6", match.Groups["priority"].Value, + $"Information must map to syslog priority 6 but got: '{record}'"); + AssertIsUtcTimestamp(match.Groups["ts"].Value, before, after); + StringAssert.Contains(record, LOG_MESSAGE); + } + + /// + /// The legacy members which the console logger provider + /// copies onto the selected formatter's options - here IncludeScopes - must keep applying + /// once a DAB formatter is selected. + /// + [TestMethod] + public void ConfigureHostLogging_LegacyIncludeScopes_IncludesScopes() + { + Dictionary settings = new() { ["Logging:Console:IncludeScopes"] = "true" }; + + (string stdout, _, DateTime before, DateTime after) = CaptureConsole(() => + { + using ILoggerFactory factory = CreateHostLoggerFactory(settings); + ILogger logger = factory.CreateLogger("TestCategory"); + using (logger.BeginScope(SCOPE_MESSAGE)) + { + logger.LogInformation(LOG_MESSAGE); + } + }); + + StringAssert.Contains(stdout, SCOPE_MESSAGE, + $"The legacy IncludeScopes setting must keep including scopes but got: '{stdout}'"); + AssertEveryEntryTimestamped(stdout, before, after); + } + + /// + /// A timestamp format configured through the legacy + /// members is an intentional override and must survive the formatter selection too. + /// + [TestMethod] + public void ConfigureHostLogging_LegacyTimestampFormat_IsPreserved() + { + Dictionary settings = new() { ["Logging:Console:TimestampFormat"] = "HH:mm:ss " }; + + (string stdout, _, _, _) = CaptureConsole(() => + { + using ILoggerFactory factory = CreateHostLoggerFactory(settings); + factory.CreateLogger("TestCategory").LogInformation(LOG_MESSAGE); + }); + + string record = stdout.Split('\n').First(line => !string.IsNullOrWhiteSpace(line)); + Assert.IsTrue( + Regex.IsMatch(record, @"^\d{2}:\d{2}:\d{2} info: "), + $"The legacy timestamp format must be used verbatim but got: '{record}'"); } /// @@ -471,8 +591,11 @@ private static void RunUnderCulture(string cultureName, Action action) /// /// Guards against the regression tests below silently passing on a runtime built with /// globalization-invariant mode, where every culture behaves like the invariant culture. + /// Asserts that the culture really does render the shared timestamp format differently from + /// the invariant culture - through a different calendar (ar-SA, th-TH) or through a + /// different time separator (fi-FI). /// - private static void AssertCultureIsNonGregorian(string cultureName) + private static void AssertCultureAffectsTimestampRendering(string cultureName) { DateTime probe = DateTime.UtcNow; string cultureRendering = string.Empty; @@ -482,8 +605,8 @@ private static void AssertCultureIsNonGregorian(string cultureName) 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."); + $"Culture '{cultureName}' is expected to render the timestamp format differently from the invariant " + + "culture; without that this test cannot detect culture-sensitive timestamp formatting."); } /// @@ -499,7 +622,7 @@ private static void AssertCultureIsNonGregorian(string cultureName) [DataRow("th-TH", true, DisplayName = "th-TH, stdio mode")] public void GetLoggerFactoryForLogLevel_NonGregorianCulture_EmitsInvariantUtcTimestamp(string cultureName, bool stdio) { - AssertCultureIsNonGregorian(cultureName); + AssertCultureAffectsTimestampRendering(cultureName); (string stdout, string stderr, DateTime before, DateTime after) = CaptureConsole(() => RunUnderCulture(cultureName, () => @@ -524,7 +647,7 @@ public void GetLoggerFactoryForLogLevel_NonGregorianCulture_EmitsInvariantUtcTim [DataRow("th-TH")] public void ConfigureHostLogging_NonGregorianCulture_EmitsInvariantUtcTimestamp(string cultureName) { - AssertCultureIsNonGregorian(cultureName); + AssertCultureAffectsTimestampRendering(cultureName); (string stdout, string stderr, DateTime before, DateTime after) = CaptureConsole(() => RunUnderCulture(cultureName, () => @@ -553,7 +676,7 @@ public void ConfigureHostLogging_NonGregorianCulture_EmitsInvariantUtcTimestamp( [DataRow("th-TH")] public void BootstrapLogger_NonGregorianCulture_EmitsInvariantUtcTimestamp(string cultureName) { - AssertCultureIsNonGregorian(cultureName); + AssertCultureAffectsTimestampRendering(cultureName); (string stdout, _, DateTime before, DateTime after) = CaptureConsole(() => RunUnderCulture(cultureName, () => BootstrapLogger.Instance.LogInformation(LOG_MESSAGE))); diff --git a/src/Service/Telemetry/ConsoleFormatterShared.cs b/src/Service/Telemetry/ConsoleFormatterShared.cs new file mode 100644 index 0000000000..49cbdbcb9b --- /dev/null +++ b/src/Service/Telemetry/ConsoleFormatterShared.cs @@ -0,0 +1,112 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System; +using System.Globalization; +using System.Text; +using Azure.DataApiBuilder.Product; +using Microsoft.Extensions.Logging.Console; + +namespace Azure.DataApiBuilder.Service.Telemetry +{ + /// + /// Helpers shared by the DAB console formatters so that the timestamp contract and the + /// console hardening are implemented exactly once, regardless of the selected record format. + /// + internal static class ConsoleFormatterShared + { + /// + /// Renders the timestamp DAB prefixes onto a console entry. + /// + /// + /// When the deployment did not configure a timestamp of its own, DAB supplies the value and + /// it is rendered as an ISO 8601 UTC timestamp with millisecond precision using + /// . The built-in formatters instead render + /// through + /// DateTimeOffset.ToString(format), which resolves against + /// - that yields a non-Gregorian year under cultures + /// such as th-TH (2569) or ar-SA (1448), and a culture specific time separator under cultures + /// such as fi-FI (08.04.02 rather than 08:04:02). + /// An explicitly configured is an + /// intentional override, so it keeps the built-in semantics (current culture, and the time + /// zone selected by ). + /// + public static string FormatTimestamp(DateTimeOffset stamp, ConsoleFormatterOptions options) + { + string? configuredFormat = options.TimestampFormat; + if (string.IsNullOrEmpty(configuredFormat)) + { + return stamp.UtcDateTime.ToString(BootstrapLogger.UTC_TIMESTAMP_FORMAT, CultureInfo.InvariantCulture); + } + + return stamp.ToString(configuredFormat); + } + + /// + /// Whether DAB - rather than the deployment - supplies the timestamp for an entry. + /// + public static bool IsDabSuppliedTimestamp(ConsoleFormatterOptions options) + => string.IsNullOrEmpty(options.TimestampFormat); + + /// + /// Returns the instant to stamp a live (non-buffered) entry with. DAB always supplies a UTC + /// value; only an explicitly configured timestamp format may opt into local time. + /// + public static DateTimeOffset GetCurrentTimestamp(ConsoleFormatterOptions options) + { + bool useLocalTime = !string.IsNullOrEmpty(options.TimestampFormat) && !options.UseUtcTimestamp; + return useLocalTime ? DateTimeOffset.Now : DateTimeOffset.UtcNow; + } + + /// + /// 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. + /// Log entries carry untrusted values (request headers, entity names, configuration paths), + /// so they must not be able to emit raw escape sequences to the operator's terminal. + /// + public 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')); + } + } +} diff --git a/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs b/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs index ceaf24d3ba..36b7738c5e 100644 --- a/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs +++ b/src/Service/Telemetry/UtcTimestampConsoleFormatter.cs @@ -4,7 +4,6 @@ using System; using System.Globalization; using System.IO; -using System.Text; using Azure.DataApiBuilder.Product; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.DependencyInjection.Extensions; @@ -97,7 +96,7 @@ public override void Write(in LogEntry logEntry, IExternalScopeP logEntry.EventId.Id, logEntry.Exception?.ToString(), logEntry.Category, - DateTimeOffset.UtcNow); + ConsoleFormatterShared.GetCurrentTimestamp(_formatterOptions)); } private void WriteInternal( @@ -118,17 +117,23 @@ private void WriteInternal( // 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)!; + message = ConsoleFormatterShared.SanitizeControlCharacters(message)!; + exception = ConsoleFormatterShared.SanitizeControlCharacters(exception); + category = ConsoleFormatterShared.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(' '); + // option) so that the DAB supplied value is always UTC and always culture invariant. + textWriter.Write(ConsoleFormatterShared.FormatTimestamp(stamp, formatterOptions)); + if (ConsoleFormatterShared.IsDabSuppliedTimestamp(formatterOptions)) + { + // A deployment supplied format is written exactly as configured (the built-in + // formatter expects any trailing separator to be part of that format), but the DAB + // supplied timestamp needs a separator before the log level. + textWriter.Write(' '); + } if (EmitAnsiColorCodes(formatterOptions.ColorBehavior)) { @@ -165,56 +170,6 @@ private void WriteInternal( } } - /// - /// 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)) @@ -319,71 +274,136 @@ private static void WriteColoredLogLevel(TextWriter textWriter, LogLevel logLeve } /// - /// Registration helpers for . + /// Records whether the console logger provider was configured through the legacy + /// members rather than through + /// . + /// + /// + /// The console logger provider only copies the legacy members onto the selected formatter's + /// options when is null. Selecting a DAB + /// formatter sets that property, which would otherwise silently drop those settings, so the + /// copy is performed here instead. A single flag is enough because the legacy members + /// themselves are left untouched on . + /// + internal sealed class LegacyConsoleLoggerOptionsMarker + { + public bool IsActive { get; set; } + } + + /// + /// Registration helpers for the DAB console formatters. /// 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 + /// Registers the DAB console formatters and selects the one matching the requested console + /// format, so that every console entry carries a culture invariant ISO 8601 UTC timestamp. + /// This only registers formatters - 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. /// /// - /// The formatter is only selected when no console format was explicitly requested, or when the - /// default "simple" format was requested. A deployment which opts into "json" or "systemd" (via - /// Logging:Console:FormatterName) keeps that output contract, because structured log - /// collectors and systemd severity extraction depend on it. Those formats render their own - /// timestamp, which the built-in formatters omit entirely unless - /// is set, so the shared UTC format is - /// applied to them as well. + /// The record structure of the requested format is preserved, because structured log collectors + /// and systemd severity extraction depend on it: "simple" maps to + /// , "json" to + /// and "systemd" to + /// . A formatter name which is not one of the + /// three built-ins identifies a formatter the deployment registered itself and is left alone. /// public static ILoggingBuilder AddUtcTimestampConsoleFormatter(this ILoggingBuilder builder) { builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton()); + builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton()); + builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton()); + builder.Services.TryAddSingleton(); // PostConfigure runs after the "Logging:Console" configuration binding, so an explicitly - // configured FormatterName is visible here and is left untouched. - builder.Services.PostConfigure(options => - { - if (string.IsNullOrEmpty(options.FormatterName) || - string.Equals(options.FormatterName, ConsoleFormatterNames.Simple, StringComparison.OrdinalIgnoreCase)) - { - options.FormatterName = UtcTimestampConsoleFormatter.FORMATTER_NAME; - } - }); - - // "json" uses JsonConsoleFormatterOptions, "systemd" uses ConsoleFormatterOptions. Neither - // shares an options type with the "simple" formatter (SimpleConsoleFormatterOptions), so - // configuring them here cannot affect the DAB formatter above. - builder.Services.PostConfigure(ApplyUtcTimestampFormat); - builder.Services.PostConfigure(ApplyUtcTimestampFormat); + // configured format - whether through FormatterName or through the legacy Format member - + // is visible here. + builder.Services.AddOptions() + .PostConfigure(SelectUtcTimestampFormatter); + + // Each built-in format binds a different options type, so the legacy members have to be + // mapped onto all three. SimpleConsoleFormatterOptions and JsonConsoleFormatterOptions + // derive from ConsoleFormatterOptions but are distinct options types, so configuring one + // does not affect the others. + builder.Services.AddOptions() + .PostConfigure, LegacyConsoleLoggerOptionsMarker>(ApplyLegacyConsoleLoggerOptions); + builder.Services.AddOptions() + .PostConfigure, LegacyConsoleLoggerOptionsMarker>(ApplyLegacyConsoleLoggerOptions); + builder.Services.AddOptions() + .PostConfigure, LegacyConsoleLoggerOptionsMarker>(ApplyLegacyConsoleLoggerOptions); return builder; } /// - /// Applies the shared UTC timestamp format to a built-in console formatter, unless the - /// deployment already configured a timestamp format of its own. + /// Replaces the requested built-in console format with the DAB formatter producing the same + /// record structure. /// - /// - /// The built-in "json" and "systemd" formatters render this format through - /// DateTimeOffset.ToString(TimestampFormat), which resolves against - /// . On a host whose culture uses a non-Gregorian - /// calendar they therefore emit that calendar's year. Making those formats culture invariant - /// would require reimplementing them, so it is deliberately not done here: they are opt-in - /// formats whose output contract belongs to the log collector consuming them. The default - /// console format, which owns, is invariant. - /// - private static void ApplyUtcTimestampFormat(ConsoleFormatterOptions options) + private static void SelectUtcTimestampFormatter(ConsoleLoggerOptions options, LegacyConsoleLoggerOptionsMarker legacy) + { + string requestedFormat; + if (string.IsNullOrEmpty(options.FormatterName)) + { +#pragma warning disable CS0618 // Type or member is obsolete + // A null FormatterName means the format is selected by the legacy Format member, and + // that the remaining legacy members apply to the selected formatter. + requestedFormat = options.Format == ConsoleLoggerFormat.Systemd + ? ConsoleFormatterNames.Systemd + : ConsoleFormatterNames.Simple; +#pragma warning restore CS0618 + legacy.IsActive = true; + } + else + { + requestedFormat = options.FormatterName; + } + + if (string.Equals(requestedFormat, ConsoleFormatterNames.Simple, StringComparison.OrdinalIgnoreCase)) + { + options.FormatterName = UtcTimestampConsoleFormatter.FORMATTER_NAME; + } + else if (string.Equals(requestedFormat, ConsoleFormatterNames.Json, StringComparison.OrdinalIgnoreCase)) + { + options.FormatterName = UtcTimestampJsonConsoleFormatter.FORMATTER_NAME; + } + else if (string.Equals(requestedFormat, ConsoleFormatterNames.Systemd, StringComparison.OrdinalIgnoreCase)) + { + options.FormatterName = UtcTimestampSystemdConsoleFormatter.FORMATTER_NAME; + } + } + + /// + /// Copies the legacy members onto a formatter's options, + /// reproducing what the console logger provider does when no formatter name is configured. + /// + private static void ApplyLegacyConsoleLoggerOptions( + ConsoleFormatterOptions formatterOptions, + IOptionsMonitor consoleLoggerOptionsMonitor, + LegacyConsoleLoggerOptionsMarker legacy) { - if (string.IsNullOrEmpty(options.TimestampFormat)) + // Resolving the console logger options runs their configuration and post-configuration + // chain - including SelectUtcTimestampFormatter - which is what populates the marker. + ConsoleLoggerOptions consoleLoggerOptions = consoleLoggerOptionsMonitor.CurrentValue; + if (!legacy.IsActive) + { + return; + } + +#pragma warning disable CS0618 // Type or member is obsolete + formatterOptions.IncludeScopes = consoleLoggerOptions.IncludeScopes; + formatterOptions.TimestampFormat = consoleLoggerOptions.TimestampFormat; + formatterOptions.UseUtcTimestamp = consoleLoggerOptions.UseUtcTimestamp; + + if (formatterOptions is SimpleConsoleFormatterOptions simpleFormatterOptions) { - options.TimestampFormat = BootstrapLogger.UTC_TIMESTAMP_FORMAT; - options.UseUtcTimestamp = true; + simpleFormatterOptions.ColorBehavior = consoleLoggerOptions.DisableColors + ? LoggerColorBehavior.Disabled + : LoggerColorBehavior.Default; } +#pragma warning restore CS0618 } } } diff --git a/src/Service/Telemetry/UtcTimestampJsonConsoleFormatter.cs b/src/Service/Telemetry/UtcTimestampJsonConsoleFormatter.cs new file mode 100644 index 0000000000..4793ad1d27 --- /dev/null +++ b/src/Service/Telemetry/UtcTimestampJsonConsoleFormatter.cs @@ -0,0 +1,256 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System; +using System.Buffers; +using System.Collections.Generic; +using System.Globalization; +using System.IO; +using System.Text; +using System.Text.Json; +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 record structure of the built-in "json" formatter - + /// one JSON object per entry carrying Timestamp, EventId, LogLevel, Category, Message, Exception, + /// State and Scopes - but renders the DAB supplied timestamp as an invariant UTC ISO 8601 value. + /// See for why the built-in formatter cannot + /// be configured to do this. + /// + public sealed class UtcTimestampJsonConsoleFormatter : ConsoleFormatter, IDisposable + { + /// + /// Value to assign to to select this formatter. + /// + public const string FORMATTER_NAME = "dab-utc-json"; + + private readonly IDisposable? _optionsReloadToken; + + private JsonConsoleFormatterOptions _formatterOptions; + + public UtcTimestampJsonConsoleFormatter(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, attributes 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, + logEntry.Category, + bufferedRecord.EventId.Id, + bufferedRecord.Exception, + bufferedRecord.Attributes.Count > 0, + stateMessage: null, + bufferedRecord.Attributes, + 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.Category, + logEntry.EventId.Id, + logEntry.Exception?.ToString(), + logEntry.State is not null, + logEntry.State?.ToString(), + logEntry.State as IReadOnlyList>, + ConsoleFormatterShared.GetCurrentTimestamp(_formatterOptions)); + } + + private void WriteInternal( + IExternalScopeProvider? scopeProvider, + TextWriter textWriter, + string? message, + LogLevel logLevel, + string category, + int eventId, + string? exception, + bool hasState, + string? stateMessage, + IReadOnlyList>? stateProperties, + DateTimeOffset stamp) + { + string? logLevelString = GetLogLevelString(logLevel); + if (logLevelString is null) + { + return; + } + + JsonConsoleFormatterOptions formatterOptions = _formatterOptions; + + ArrayBufferWriter output = new(initialCapacity: 1024); + using (Utf8JsonWriter writer = new(output, formatterOptions.JsonWriterOptions)) + { + writer.WriteStartObject(); + writer.WriteString("Timestamp", ConsoleFormatterShared.FormatTimestamp(stamp, formatterOptions)); + writer.WriteNumber("EventId", eventId); + writer.WriteString("LogLevel", logLevelString); + writer.WriteString("Category", category); + writer.WriteString("Message", message); + + if (exception is not null) + { + writer.WriteString(nameof(Exception), exception); + } + + if (hasState) + { + writer.WriteStartObject("State"); + + // The message and the state message are usually identical, so the state message + // is only written when it differs - this keeps the record smaller. + if (!string.Equals(message, stateMessage, StringComparison.Ordinal)) + { + writer.WriteString("Message", stateMessage); + } + + if (stateProperties is not null) + { + foreach (KeyValuePair item in stateProperties) + { + WriteItem(writer, item); + } + } + + writer.WriteEndObject(); + } + + WriteScopeInformation(writer, scopeProvider, formatterOptions.IncludeScopes); + writer.WriteEndObject(); + writer.Flush(); + } + + // JSON string escaping already neutralizes the control characters which would otherwise + // drive terminal escape sequences, so no additional sanitization is needed here. + textWriter.Write(Encoding.UTF8.GetString(output.WrittenSpan)); + textWriter.Write(Environment.NewLine); + } + + private static void WriteScopeInformation(Utf8JsonWriter writer, IExternalScopeProvider? scopeProvider, bool includeScopes) + { + if (!includeScopes || scopeProvider is null) + { + return; + } + + writer.WriteStartArray("Scopes"); + scopeProvider.ForEachScope((scope, state) => + { + if (scope is IEnumerable> scopeItems) + { + state.WriteStartObject(); + state.WriteString("Message", scope.ToString()); + foreach (KeyValuePair item in scopeItems) + { + WriteItem(state, item); + } + + state.WriteEndObject(); + } + else + { + state.WriteStringValue(ToInvariantString(scope)); + } + }, writer); + writer.WriteEndArray(); + } + + private static void WriteItem(Utf8JsonWriter writer, KeyValuePair item) + { + string key = item.Key; + switch (item.Value) + { + case bool boolValue: + writer.WriteBoolean(key, boolValue); + break; + case byte byteValue: + writer.WriteNumber(key, byteValue); + break; + case sbyte sbyteValue: + writer.WriteNumber(key, sbyteValue); + break; + case char charValue: + writer.WriteString(key, charValue.ToString()); + break; + case decimal decimalValue: + writer.WriteNumber(key, decimalValue); + break; + case double doubleValue: + writer.WriteNumber(key, doubleValue); + break; + case float floatValue: + writer.WriteNumber(key, floatValue); + break; + case int intValue: + writer.WriteNumber(key, intValue); + break; + case uint uintValue: + writer.WriteNumber(key, uintValue); + break; + case long longValue: + writer.WriteNumber(key, longValue); + break; + case ulong ulongValue: + writer.WriteNumber(key, ulongValue); + break; + case short shortValue: + writer.WriteNumber(key, shortValue); + break; + case ushort ushortValue: + writer.WriteNumber(key, ushortValue); + break; + case null: + writer.WriteNull(key); + break; + default: + writer.WriteString(key, ToInvariantString(item.Value)); + break; + } + } + + private static string? ToInvariantString(object? value) => Convert.ToString(value, CultureInfo.InvariantCulture); + + private static string? GetLogLevelString(LogLevel logLevel) + { + return logLevel switch + { + LogLevel.Trace => "Trace", + LogLevel.Debug => "Debug", + LogLevel.Information => "Information", + LogLevel.Warning => "Warning", + LogLevel.Error => "Error", + LogLevel.Critical => "Critical", + _ => null, + }; + } + } +} diff --git a/src/Service/Telemetry/UtcTimestampSystemdConsoleFormatter.cs b/src/Service/Telemetry/UtcTimestampSystemdConsoleFormatter.cs new file mode 100644 index 0000000000..4263be0e91 --- /dev/null +++ b/src/Service/Telemetry/UtcTimestampSystemdConsoleFormatter.cs @@ -0,0 +1,180 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System; +using System.Globalization; +using System.IO; +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 record structure of the built-in "systemd" formatter - + /// the syslog priority prefix journald uses for severity extraction, followed by the timestamp, + /// category, event id, scopes, message and exception on a single line: + /// + /// <6>2026-07-07T14:01:01.344Z Azure.DataApiBuilder.Service.Startup[0] Now listening on: http://localhost:5000 + /// + /// but renders the DAB supplied timestamp as an invariant UTC ISO 8601 value. + /// See for why the built-in formatter cannot + /// be configured to do this. + /// + public sealed class UtcTimestampSystemdConsoleFormatter : ConsoleFormatter, IDisposable + { + /// + /// Value to assign to to select this formatter. + /// + public const string FORMATTER_NAME = "dab-utc-systemd"; + + private readonly IDisposable? _optionsReloadToken; + + private ConsoleFormatterOptions _formatterOptions; + + public UtcTimestampSystemdConsoleFormatter(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, + logEntry.Category, + bufferedRecord.EventId.Id, + bufferedRecord.Exception, + 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.Category, + logEntry.EventId.Id, + logEntry.Exception?.ToString(), + ConsoleFormatterShared.GetCurrentTimestamp(_formatterOptions)); + } + + private void WriteInternal( + IExternalScopeProvider? scopeProvider, + TextWriter textWriter, + string message, + LogLevel logLevel, + string category, + int eventId, + string? exception, + DateTimeOffset stamp) + { + string? logLevelString = GetSyslogSeverityString(logLevel); + if (logLevelString is null) + { + return; + } + + ConsoleFormatterOptions formatterOptions = _formatterOptions; + + // systemd reads messages line-by-line, so newlines are replaced before the remaining + // control characters are escaped. + message = ConsoleFormatterShared.SanitizeControlCharacters(ReplaceNewLines(message))!; + exception = ConsoleFormatterShared.SanitizeControlCharacters(ReplaceNewLines(exception)); + category = ConsoleFormatterShared.SanitizeControlCharacters(category)!; + + textWriter.Write(logLevelString); + textWriter.Write(ConsoleFormatterShared.FormatTimestamp(stamp, formatterOptions)); + if (ConsoleFormatterShared.IsDabSuppliedTimestamp(formatterOptions)) + { + // A deployment supplied format is written exactly as configured (the built-in + // formatter expects any trailing separator to be part of that format), but the DAB + // supplied timestamp needs a separator before the category. + textWriter.Write(' '); + } + + textWriter.Write(category); + textWriter.Write('['); + textWriter.Write(eventId.ToString(CultureInfo.InvariantCulture)); + textWriter.Write(']'); + + WriteScopeInformation(textWriter, scopeProvider, formatterOptions.IncludeScopes); + + if (!string.IsNullOrEmpty(message)) + { + textWriter.Write(' '); + textWriter.Write(message); + } + + if (!string.IsNullOrEmpty(exception)) + { + textWriter.Write(' '); + textWriter.Write(exception); + } + + textWriter.Write(Environment.NewLine); + } + + private static string? ReplaceNewLines(string? value) + { + if (string.IsNullOrEmpty(value)) + { + return value; + } + + return value.Replace(Environment.NewLine, " ").Replace("\n", " ").Replace("\r", " "); + } + + private static void WriteScopeInformation(TextWriter textWriter, IExternalScopeProvider? scopeProvider, bool includeScopes) + { + if (!includeScopes || scopeProvider is null) + { + return; + } + + scopeProvider.ForEachScope((scope, state) => + { + state.Write(" => "); + state.Write(ConsoleFormatterShared.SanitizeControlCharacters(scope?.ToString())); + }, textWriter); + } + + /// + /// Maps a log level onto the syslog severity from RFC 5424 that journald reads. + /// + private static string? GetSyslogSeverityString(LogLevel logLevel) + { + return logLevel switch + { + LogLevel.Trace => "<7>", + LogLevel.Debug => "<7>", + LogLevel.Information => "<6>", + LogLevel.Warning => "<4>", + LogLevel.Error => "<3>", + LogLevel.Critical => "<2>", + _ => null, + }; + } + } +}