diff --git a/src/libraries/Microsoft.Extensions.Logging.Abstractions/ref/Microsoft.Extensions.Logging.Abstractions.cs b/src/libraries/Microsoft.Extensions.Logging.Abstractions/ref/Microsoft.Extensions.Logging.Abstractions.cs index eac0fb38df2c4d..36f1188566a837 100644 --- a/src/libraries/Microsoft.Extensions.Logging.Abstractions/ref/Microsoft.Extensions.Logging.Abstractions.cs +++ b/src/libraries/Microsoft.Extensions.Logging.Abstractions/ref/Microsoft.Extensions.Logging.Abstractions.cs @@ -202,4 +202,15 @@ public NullLogger() { } public bool IsEnabled(Microsoft.Extensions.Logging.LogLevel logLevel) { throw null; } public void Log(Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.Extensions.Logging.EventId eventId, TState state, System.Exception? exception, System.Func formatter) { } } + public partial struct BufferedLogRecordMetadata + { + public System.DateTimeOffset CreationTime { get; set; } + public int? ManagedThreadId { get; set; } + public System.Diagnostics.ActivitySpanId? SpanId { get; set; } + public System.Diagnostics.ActivityTraceId? TraceId { get; set; } + } + public partial interface IBufferedLogRecord + { + public void ExtractMetadata(out BufferedLogRecordMetadata metadata); + } } diff --git a/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/BufferedLogRecordMetadata.cs b/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/BufferedLogRecordMetadata.cs new file mode 100644 index 00000000000000..74a2cd21fc5a9e --- /dev/null +++ b/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/BufferedLogRecordMetadata.cs @@ -0,0 +1,34 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Diagnostics; + +namespace Microsoft.Extensions.Logging +{ + /// + /// Holds metadata for a buffered log record. + /// + public struct BufferedLogRecordMetadata + { + /// + /// Gets the time when the log record was recorded. + /// + public DateTimeOffset CreationTime { get; set; } + + /// + /// Gets the ID of the thread that created the log record. + /// + public int? ManagedThreadId { get; set; } + + /// + /// Gets the ID of the span in effect when the log record was created. + /// + public ActivitySpanId? SpanId { get; set; } + + /// + /// Gets the ID of the trace in effect when the log record was created. + /// + public ActivityTraceId? TraceId { get; set; } + } +} diff --git a/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/IBufferedLogRecord.cs b/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/IBufferedLogRecord.cs new file mode 100644 index 00000000000000..719c82a1275b1e --- /dev/null +++ b/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/IBufferedLogRecord.cs @@ -0,0 +1,21 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +namespace Microsoft.Extensions.Logging +{ + /// + /// A buffered log record. + /// + /// + /// If the logging infrastructure decides to buffer log records in memory, it will ensure that the + /// TState value delivered to logging providers implements this interface. The logging providers + /// can then use the metadata to augment the log records they emit. + /// + public interface IBufferedLogRecord + { + /// + /// Extracts the metadata for the buffered log record. + /// + public void ExtractMetadata(out BufferedLogRecordMetadata metadata); + } +} diff --git a/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/Microsoft.Extensions.Logging.Abstractions.csproj b/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/Microsoft.Extensions.Logging.Abstractions.csproj index 28d8bcddd18515..54d1a53470341b 100644 --- a/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/Microsoft.Extensions.Logging.Abstractions.csproj +++ b/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/Microsoft.Extensions.Logging.Abstractions.csproj @@ -51,6 +51,7 @@ Microsoft.Extensions.Logging.Abstractions.NullLogger + diff --git a/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs b/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs index 945e6ebb23584e..d6923d4eee99eb 100644 --- a/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs +++ b/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs @@ -34,14 +34,26 @@ public override void Write(in LogEntry logEntry, IExternalScopeP return; } + DateTimeOffset stamp; + if (logEntry.State is IBufferedLogRecord bufferedLogRecord) + { + bufferedLogRecord.ExtractMetadata(out var metadata); + stamp = FormatterOptions.UseUtcTimestamp ? metadata.CreationTime.ToUniversalTime() : metadata.CreationTime.ToLocalTime(); + } + else + { + stamp = FormatterOptions.UseUtcTimestamp ? DateTimeOffset.UtcNow : DateTimeOffset.Now; + } + // We extract most of the work into a non-generic method to save code size. If this was left in the generic // method, we'd get generic specialization for all TState parameters, but that's unnecessary. WriteInternal(scopeProvider, textWriter, message, logEntry.LogLevel, logEntry.Category, logEntry.EventId.Id, logEntry.Exception, - logEntry.State != null, logEntry.State?.ToString(), logEntry.State as IReadOnlyCollection>); + logEntry.State != null, logEntry.State?.ToString(), logEntry.State as IReadOnlyCollection>, stamp); } private void WriteInternal(IExternalScopeProvider? scopeProvider, TextWriter textWriter, string message, LogLevel logLevel, - string category, int eventId, Exception? exception, bool hasState, string? stateMessage, IReadOnlyCollection>? stateProperties) + string category, int eventId, Exception? exception, bool hasState, string? stateMessage, IReadOnlyCollection>? stateProperties, + DateTimeOffset stamp) { const int DefaultBufferSize = 1024; using (var output = new PooledByteBufferWriter(DefaultBufferSize)) @@ -52,8 +64,7 @@ private void WriteInternal(IExternalScopeProvider? scopeProvider, TextWriter tex var timestampFormat = FormatterOptions.TimestampFormat; if (timestampFormat != null) { - DateTimeOffset dateTimeOffset = FormatterOptions.UseUtcTimestamp ? DateTimeOffset.UtcNow : DateTimeOffset.Now; - writer.WriteString("Timestamp", dateTimeOffset.ToString(timestampFormat)); + writer.WriteString("Timestamp", stamp.ToString(timestampFormat)); } writer.WriteNumber(nameof(LogEntry.EventId), eventId); writer.WriteString(nameof(LogEntry.LogLevel), GetLogLevelString(logLevel)); diff --git a/src/libraries/Microsoft.Extensions.Logging.Console/src/SimpleConsoleFormatter.cs b/src/libraries/Microsoft.Extensions.Logging.Console/src/SimpleConsoleFormatter.cs index 79cacb9b3baafa..a37c6c84a9aafa 100644 --- a/src/libraries/Microsoft.Extensions.Logging.Console/src/SimpleConsoleFormatter.cs +++ b/src/libraries/Microsoft.Extensions.Logging.Console/src/SimpleConsoleFormatter.cs @@ -52,13 +52,24 @@ public override void Write(in LogEntry logEntry, IExternalScopeP return; } + DateTimeOffset stamp; + if (logEntry.State is IBufferedLogRecord bufferedLogRecord) + { + bufferedLogRecord.ExtractMetadata(out var metadata); + stamp = FormatterOptions.UseUtcTimestamp ? metadata.CreationTime.ToUniversalTime() : metadata.CreationTime.ToLocalTime(); + } + else + { + stamp = GetCurrentDateTime(); + } + // We extract most of the work into a non-generic method to save code size. If this was left in the generic // method, we'd get generic specialization for all TState parameters, but that's unnecessary. - WriteInternal(scopeProvider, textWriter, message, logEntry.LogLevel, logEntry.EventId.Id, logEntry.Exception, logEntry.Category); + WriteInternal(scopeProvider, textWriter, message, logEntry.LogLevel, logEntry.EventId.Id, logEntry.Exception, logEntry.Category, stamp); } private void WriteInternal(IExternalScopeProvider? scopeProvider, TextWriter textWriter, string message, LogLevel logLevel, - int eventId, Exception? exception, string category) + int eventId, Exception? exception, string category, DateTimeOffset stamp) { ConsoleColors logLevelColors = GetLogLevelConsoleColors(logLevel); string logLevelString = GetLogLevelString(logLevel); @@ -67,8 +78,7 @@ private void WriteInternal(IExternalScopeProvider? scopeProvider, TextWriter tex string? timestampFormat = FormatterOptions.TimestampFormat; if (timestampFormat != null) { - DateTimeOffset dateTimeOffset = GetCurrentDateTime(); - timestamp = dateTimeOffset.ToString(timestampFormat); + timestamp = stamp.ToString(timestampFormat); } if (timestamp != null) { diff --git a/src/libraries/Microsoft.Extensions.Logging.Console/src/SystemdConsoleFormatter.cs b/src/libraries/Microsoft.Extensions.Logging.Console/src/SystemdConsoleFormatter.cs index 2d306fee1d0a4b..bf66722b5d385d 100644 --- a/src/libraries/Microsoft.Extensions.Logging.Console/src/SystemdConsoleFormatter.cs +++ b/src/libraries/Microsoft.Extensions.Logging.Console/src/SystemdConsoleFormatter.cs @@ -42,13 +42,24 @@ public override void Write(in LogEntry logEntry, IExternalScopeP return; } + DateTimeOffset stamp; + if (logEntry.State is IBufferedLogRecord bufferedLogRecord) + { + bufferedLogRecord.ExtractMetadata(out var metadata); + stamp = FormatterOptions.UseUtcTimestamp ? metadata.CreationTime.ToUniversalTime() : metadata.CreationTime.ToLocalTime(); + } + else + { + stamp = GetCurrentDateTime(); + } + // We extract most of the work into a non-generic method to save code size. If this was left in the generic // method, we'd get generic specialization for all TState parameters, but that's unnecessary. - WriteInternal(scopeProvider, textWriter, message, logEntry.LogLevel, logEntry.Category, logEntry.EventId.Id, logEntry.Exception); + WriteInternal(scopeProvider, textWriter, message, logEntry.LogLevel, logEntry.Category, logEntry.EventId.Id, logEntry.Exception, stamp); } private void WriteInternal(IExternalScopeProvider? scopeProvider, TextWriter textWriter, string message, LogLevel logLevel, string category, - int eventId, Exception? exception) + int eventId, Exception? exception, DateTimeOffset stamp) { // systemd reads messages from standard out line-by-line in a 'message' format. // newline characters are treated as message delimiters, so we must replace them. @@ -64,8 +75,7 @@ private void WriteInternal(IExternalScopeProvider? scopeProvider, TextWriter tex string? timestampFormat = FormatterOptions.TimestampFormat; if (timestampFormat != null) { - DateTimeOffset dateTimeOffset = GetCurrentDateTime(); - textWriter.Write(dateTimeOffset.ToString(timestampFormat)); + textWriter.Write(stamp.ToString(timestampFormat)); } // category and event id diff --git a/src/libraries/Microsoft.Extensions.Logging.Console/tests/Microsoft.Extensions.Logging.Console.Tests/ConsoleLoggerTest.cs b/src/libraries/Microsoft.Extensions.Logging.Console/tests/Microsoft.Extensions.Logging.Console.Tests/ConsoleLoggerTest.cs index 5a71dad69bbdbd..05754e804eec9a 100644 --- a/src/libraries/Microsoft.Extensions.Logging.Console/tests/Microsoft.Extensions.Logging.Console.Tests/ConsoleLoggerTest.cs +++ b/src/libraries/Microsoft.Extensions.Logging.Console/tests/Microsoft.Extensions.Logging.Console.Tests/ConsoleLoggerTest.cs @@ -551,6 +551,68 @@ public void Log_LogsCorrectTimestamp(ConsoleLoggerFormat format, LogLevel level) } } + class BufferedLogRecord : IBufferedLogRecord + { + private readonly string _state; + private readonly DateTimeOffset _creationTime;; + + public BufferedLogRecord(string state, DateTimeOffset creationTime) + { + _state = state; + _creationTime = creationTime; + } + + public override string ToString() => _state; + + public void ExtractMetadata(out LogRecordMetadata metadata) + { + metadata = new LogRecordMetadata(); + metadata.CreationTime = _creationTime; + } + } + + [ConditionalTheory(typeof(PlatformDetection), nameof(PlatformDetection.IsThreadingSupported))] + [MemberData(nameof(FormatsAndLevels))] + public void Log_LogsCorrectOverrideTimestamp(ConsoleLoggerFormat format, LogLevel level) + { + // Arrange + using var t = SetUp(new ConsoleLoggerOptions { TimestampFormat = "yyyy-MM-ddTHH:mm:sszz ", Format = format, UseUtcTimestamp = false }); + var levelPrefix = t.GetLevelPrefix(level); + var logger = t.Logger; + var sink = t.Sink; + var ex = new Exception("Exception message" + Environment.NewLine + "with a second line"); + var now = new DateTimeOffset(TimeSpan.FromTicks(12345)); + + // Act + logger.Log(level, 0, new BufferedLogRecord(_state, now), ex, _defaultFormatter); + + // Assert + switch (format) + { + case ConsoleLoggerFormat.Default: + { + Assert.Equal(3, sink.Writes.Count); + Assert.StartsWith(levelPrefix, sink.Writes[1].Message); + Assert.Matches(@"^\d{4}\D\d{2}\D\d{2}\D\d{2}\D\d{2}\D\d{2}\D\d{2}\s$", sink.Writes[0].Message); + var parsedDateTime = DateTimeOffset.Parse(sink.Writes[0].Message.Trim()); + Assert.Equal(now, parsedDateTime); + } + break; + case ConsoleLoggerFormat.Systemd: + { + Assert.Single(sink.Writes); + Assert.StartsWith(levelPrefix, sink.Writes[0].Message); + var regexMatch = Regex.Match(sink.Writes[0].Message, @"^<\d>(\d{4}\D\d{2}\D\d{2}\D\d{2}\D\d{2}\D\d{2}\D\d{2})\s[^\s]"); + Assert.True(regexMatch.Success); + var parsedDateTime = DateTimeOffset.Parse(regexMatch.Groups[1].Value); + Assert.Equal(now, parsedDateTime); + } + break; + default: + throw new ArgumentOutOfRangeException(nameof(format)); + } + } + [ConditionalTheory(typeof(PlatformDetection), nameof(PlatformDetection.IsThreadingSupported))] [MemberData(nameof(FormatsAndLevels))] public void WriteCore_LogsCorrectTimestampInUtc(ConsoleLoggerFormat format, LogLevel level)