Introduce IBufferedLogRecordMetadata

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<TState>(Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.Extensions.Logging.EventId eventId, TState state, System.Exception? exception, System.Func<TState, System.Exception?, string> 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);
+    }
 }

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
+{
+    /// <summary>
+    /// Holds metadata for a buffered log record.
+    /// </summary>
+    public struct BufferedLogRecordMetadata
+    {
+        /// <summary>
+        /// Gets the time when the log record was recorded.
+        /// </summary>
+        public DateTimeOffset CreationTime { get; set; }
+
+        /// <summary>
+        /// Gets the ID of the thread that created the log record.
+        /// </summary>
+        public int? ManagedThreadId { get; set; }
+
+        /// <summary>
+        /// Gets the ID of the span in effect when the log record was created.
+        /// </summary>
+        public ActivitySpanId? SpanId { get; set; }
+
+        /// <summary>
+        /// Gets the ID of the trace in effect when the log record was created.
+        /// </summary>
+        public ActivityTraceId? TraceId { get; set; }
+    }
+}

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
+{
+    /// <summary>
+    /// 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 IBufferedLogRecord
+    {
+        /// <summary>
+        /// Extracts the metadata for the buffered log record.
+        /// </summary>
+        public void ExtractMetadata(out BufferedLogRecordMetadata metadata);
+    }
+}

src/libraries/Microsoft.Extensions.Logging.Abstractions/src/Microsoft.Extensions.Logging.Abstractions.csproj

@@ -51,6 +51,7 @@ Microsoft.Extensions.Logging.Abstractions.NullLogger</PackageDescription>
     <ProjectReference Include="..\gen\Microsoft.Extensions.Logging.Generators.Roslyn4.4.csproj"
                       ReferenceOutputAssembly="false"
                       PackAsAnalyzer="true" />
+    <ProjectReference Include="$(LibrariesProjectRoot)System.Diagnostics.DiagnosticSource\src\System.Diagnostics.DiagnosticSource.csproj" /> 
   </ItemGroup>
 
 </Project>

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

@@ -34,14 +34,26 @@ public override void Write<TState>(in LogEntry<TState> 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<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 +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<object>.EventId), eventId);
                     writer.WriteString(nameof(LogEntry<object>.LogLevel), GetLogLevelString(logLevel));

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

@@ -52,13 +52,24 @@ public override void Write<TState>(in LogEntry<TState> 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)
             {

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

@@ -42,13 +42,24 @@ public override void Write<TState>(in LogEntry<TState> 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 '<pri>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

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)

src/libraries/Microsoft.Extensions.Logging.Console/tests/Microsoft.Extensions.Logging.Console.Tests/Microsoft.Extensions.Logging.Console.Tests.csproj

@@ -10,6 +10,6 @@
   <ItemGroup>
     <Compile Include="$(CoreLibSharedDir)System\Runtime\CompilerServices\IsExternalInit.cs" Link="Common\System\Runtime\CompilerServices\IsExternalInit.cs" />
     <ProjectReference Include="$(LibrariesProjectRoot)Microsoft.Extensions.Logging.Console\src\Microsoft.Extensions.Logging.Console.csproj" SkipUseReferenceAssembly="true" />
+    <ProjectReference Include="$(LibrariesProjectRoot)System.Diagnostics.DiagnosticSource\ref\System.Diagnostics.DiagnosticSource.csproj" />
   </ItemGroup>
-
 </Project>

src/libraries/Microsoft.Extensions.Logging.Console/tests/tests.sln

@@ -0,0 +1,25 @@
+
+Microsoft Visual Studio Solution File, Format Version 12.00
+# Visual Studio Version 17
+VisualStudioVersion = 17.5.002.0
+MinimumVisualStudioVersion = 10.0.40219.1
+Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Microsoft.Extensions.Logging.Console.Tests", "Microsoft.Extensions.Logging.Console.Tests\Microsoft.Extensions.Logging.Console.Tests.csproj", "{102F40FA-B0D2-454C-8961-246C8526E1DB}"
+EndProject
+Global
+	GlobalSection(SolutionConfigurationPlatforms) = preSolution
+		Debug|Any CPU = Debug|Any CPU
+		Release|Any CPU = Release|Any CPU
+	EndGlobalSection
+	GlobalSection(ProjectConfigurationPlatforms) = postSolution
+		{102F40FA-B0D2-454C-8961-246C8526E1DB}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{102F40FA-B0D2-454C-8961-246C8526E1DB}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{102F40FA-B0D2-454C-8961-246C8526E1DB}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{102F40FA-B0D2-454C-8961-246C8526E1DB}.Release|Any CPU.Build.0 = Release|Any CPU
+	EndGlobalSection
+	GlobalSection(SolutionProperties) = preSolution
+		HideSolutionNode = FALSE
+	EndGlobalSection
+	GlobalSection(ExtensibilityGlobals) = postSolution
+		SolutionGuid = {0FC155C1-F2A6-4E5E-A4BA-EDAE40CCBCD5}
+	EndGlobalSection
+EndGlobal