From e2a98baa4a046a34caf52d6e2e79cc9ab6bbfc71 Mon Sep 17 00:00:00 2001 From: Martin Taillefer Date: Thu, 6 Jun 2024 12:20:07 -0700 Subject: [PATCH] Introduce IBufferedLogRecordMetadata --- .../src/IBufferedLogRecordMetadata.cs | 39 ++++++++++++ .../src/JsonConsoleFormatter.cs | 20 ++++-- .../src/SimpleConsoleFormatter.cs | 17 ++++-- .../src/SystemdConsoleFormatter.cs | 17 ++++-- .../ConsoleLoggerTest.cs | 61 +++++++++++++++++++ 5 files changed, 142 insertions(+), 12 deletions(-) create mode 100644 src/libraries/Microsoft.Extensions.Logging.Abstractions/src/IBufferedLogRecordMetadata.cs diff --git a/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/IBufferedLogRecordMetadata.cs b/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/IBufferedLogRecordMetadata.cs new file mode 100644 index 00000000000000..01f9fb46a4d99a --- /dev/null +++ b/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 +{ + /// + /// Holds metadata for 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 IBufferedLogRecordMetadata + { + /// + /// Gets the time when the log record was recorded. + /// + public DateTimeOffset CreationTime { get; } + + /// + /// Gets the ID of the thread that created the log record. + /// + public int? ManagedThreadId { get; } + + /// + /// Gets the ID of the span in effect when the log record was created. + /// + public ActivitySpanId? SpanId { get; } + + /// + /// Gets the ID of the trace in effect when the log record was created. + /// + public ActivityTraceId? TraceId { get; } + } +} diff --git a/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs b/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs index 945e6ebb23584e..a14e4969ad7563 100644 --- a/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs +++ b/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs @@ -34,14 +34,27 @@ public override void Write(in LogEntry 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>); + 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 +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.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..f5c36c9c33bb5c 100644 --- a/src/libraries/Microsoft.Extensions.Logging.Console/src/SimpleConsoleFormatter.cs +++ b/src/libraries/Microsoft.Extensions.Logging.Console/src/SimpleConsoleFormatter.cs @@ -52,13 +52,23 @@ public override void Write(in LogEntry 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) { diff --git a/src/libraries/Microsoft.Extensions.Logging.Console/src/SystemdConsoleFormatter.cs b/src/libraries/Microsoft.Extensions.Logging.Console/src/SystemdConsoleFormatter.cs index 2d306fee1d0a4b..895c6a0b4f0600 100644 --- a/src/libraries/Microsoft.Extensions.Logging.Console/src/SystemdConsoleFormatter.cs +++ b/src/libraries/Microsoft.Extensions.Logging.Console/src/SystemdConsoleFormatter.cs @@ -42,13 +42,23 @@ public override void Write(in LogEntry 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 '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 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..4034ada5b98ee3 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,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)