feat: add UTC timestamps to all console log entries

[Copilot]

Why make this change?

Console log output lacks timestamps, making it difficult to correlate events or determine when entries occurred — especially under high request volume.

What is this change?

Prepends an ISO 8601 UTC timestamp with millisecond precision to every console log entry:

2026-07-07T14:01:01.344Z info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://localhost:5000/graphql - - -
2026-07-07T14:01:01.345Z dbug: Azure.DataApiBuilder.Core.AuthenticationHelpers.ClientRoleHeaderAuthenticationMiddleware[0]
      bfa3a6ee AuthN state: Anonymous. Role: Anonymous.

• src/Service/Program.cs — Replaces AddConsole() with AddSimpleConsole(TimestampFormat, UseUtcTimestamp) in both GetLoggerFactoryForLogLevel (startup logger) and CreateHostBuilder.ConfigureLogging (web host logger). MCP stdio path additionally uses Services.Configure<ConsoleLoggerOptions> for stderr routing, keeping a single registered provider.
• src/Cli/CustomLoggerProvider.cs — Prepends DateTime.UtcNow.ToString(UtcTimestampFormat) before the abbreviated level label in the CLI's custom console logger (both standard and MCP stdio paths). Timestamp format extracted to a named constant.
• src/Cli.Tests/CustomLoggerTests.cs — Updates LogOutput_UsesAbbreviatedLogLevelLabels assertion from StartsWith to Contains since the timestamp now precedes the level label.

How was this tested?

• Integration Tests
• Unit Tests

Sample Request(s)

No REST/GraphQL/CLI request changes — output-only behavioral change visible when running dab start.

[Copilot]

Pull request overview

This PR aims to make console logs easier to correlate by prepending an ISO 8601 UTC timestamp (millisecond precision) to console output emitted by both the Service host and the CLI custom logger.

Changes:

• Updated Service logging to use the console “simple” formatter with UTC timestamp settings (including MCP stdio stderr routing for the startup logger factory).
• Updated the CLI custom console logger to prepend a UTC timestamp before the abbreviated log level label.
• Adjusted CLI unit tests for the new timestamp-prefixed output (but the updated assertion is now too permissive).

Reviewed changes

Copilot reviewed 3 out of 3 changed files in this pull request and generated 4 comments.

File	Description
src/Service/Program.cs	Switches console logging to include UTC timestamps; MCP stdio path continues to keep stdout clean.
src/Cli/CustomLoggerProvider.cs	Prepends UTC timestamps to CLI log prefixes for both standard and MCP stdio modes.
src/Cli.Tests/CustomLoggerTests.cs	Updates assertions to account for timestamps in log output.

[Copilot]

Copilot

Issue #3708 requires every DAB console log entry to begin with an ISO 8601 UTC timestamp with millisecond precision. The current change only timestamps messages emitted through ILogger....

Done in d7fbf1b.

Added BootstrapLogger (src/Config/Utilities/BootstrapLogger.cs) — a single ILogger implementation that is the only place a timestamp is formatted (yyyy-MM-dd'T'HH:mm:ss.fff'Z', CultureInfo.InvariantCulture). The engine/CLI console formatters now reuse that same constant, so all three paths emit identical prefixes.

Migrated diagnostics:

• Program.Main() URL validation, Program.StartEngine() startup failures, and the https-redirect notice
• RuntimeConfigProvider.ValidateConfig() hot-reload messages
• ConfigFileWatcher.OnConfigFileChange()
• FileSystemRuntimeConfigLoader watcher/reload errors (uses the injected ILogger<FileSystemRuntimeConfigLoader> when available, bootstrap logger otherwise)
• FileUtilities.ComputeHash() retry diagnostics
• Startup.RefreshGraphQLSchema() / EvictGraphQLSchema() — these run after DI, so they use ILogger<Startup>
• SqlPaginationUtil.ResolveRequestScheme() / ResolveRequestHost()

Against the acceptance criteria:

1. Every remaining production diagnostic is emitted through a logger, so all entries start with yyyy-MM-ddTHH:mm:ss.fffZ.
2. Formatting is UTC and culture-invariant, in one place.
3. BootstrapLogger.WriteAllOutputToStandardError is set by both the engine (StartEngine MCP branch) and the CLI (--mcp-stdio), so nothing bootstrap-emitted can reach stdout; error/critical entries already go to stderr otherwise.
4. No extra console provider: the web host configures the existing simple-console formatter options via logging.Services.Configure, and the MCP startup factory registers exactly one provider.
5. dab app-name encode/decode output and the auto-config simulation table remain plain Console.Write/WriteLine.

