Introduce IBufferedLogRecordMetadata

src/libraries/Microsoft.Extensions.Logging.Abstractions/src/IBufferedLogRecordMetadata.cs

@@ -0,0 +1,39 @@
+// 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
+{
+    /// <summary>
+    /// Holds metadata for a buffered log record.
+    /// </summary>
+    /// <remarks>
+    /// If the logging infrastructure decides to buffer log records in memory, it will ensure that the
+    /// <c>TState</c> value delivered to logging providers implements this interface. The logging providers
+    /// can then use the metadata to augment the log records they emit.
+    /// </remarks>    
+    public interface IBufferedLogRecordMetadata
+    {
+        /// <summary>
+        /// Gets the time when the log record was recorded.
+        /// </summary>
+        public DateTimeOffset? CreationTime { get; }
+
+        /// <summary>
+        /// Gets the ID of the thread that created the log record.
+        /// </summary>
+        public int? ManagedThreadId { get; }
+
+        /// <summary>
+        /// Gets the ID of the span in effect when the log record was created.
+        /// </summary>
+        public ActivitySpanId? SpanId { get; }
+
+        /// <summary>
+        /// Gets the ID of the trace in effect when the log record was created.
+        /// </summary>
+        public ActivityTraceId? TraceId { get; }
+    }
+}

src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs

@@ -34,14 +34,27 @@ public override void Write<TState>(in LogEntry<TState> logEntry, IExternalScopeP
                 return;
             }
 
+            DateTimeOffset stamp;
+            if (logEntry.State is IBufferedLogRecordMetadata metadata)
+            {
+
+                // TODO: should this be adjusted between UTC and local time
+                stamp = FormatterOptions.UseUtcTimestamp ? metadata.CreationTime : 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<KeyValuePair<string, object>>);
+                logEntry.State != null, logEntry.State?.ToString(), logEntry.State as IReadOnlyCollection<KeyValuePair<string, object>>, stamp);
         }
 
         private void WriteInternal(IExternalScopeProvider? scopeProvider, TextWriter textWriter, string message, LogLevel logLevel,
-            string category, int eventId, Exception? exception, bool hasState, string? stateMessage, IReadOnlyCollection<KeyValuePair<string, object>>? stateProperties)
+            string category, int eventId, Exception? exception, bool hasState, string? stateMessage, IReadOnlyCollection<KeyValuePair<string, object>>? stateProperties,
+            DateTimeOffset stamp)
         {
             const int DefaultBufferSize = 1024;
             using (var output = new PooledByteBufferWriter(DefaultBufferSize))
@@ -52,8 +65,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<object>.EventId), eventId);
                     writer.WriteString(nameof(LogEntry<object>.LogLevel), GetLogLevelString(logLevel));

src/libraries/Microsoft.Extensions.Logging.Console/src/SimpleConsoleFormatter.cs

@@ -52,13 +52,23 @@ public override void Write<TState>(in LogEntry<TState> logEntry, IExternalScopeP
                 return;
             }
 
+            DateTimeOffset stamp;
+            if (logEntry.State is IBufferedLogRecordMetadata metadata)
+            {
+                stamp = FormatterOptions.UseUtcTimestamp ? metadata.CreationTime : 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 +77,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)
             {

src/libraries/Microsoft.Extensions.Logging.Console/src/SystemdConsoleFormatter.cs

@@ -42,13 +42,23 @@ public override void Write<TState>(in LogEntry<TState> logEntry, IExternalScopeP
                 return;
             }
 
+            DateTimeOffset stamp;
+            if (logEntry.State is IBufferedLogRecordMetadata metadata)
+            {
+                stamp = FormatterOptions.UseUtcTimestamp ? metadata.CreationTime : 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 '<pri>message' format.
             // newline characters are treated as message delimiters, so we must replace them.
@@ -64,8 +74,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

src/libraries/Microsoft.Extensions.Logging.Console/tests/Microsoft.Extensions.Logging.Console.Tests/ConsoleLoggerTest.cs

@@ -551,6 +551,67 @@ public void Log_LogsCorrectTimestamp(ConsoleLoggerFormat format, LogLevel level)
             }
         }
 
+        class BufferedLogRecord : IBufferedLogRecordMetadata
+        {
+            private readonly string _state;
+            private readonly DateTimeOffset _creationTime;;
+
+            public BufferedLogRecord(string state, DateTimeOffset creationTime)
+            {
+                _state = state;
+                _creationTime = creationTime;
+            }
+
+            public override string ToString() => _state;
+
+            public DateTimeOffset CreationTime { get { return _creationTime; } }
+            public int ThreadId => null;
+            public ActivitySpanId => null,
+            public ActivityTraceId => null,
+        }
+
+        [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)