feat: add UTC timestamps to all console log entries

src/Aspire.AppHost/AppHost.cs

@@ -1,4 +1,6 @@
+using Azure.DataApiBuilder.Product;
 using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Logging;
 
 var builder = DistributedApplication.CreateBuilder(args);
 
@@ -15,7 +17,7 @@
 
         if (string.IsNullOrEmpty(databaseConnectionString))
         {
-            Console.WriteLine("No connection string provided, starting a local SQL Server container.");
+            BootstrapLogger.Instance.LogInformation("No connection string provided, starting a local SQL Server container.");
 
             sqlDbContainer = builder.AddSqlServer("sqlserver")
                 .WithDataVolume()
@@ -53,9 +55,9 @@
 
         IResourceBuilder<PostgresDatabaseResource>? 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()

src/Aspire.AppHost/Aspire.AppHost.csproj

@@ -22,6 +22,11 @@
 
   <ItemGroup>
     <ProjectReference Include="..\Service\Azure.DataApiBuilder.Service.csproj" />
+    <!-- Referenced as a plain library (not an Aspire resource) so AppHost diagnostics can use
+         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. -->
+    <ProjectReference Include="..\Product\Azure.DataApiBuilder.Product.csproj" IsAspireProjectResource="false" />
   </ItemGroup>
 
 </Project>

src/Cli.Tests/CustomLoggerTests.cs

@@ -1,6 +1,9 @@
 // Copyright (c) Microsoft Corporation.
 // Licensed under the MIT License.
 
+using System.Globalization;
+using System.Text.RegularExpressions;
+
 namespace Cli.Tests;
 
 /// <summary>
@@ -29,30 +32,97 @@ public void ResetMcpStaticState()
         Cli.Utils.ConfigLogLevel = LogLevel.Information;
     }
 
+    /// <summary>
+    /// 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.
+    /// </summary>
+    private static readonly Regex _timestampPrefix =
+        new(@"^(?<ts>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z) ", RegexOptions.Compiled);
+
     /// <summary>
     /// Redirects Console.Out and Console.Error around <paramref name="action"/>
-    /// 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.
     /// </summary>
-    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
         {
             Console.SetOut(originalOut);
             Console.SetError(originalError);
         }
 
-        return (stdout.ToString(), stderr.ToString());
+        return (stdout.ToString(), stderr.ToString(), before, after);
+    }
+
+    /// <summary>
+    /// Asserts that <paramref name="entry"/> 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.
+    /// </summary>
+    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..];
+    }
+
+    /// <summary>
+    /// Asserts that every emitted line is timestamped (the CLI logger writes one line per
+    /// entry) and returns the lines with their timestamps stripped.
+    /// </summary>
+    private static string[] AssertEveryEntryTimestamped(string output, DateTime before, DateTime after)
+    {
+        string[] entries = output
+            .Split('\n')
+            .Select(line => line.TrimEnd('\r'))
+            .Where(line => !string.IsNullOrWhiteSpace(line))
+            .ToArray();
+
+        Assert.IsTrue(entries.Length > 0, $"Expected at least one log entry but got: '{output}'");
+
+        return entries.Select(entry => AssertStartsWithUtcTimestamp(entry, before, after)).ToArray();
     }
 
     private static ILogger NewLogger() =>