Also added BootstrapLoggerTests covering the timestamp prefix, stream routing, and the stderr-only mode.

[Copilot]

Copilot

The current test validates timestamps only for the normal CLI logger path. The MCP tests would still pass if MCP timestamp generation were removed, and neither service logging configurati...

Done in 0a43f4c.

Writing the requested CreateHostBuilder test surfaced a real bug: the web-host path had no timestamps at all. Host.CreateDefaultBuilder() registers the console provider with ConsoleLoggerOptions.FormatterName unset, and in that state the provider ignores SimpleConsoleFormatterOptions and derives its formatter options from ConsoleLoggerOptions' own obsolete properties — so Services.Configure<SimpleConsoleFormatterOptions>(...) was silently discarded. Fixed by also setting FormatterName = ConsoleFormatterNames.Simple. I extracted the ConfigureLogging body into Program.ConfigureHostLogging(ILoggingBuilder, bool) so the pipeline can be exercised directly; CreateHostBuilder just delegates to it.

Shared timestamp assertion (in both test projects) verifies the prefix: parses with TryParseExact under CultureInfo.InvariantCulture to DateTimeKind.Utc, ends in Z, has exactly three fractional-second digits (the Z immediately after the third digit rules out extra precision), and falls within the UTC window captured immediately before/after the log call.

New/updated coverage:

• src/Cli.Tests/CustomLoggerTests.cs — standard path now asserts the timestamp is followed immediately by the level label; the MCP CLI-override and config-override tests assert every emitted entry is timestamped via CollectionAssert.AreEqual on the timestamp-stripped lines, so removing the MCP timestamp (or leaking a filtered entry) fails. Existing severity-label, filtering, message-content and stdout/stderr assertions are retained.
• src/Service.Tests/UnitTests/ConsoleLogTimestampTests.cs — GetLoggerFactoryForLogLevel() in normal (stdout) and stdio (stderr-only, stdout clean) modes; ConfigureHostLogging() emitting each event exactly once plus a check that exactly one ConsoleLoggerProvider descriptor is registered; stdio mode writing nothing to the console; and the migrated diagnostic paths (SqlPaginationUtil.ResolveRequestScheme/ResolveRequestHost invalid-forwarded-header warnings, FileUtilities.ComputeHash missing-file warning, bootstrap stderr routing).

Mutation-checked: deleting the MCP timestamp fails both MCP tests, and reverting the FormatterName fix fails ConfigureHostLogging_NormalMode_EmitsEachEntryOnceWithTimestamp. Solution builds clean, dotnet format --verify-no-changes passes, and CodeQL reports no alerts.

[aaronburtle]

Copilot

The service console paths still do not satisfy the culture-invariant timestamp requirement.

The formatter configuration at:

• host logging
• stdio logger factory
• normal logger factory

uses SimpleConsoleFormatterOptions.TimestampFormat. However, SimpleConsoleFormatter calls DateTimeOffset.ToString(timestampFormat) using CurrentCulture; UseUtcTimestamp controls the timezone but not the calendar or formatting culture.

I reproduced the actual .NET 10 formatter output with the current format:

• en-US: 2026-08-29T05:29:44.082Z
• ar-SA: 1448-03-16T05:29:44.103Z
• th-TH: 2569-08-29T05:29:44.113Z
• fa-IR: 1405-06-07T05:29:44.117Z

Therefore, these paths do not consistently emit the required Gregorian yyyy-MM-ddTHH:mm:ss.fffZ prefix. This differs from BootstrapLogger and the CLI logger, which explicitly pass CultureInfo.InvariantCulture.

Please use a console formatter that formats the UTC timestamp explicitly with CultureInfo.InvariantCulture. Please do not change the process-wide culture as a workaround, and preserve the current guarantees around MCP stdout isolation and single-provider registration.

Please also add regression coverage that runs both GetLoggerFactoryForLogLevel() and the host logging path under at least one non-Gregorian culture such as ar-SA or th-TH, verifies the exact UTC prefix, and restores culture state safely after each test.

[aaronburtle]

Copilot

The direct-console inventory is still incomplete. Two log-like diagnostics remain in the production Aspire executable:

• SQL Server container diagnostic
• PostgreSQL container diagnostic

Both use bare Console.WriteLine() and therefore remain untimestamped. These are operational diagnostics, unlike intentional CLI command results such as encoded values or simulation tables.