@@ -72,13 +142,15 @@ public void LogOutput_UsesAbbreviatedLogLevelLabels(LogLevel logLevel, string ex
     {
         const string Message = "test message";
 
-        (string stdout, string stderr) = CaptureConsole(() => NewLogger().Log(logLevel, Message));
+        (string stdout, string stderr, DateTime before, DateTime after) =
+            CaptureConsole(() => NewLogger().Log(logLevel, Message));
 
         string actual = expectStderr ? stderr : stdout;
         string other = expectStderr ? stdout : stderr;
 
-        Assert.IsTrue(actual.StartsWith(expectedPrefix),
-            $"Expected output to start with '{expectedPrefix}' but got: '{actual}'");
+        string[] withoutTimestamps = AssertEveryEntryTimestamped(actual, before, after);
+        Assert.IsTrue(withoutTimestamps.Single().StartsWith(expectedPrefix),
+            $"Expected the timestamp to be followed immediately by '{expectedPrefix}' but got: '{actual}'");
         StringAssert.Contains(actual, Message);
         Assert.AreEqual(string.Empty, other,
             $"Did not expect output on the other stream but got: '{other}'");
@@ -94,7 +166,7 @@ public void Mcp_NoOverrides_SuppressesAllOutput()
     {
         Cli.Utils.IsMcpStdioMode = true;
 
-        (string stdout, string stderr) = CaptureConsole(() =>
+        (string stdout, string stderr, _, _) = CaptureConsole(() =>
         {
             ILogger logger = NewLogger();
             logger.Log(LogLevel.Information, "info should not appear");
@@ -117,7 +189,7 @@ public void Mcp_CliOverride_WritesToStderrAndHonorsCliLevel()
         Cli.Utils.IsCliOverriding = true;
         Cli.Utils.CliLogLevel = LogLevel.Warning;
 
-        (string stdout, string stderr) = CaptureConsole(() =>
+        (string stdout, string stderr, DateTime before, DateTime after) = CaptureConsole(() =>
         {
             ILogger logger = NewLogger();
             logger.Log(LogLevel.Information, "filtered info");   // below threshold
@@ -129,6 +201,13 @@ public void Mcp_CliOverride_WritesToStderrAndHonorsCliLevel()
         Assert.IsFalse(stderr.Contains("filtered info"), $"Below-threshold log should be filtered. Got: '{stderr}'");
         StringAssert.Contains(stderr, "warn: visible warn");
         StringAssert.Contains(stderr, "fail: visible error");
+
+        // Every emitted entry - not just the first - must carry a UTC timestamp.
+        string[] withoutTimestamps = AssertEveryEntryTimestamped(stderr, before, after);
+        CollectionAssert.AreEqual(
+            new[] { "warn: visible warn", "fail: visible error" },
+            withoutTimestamps,
+            $"Expected exactly the above-threshold entries, each prefixed by a timestamp. Got: '{stderr}'");
     }
 
     /// <summary>
@@ -143,16 +222,24 @@ public void Mcp_ConfigOverride_WritesToStderrAndHonorsConfigLevel()
         Cli.Utils.IsConfigOverriding = true;
         Cli.Utils.ConfigLogLevel = LogLevel.Information;
 
-        (string stdout, string stderr) = CaptureConsole(() =>
+        (string stdout, string stderr, DateTime before, DateTime after) = CaptureConsole(() =>
         {
             ILogger logger = NewLogger();
-            logger.Log(LogLevel.Debug, "filtered debug");      // below threshold
-            logger.Log(LogLevel.Information, "visible info");  // at threshold
+            logger.Log(LogLevel.Debug, "filtered debug");        // below threshold
+            logger.Log(LogLevel.Information, "visible info");    // at threshold
+            logger.Log(LogLevel.Error, "visible error");         // above threshold
         });
 
         Assert.AreEqual(string.Empty, stdout, "MCP mode must never write to stdout.");
         Assert.IsFalse(stderr.Contains("filtered debug"), $"Below-threshold log should be filtered. Got: '{stderr}'");
         StringAssert.Contains(stderr, "info: visible info");
+
+        // Every emitted entry - not just the first - must carry a UTC timestamp.
+        string[] withoutTimestamps = AssertEveryEntryTimestamped(stderr, before, after);
+        CollectionAssert.AreEqual(
+            new[] { "info: visible info", "fail: visible error" },
+            withoutTimestamps,
+            $"Expected exactly the above-threshold entries, each prefixed by a timestamp. Got: '{stderr}'");
     }
 
     /// <summary>
@@ -168,7 +255,7 @@ public void Mcp_CliOverridePrecedesConfigOverride()
         Cli.Utils.IsConfigOverriding = true;
         Cli.Utils.ConfigLogLevel = LogLevel.Information;
 
-        (_, string stderr) = CaptureConsole(() =>
+        (_, string stderr, _, _) = CaptureConsole(() =>
         {
             ILogger logger = NewLogger();
             logger.Log(LogLevel.Information, "filtered by CLI Warning");

src/Cli/CustomLoggerProvider.cs

@@ -1,6 +1,8 @@
 // Copyright (c) Microsoft Corporation.
 // Licensed under the MIT License.
 
+using System.Globalization;
+using Azure.DataApiBuilder.Product;
 using Microsoft.Extensions.Logging;
 
 /// <summary>
@@ -25,6 +27,8 @@ public ILogger CreateLogger(string categoryName)
 
     public class CustomConsoleLogger : ILogger
     {
+        private const string UTC_TIMESTAMP_FORMAT = BootstrapLogger.UTC_TIMESTAMP_FORMAT;
+
         private readonly LogLevel _minimumLogLevel;
 
         // Minimum LogLevel for CLI output.
@@ -124,13 +128,14 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
                 // Apply colors so the abbreviation matches the visual style of engine logs.
                 // try/finally guarantees the original colors are restored even if Write throws,
                 // otherwise the console would be left tinted (e.g. red on error) for subsequent output.
+                string mcpTimestamp = DateTime.UtcNow.ToString(UTC_TIMESTAMP_FORMAT, CultureInfo.InvariantCulture);
                 ConsoleColor mcpOriginalForeGroundColor = Console.ForegroundColor;
                 ConsoleColor mcpOriginalBackGroundColor = Console.BackgroundColor;
                 try
                 {
                     Console.ForegroundColor = _logLevelToForeGroundConsoleColorMap.GetValueOrDefault(logLevel, ConsoleColor.White);
                     Console.BackgroundColor = _logLevelToBackGroundConsoleColorMap.GetValueOrDefault(logLevel, ConsoleColor.Black);
-                    Console.Error.Write($"{mcpAbbreviation}:");
+                    Console.Error.Write($"{mcpTimestamp} {mcpAbbreviation}:");
                 }
                 finally
                 {
@@ -153,6 +158,7 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
             }
 
             TextWriter writer = logLevel >= LogLevel.Error ? Console.Error : Console.Out;
+            string timestamp = DateTime.UtcNow.ToString(UTC_TIMESTAMP_FORMAT, CultureInfo.InvariantCulture);
             // try/finally guarantees the original colors are restored even if Write throws,
             // otherwise the console would be left tinted (e.g. red on error) for subsequent output.
             ConsoleColor originalForeGroundColor = Console.ForegroundColor;
@@ -161,7 +167,7 @@ public void Log<TState>(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
             {

src/Cli/Program.cs

@@ -3,6 +3,7 @@
 
 using System.IO.Abstractions;
 using Azure.DataApiBuilder.Config;
+using Azure.DataApiBuilder.Product;
 using Cli.Commands;
 using CommandLine;
 using Microsoft.Extensions.Logging;
@@ -59,6 +60,9 @@ private static void ParseEarlyFlags(string[] args)
                 if (string.Equals(arg, "--mcp-stdio", StringComparison.OrdinalIgnoreCase))
                 {
                     Utils.IsMcpStdioMode = true;
+
+                    // stdout is reserved for the JSON-RPC protocol stream.
+                    BootstrapLogger.WriteAllOutputToStandardError = true;
                 }
                 else if (string.Equals(arg, "--log-level", StringComparison.OrdinalIgnoreCase) && i + 1 < args.Length)
                 {

src/Config/ConfigFileWatcher.cs

@@ -3,6 +3,8 @@
 
 using System.IO.Abstractions;
 using Azure.DataApiBuilder.Config.Utilities;
+using Azure.DataApiBuilder.Product;
+using Microsoft.Extensions.Logging;
 
 namespace Azure.DataApiBuilder.Config;
 
@@ -109,17 +111,17 @@ private void OnConfigFileChange(object sender, FileSystemEventArgs e)
         catch (AggregateException ex)
         {
             // Need to remove the dependencies in startup on the RuntimeConfigProvider
-            // before we can have an ILogger here.
+            // before we can have an injected ILogger here.
             foreach (Exception exception in ex.InnerExceptions)
             {
-                Console.WriteLine("Unable to hot reload configuration file due to " + exception.Message);
+                BootstrapLogger.Instance.LogWarning("Unable to hot reload configuration file due to " + exception.Message);
             }
         }
         catch (Exception ex)
         {
             // Need to remove the dependencies in startup on the RuntimeConfigProvider
-            // before we can have an ILogger here.
-            Console.WriteLine("Unable to hot reload configuration file due to " + ex.Message);
+            // before we can have an injected ILogger here.
+            BootstrapLogger.Instance.LogWarning("Unable to hot reload configuration file due to " + ex.Message);
         }
     }
 

src/Config/FileSystemRuntimeConfigLoader.cs

@@ -9,6 +9,7 @@
 using Azure.DataApiBuilder.Config.Converters;
 using Azure.DataApiBuilder.Config.ObjectModel;
 using Azure.DataApiBuilder.Config.Utilities;
+using Azure.DataApiBuilder.Product;
 using Azure.DataApiBuilder.Service.Exceptions;
 using Microsoft.Extensions.Logging;
 
@@ -181,8 +182,8 @@ private bool TrySetupConfigFileWatcher()
             catch (Exception ex)
             {
                 // Need to remove the dependencies in startup on the RuntimeConfigProvider
-                // before we can have an ILogger here.
-                Console.WriteLine($"Attempt to configure config file watcher for hot reload failed due to: {ex.Message}.");
+                // before we can have an injected ILogger here.
+                (_logger as ILogger ?? BootstrapLogger.Instance).LogWarning($"Attempt to configure config file watcher for hot reload failed due to: {ex.Message}.");
             }
 
             return _configFileWatcher is not null;
@@ -208,8 +209,8 @@ private void OnNewFileContentsDetected(object? sender, EventArgs e)
         catch (Exception ex)
         {
             // Need to remove the dependencies in startup on the RuntimeConfigProvider
-            // before we can have an ILogger here.
-            Console.WriteLine("Unable to hot reload configuration file due to " + ex.Message);
+            // before we can have an injected ILogger here.
+            (_logger as ILogger ?? BootstrapLogger.Instance).LogWarning("Unable to hot reload configuration file due to " + ex.Message);
         }
     }
 

src/Config/Utilities/FileUtilities.cs

@@ -3,6 +3,8 @@
 
 using System.IO.Abstractions;
 using System.Security.Cryptography;
+using Azure.DataApiBuilder.Product;
+using Microsoft.Extensions.Logging;
 
 namespace Azure.DataApiBuilder.Config.Utilities;
 
@@ -61,13 +63,13 @@ public static byte[] ComputeHash(IFileSystem fileSystem, string filePath)
                 }
                 else
                 {
-                    Console.WriteLine($"Path '{filePath}' not found in: " + Directory.GetCurrentDirectory());
+                    BootstrapLogger.Instance.LogWarning($"Path '{filePath}' not found in: " + Directory.GetCurrentDirectory());
                     throw new FileNotFoundException();
                 }
             }
             catch (IOException ex)
             {
-                Console.WriteLine($"IO Exception, retrying due to {ex.Message}");
+                BootstrapLogger.Instance.LogWarning($"IO Exception, retrying due to {ex.Message}");
                 if (runCount == RunLimit)
                 {
                     throw;