Please route these messages through the centralized timestamped logging path, or explicitly narrow and document the PR's scope if Aspire AppHost output is intentionally excluded from the “all console log entries” contract. If it remains in scope, please add coverage confirming that these diagnostics use the same invariant UTC millisecond prefix.

[Copilot]

Copilot

The service console paths still do not satisfy the culture-invariant timestamp requirement.
...

Fixed in 7d24499.

Reproduced first — with the previous SimpleConsoleFormatterOptions.TimestampFormat configuration on .NET 10:

en-US   : 2026-08-29T05:40:10.447Z info: Cat[0]
ar-SA   : 1448-03-16T05:40:10.647Z info: Cat[0]
th-TH   : 2569-08-29T05:40:10.679Z info: Cat[0]
fa-IR   : 1405-06-07T05:40:10.693Z info: Cat[0]

Added UtcTimestampConsoleFormatter (src/Service/Telemetry/UtcTimestampConsoleFormatter.cs), a ConsoleFormatter that reproduces the "simple" formatter's layout (level colors, category[eventId] header, indented/multi-line message and exception padding, scopes, single-line) but writes the timestamp itself via DateTime.UtcNow.ToString(BootstrapLogger.UTC_TIMESTAMP_FORMAT, CultureInfo.InvariantCulture) rather than through TimestampFormat. It reuses the same shared format constant as BootstrapLogger and the CLI logger, so all three paths remain identical. Process-wide culture is untouched.

AddUtcTimestampConsoleFormatter() registers only the formatter (via TryAddEnumerable) and sets ConsoleLoggerOptions.FormatterName; it never adds a provider, so all three sites keep their existing provider guarantees:

• host logging still reuses the provider from Host.CreateDefaultBuilder() — ConfigureHostLogging_NormalMode_RegistersSingleConsoleProvider and the emit-exactly-once test stay green
• the stdio factory keeps ClearProviders() + one AddConsole() + LogToStandardErrorThreshold = Trace via Services.Configure, so stdout stays reserved for JSON-RPC

Regression coverage in ConsoleLogTimestampTests: GetLoggerFactoryForLogLevel (normal and stdio) and ConfigureHostLogging under both ar-SA and th-TH, plus BootstrapLogger. RunUnderCulture restores CurrentCulture/CurrentUICulture in a finally, and AssertCultureIsNonGregorian fails the test if the runtime is in globalization-invariant mode so the assertions can't pass vacuously. Mutation-checked: swapping InvariantCulture for CurrentCulture in the formatter fails exactly the 6 new formatter-based culture rows.

Solution builds with 0 warnings and dotnet format --verify-no-changes passes. Note: codeql_checker timed out on this run rather than reporting alerts.

[Copilot]

Copilot

The direct-console inventory is still incomplete. Two log-like diagnostics remain in the production Aspire executable:
...

Kept in scope and fixed in 5a7e038.

Both AppHost diagnostics now go through BootstrapLogger.Instance.LogInformation(...), so they carry the same invariant UTC millisecond prefix as the engine and CLI.

One wrinkle worth noting: the Aspire SDK rewrites ProjectReference into Projects.* metadata with ReferenceOutputAssembly=false, so the existing reference to the Service project does not give AppHost an assembly reference — BootstrapLogger was unresolvable and the first build failed. I added a second reference to the Config project marked IsAspireProjectResource="false" so it resolves as a plain library without becoming an orchestrated resource. The Service reference is untouched and Projects.Azure_DataApiBuilder_Service still resolves.

For coverage: AppHost is top-level statements in an executable that builds and runs a distributed application, so invoking it from a test isn't practical. Instead of asserting the prefix a fourth time, I added ProductionSources_DoNotWriteDiagnosticsDirectlyToConsole, which scans every .cs file across the eight production projects (including Aspire.AppHost) for Console.Write* / Console.Error.Write* / Console.Out.Write* and fails with file+line on any hit. Comment lines are skipped, and intentional command output is allow-listed with a justification:

• Cli/CustomLoggerProvider.cs — the CLI console logger itself
• Cli/Commands/AppNameOptions.cs — encoded/decoded app name
• Cli/ConfigGenerator.cs — auto-entities simulation table

That is the load-bearing link: the BootstrapLogger tests (including the ar-SA/th-TH rows) prove the prefix, and the guard proves AppHost has no path that bypasses it. It also addresses the root cause of this being the third incomplete-inventory round — a new bare console write anywhere in production now fails a test rather than waiting for review. Mutation-checked: reverting either AppHost line fails the guard with the exact location.

One change you should look at, outside what you asked for. Line 58 was if (!string.IsNullOrEmpty(databaseConnectionString)) guarding the message "No connection string provided, starting a local PostgreSQL container." — inverted relative to the identical mssql branch at line 18. As written it started a container only when a connection string was supplied (then ignored it, since postgresDB was non-null), and used an empty connection string when none was given. I flipped it to match mssql, because I was otherwise certifying a diagnostic that states the opposite of its own condition. It is a behavior change to the AppHost dev tool and trivially revertable if you'd rather handle it separately.

Solution builds with 0 warnings, dotnet format --verify-no-changes passes, 24 service timestamp tests and 8 CLI logger tests pass. codeql_checker timed out on this run rather than reporting alerts, so this commit is unscanned.

[aaronburtle]

Copilot

The custom formatter needs to preserve BufferedLogRecord semantics.

In .NET 10, ConsoleLogger.LogRecords() passes buffered entries as LogEntry<BufferedLogRecord>. The original event timestamp and formatted exception are stored in the BufferedLogRecord state; LogEntry.Exception is null. This implementation always uses DateTime.UtcNow and only emits logEntry.Exception, so a buffered entry is timestamped at flush time and its exception is silently dropped.

I reproduced both behaviors by invoking this formatter with the same LogEntry<BufferedLogRecord> shape used by ConsoleLogger:

• the configured record timestamp was replaced with the current time;
• the buffered exception was absent from the output.

The built-in SimpleConsoleFormatter special-cases BufferedLogRecord and reads its Timestamp, FormattedMessage, and Exception. Please preserve that behavior here and add a focused regression test covering the original timestamp and buffered exception.

[aaronburtle]

Copilot

Referencing the full Config project just to reuse BootstrapLogger introduces new assembly-version conflicts in AppHost.

Before this reference was added, AppHost built without warnings. At the current head, both the AppHost build and full solution build report MSB3277 conflicts for:

• Azure.Core 1.47.3 versus 1.50.0, with 1.47.3 selected;
• Azure.Identity 1.15.0 versus 1.17.1, with 1.15.0 selected.

This couples AppHost to Config's Key Vault/Azure dependency graph and causes older Azure assemblies to win dependency resolution for the executable. Please avoid taking the full Config dependency for this small logging utility—for example, move the dependency-light timestamp/bootstrap logging functionality into an appropriate shared project, or use an AppHost-local logging path—and restore a warning-free AppHost build.

[aaronburtle]

Copilot

1. The direct-console source scanner omits the Product project, so its “production sources” coverage is not exhaustive.
2. A focused test for the corrected PostgreSQL empty/non-empty connection-string behavior would be worthwhile, especially because that change is unrelated to the timestamp feature.

[Copilot]

Copilot

The custom formatter needs to preserve BufferedLogRecord semantics.
...

Fixed in 360c058.

Confirmed against the .NET 10 SimpleConsoleFormatter source — it branches on logEntry.State is BufferedLogRecord and passes bufferedRecord.FormattedMessage, LogLevel, EventId.Id, Exception (already a preformatted string), Timestamp, and a null scopeProvider. My implementation had none of that.

Restructured Write to mirror it: the buffered branch now reads the record's own values and passes bufferedRecord.Timestamp through to a shared WriteInternal(...), which renders it as stamp.UtcDateTime.ToString(UTC_TIMESTAMP_FORMAT, InvariantCulture). The live path passes DateTimeOffset.UtcNow instead. Both branches share one write routine, so the timestamp/level/category/exception layout can't diverge again. .UtcDateTime also means a buffered record captured with a non-zero offset is normalized rather than emitted with a local wall-clock time under a Z suffix.

Tests:

• Formatter_BufferedLogRecord_UsesOriginalTimestamp — builds the same LogEntry<BufferedLogRecord> shape ConsoleLogger uses (null formatter, null LogEntry.Exception) with a fixed 2021 instant, asserting the output starts with 2021-03-04T05:06:07.089Z. Runs under en-US and th-TH so it also pins the invariant calendar on this path.
• Formatter_BufferedLogRecord_WritesBufferedException — asserts the buffered exception text is present.

Mutation-checked: removing the buffered branch fails all three rows.

One extra fix. Comparing against the built-in surfaced a second divergence I'd introduced: it runs message, exception, and category through ConsoleControlCharacterSanitizer, and mine didn't. Since log messages carry untrusted values (headers, entity names, config paths), that dropped terminal-escape-injection protection — a security regression versus the formatter I replaced, not a cosmetic one. WriteInternal now escapes C0/DEL/C1 as \uXXXX while preserving tab/CR/LF, matching the built-in's ranges. Covered by Formatter_ControlCharactersInMessage_AreEscaped, which fails if the sanitization is removed. The runtime's internal type isn't public, hence the local implementation.

Solution builds with 0 warnings, dotnet format --verify-no-changes passes, 28 service timestamp tests and 8 CLI logger tests pass. codeql_checker timed out again rather than reporting alerts, so this commit is unscanned.

[Copilot]

Copilot

Referencing the full Config project just to reuse BootstrapLogger introduces new assembly-version conflicts in AppHost.
...

Fixed in 59dd5a1 by removing the Config reference entirely.

BootstrapLogger moved from src/Config/Utilities/ to src/Product/ (namespace Azure.DataApiBuilder.Product), and AppHost now references Azure.DataApiBuilder.Product.csproj instead of Config. Product had no dependencies at all; it now takes exactly one, Microsoft.Extensions.Logging.Abstractions, so AppHost gets the shared logger without Config's Key Vault/Azure graph. Config already referenced Product, so every existing consumer (Config, Core, Service, Cli) still resolves the type transitively — the only change at those call sites is the using.

Verification that the coupling is actually gone: the first build after switching the reference failed with CS0234: The type or namespace name 'Config' does not exist in the namespace 'Azure.DataApiBuilder' in AppHost.cs, confirming Config is no longer on AppHost's compile path rather than merely being deprioritized. Azure.Core.dll and Azure.Identity.dll are no longer present in the AppHost output directory. Full solution builds with 0 warnings and dotnet format --verify-no-changes passes.

One thing I should flag: I was not able to reproduce the MSB3277 warnings locally, either before or after this change — dotnet build src/Aspire.AppHost/Aspire.AppHost.csproj -v n --no-incremental and the full solution build both reported zero warnings at the previous head in this sandbox. I suspect a NuGet resolution difference in this environment rather than the warning being absent. So I treated your report as authoritative and fixed the root cause (the dependency edge) rather than chasing the specific binding conflict, which means I've verified the reference is gone but haven't been able to directly observe the warnings disappear. Worth a glance at your end to confirm.

Note: codeql_checker timed out again on this run rather than reporting alerts, so this commit is unscanned.

Copilot

1. The direct-console source scanner omits the Product project, so its “production sources” coverage is not exhaustive.
   ...

Both addressed in 59dd5a1.

1. Product missing from the scanner. Rather than just appending "Product" to the hard-coded array, I removed the hard-coded array — that list was the reason the gap existed, and adding one entry would leave the next new project equally invisible. ProductionSources_DoNotWriteDiagnosticsDirectlyToConsole now discovers production projects by enumerating src/ for directories containing a .csproj, excluding *.Tests. A CollectionAssert.AreEqual on the discovered names pins the current set (Aspire.AppHost, Auth, Azure.DataApiBuilder.Mcp, Cli, Config, Core, Product, Service, Service.GraphQLBuilder), so the guard can't silently pass by scanning nothing, and adding a project fails the test until its console writes have been reviewed. Product scans clean — no violations, nothing new to allow-list.

2. PostgreSQL connection-string behavior. Added AppHost_StartsLocalDatabaseContainerOnlyWhenNoConnectionStringProvided. AppHost is top-level statements in an executable that builds and runs a distributed application, and exercising the real branch would mean taking an Aspire.Hosting dependency in Service.Tests, so this asserts at the source level, consistent with the existing guard test in the same file: it locates every "No connection string provided" diagnostic, walks back to the nearest preceding line of code, and requires it to be exactly if (string.IsNullOrEmpty(databaseConnectionString)). It also asserts there are exactly two such diagnostics, so neither the mssql nor the postgresql branch can drop out of coverage by deleting its message. That pins the specific defect — a diagnostic contradicting its own condition — which is what the inversion actually was.

To be clear about its limits: this verifies the guard/diagnostic pairing, not the downstream postgresDB is null wiring, so it's a narrower assertion than a true behavioral test would give you.

Mutation-checked both: re-inverting the postgres guard fails the new test, and adding a bare Console.WriteLine to src/Product/ProductInfo.cs fails the scanner with the exact file and line. 29 service timestamp tests and 8 CLI logger tests pass, solution builds with 0 warnings, dotnet format --verify-no-changes passes.

Note: codeql_checker timed out on this run rather than reporting alerts.

[aaronburtle]

LGTM!