Skip to content

Commit

Permalink
Introduce IBufferedLogger (dotnet#103138)
Browse files Browse the repository at this point in the history
* Introduce IBufferedLogger

* Update following review

* Apply suggestions from code review

Co-authored-by: Stephen Toub <stoub@microsoft.com>

* Next batch of review changes

* Another fix

* More fixes

---------

Co-authored-by: Martin Taillefer <mataille@microsoft.com>
Co-authored-by: Stephen Toub <stoub@microsoft.com>
  • Loading branch information
3 people committed Jul 18, 2024
1 parent c19c03e commit 223249f
Show file tree
Hide file tree
Showing 12 changed files with 294 additions and 41 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -202,4 +202,21 @@ 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 abstract class BufferedLogRecord
{
public abstract System.DateTimeOffset Timestamp { get; }
public abstract Microsoft.Extensions.Logging.LogLevel LogLevel { get; }
public abstract Microsoft.Extensions.Logging.EventId EventId { get; }
public virtual string? Exception { get; }
public virtual System.Diagnostics.ActivitySpanId? ActivitySpanId { get; }
public virtual System.Diagnostics.ActivityTraceId? ActivityTraceId { get; }
public virtual int? ManagedThreadId { get; }
public virtual string? FormattedMessage { get; }
public virtual string? MessageTemplate { get; }
public virtual System.Collections.Generic.IReadOnlyList<System.Collections.Generic.KeyValuePair<string, object?>> Attributes { get; }
}
public interface IBufferedLogger
{
void LogRecords(System.Collections.Generic.IEnumerable<Microsoft.Extensions.Logging.Abstractions.BufferedLogRecord> records);
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -9,5 +9,6 @@

<ItemGroup>
<ProjectReference Include="$(LibrariesProjectRoot)Microsoft.Extensions.DependencyInjection.Abstractions\ref\Microsoft.Extensions.DependencyInjection.Abstractions.csproj" />
<ProjectReference Include="$(LibrariesProjectRoot)System.Diagnostics.DiagnosticSource\ref\System.Diagnostics.DiagnosticSource.csproj" />
</ItemGroup>
</Project>
Original file line number Diff line number Diff line change
@@ -0,0 +1,70 @@
// 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.Collections.Generic;
using System.Diagnostics;

namespace Microsoft.Extensions.Logging.Abstractions
{
/// <summary>
/// Represents a buffered log record to be written in batch to an <see cref="IBufferedLogger" />.
/// </summary>
/// <remarks>
/// Instances of this type may be pooled and reused. Implementations of <see cref="IBufferedLogger" /> must
/// not hold onto instance of <see cref="BufferedLogRecord" /> passed to its <see cref="IBufferedLogger.LogRecords" /> method
/// beyond the invocation of that method.
/// </remarks>
public abstract class BufferedLogRecord
{
/// <summary>
/// Gets the time when the log record was first created.
/// </summary>
public abstract DateTimeOffset Timestamp { get; }

/// <summary>
/// Gets the record's logging severity level.
/// </summary>
public abstract LogLevel LogLevel { get; }

/// <summary>
/// Gets the record's event id.
/// </summary>
public abstract EventId EventId { get; }

/// <summary>
/// Gets an exception string for this record.
/// </summary>
public virtual string? Exception => null;

/// <summary>
/// Gets an activity span ID for this record, representing the state of the thread that created the record.
/// </summary>
public virtual ActivitySpanId? ActivitySpanId => null;

/// <summary>
/// Gets an activity trace ID for this record, representing the state of the thread that created the record.
/// </summary>
public virtual ActivityTraceId? ActivityTraceId => null;

/// <summary>
/// Gets the ID of the thread that created the log record.
/// </summary>
public virtual int? ManagedThreadId => null;

/// <summary>
/// Gets the formatted log message.
/// </summary>
public virtual string? FormattedMessage => null;

/// <summary>
/// Gets the original log message template.
/// </summary>
public virtual string? MessageTemplate => null;

/// <summary>
/// Gets the variable set of name/value pairs associated with the record.
/// </summary>
public virtual IReadOnlyList<KeyValuePair<string, object?>> Attributes => [];
}
}
Original file line number Diff line number Diff line change
@@ -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.Collections.Generic;

namespace Microsoft.Extensions.Logging.Abstractions
{
/// <summary>
/// Represents the ability of a logging provider to support buffered logging.
/// </summary>
/// <remarks>
/// A logging provider implements the <see cref="ILogger" /> interface that gets invoked by the
/// logging infrastructure whenever it’s time to log a piece of state.
///
/// A logging provider may also optionally implement the <see cref="IBufferedLogger" /> interface.
/// The logging infrastructure may type-test the <see cref="ILogger" /> object to determine if
/// it supports the <see cref="IBufferedLogger" /> interface. If it does, that indicates to the
/// logging infrastructure that the logging provider supports buffering. Whenever log
/// buffering is enabled, buffered log records may be delivered to the logging provider
/// in a batch via <see cref="IBufferedLogger.LogRecords" />.
///
/// If a logging provider does not support log buffering, then it will always be given
/// unbuffered log records. If a logging provider does support log buffering, whether its
/// <see cref="ILogger" /> or <see cref="IBufferedLogger" /> implementation is used is
/// determined by the log producer.
/// </remarks>
public interface IBufferedLogger
{
/// <summary>
/// Delivers a batch of buffered log records to a logging provider.
/// </summary>
/// <param name="records">The buffered log records to log.</param>
/// <remarks>
/// Once this function returns, the implementation should no longer access the records
/// or state referenced by these records since the instances may be reused to represent other logs.
/// </remarks>
void LogRecords(IEnumerable<BufferedLogRecord> records);
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -53,6 +53,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>
Original file line number Diff line number Diff line change
Expand Up @@ -32,7 +32,7 @@ protected ConsoleFormatter(string name)
/// Writes the log message to the specified TextWriter.
/// </summary>
/// <remarks>
/// if the formatter wants to write colors to the console, it can do so by embedding ANSI color codes into the string
/// If the formatter wants to write colors to the console, it can do so by embedding ANSI color codes into the string.
/// </remarks>
/// <param name="logEntry">The log entry.</param>
/// <param name="scopeProvider">The provider of scope data.</param>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@
// The .NET Foundation licenses this file to you under the MIT license.

using System;
using System.Collections.Generic;
using System.Diagnostics.CodeAnalysis;
using System.IO;
using System.Runtime.Versioning;
Expand All @@ -13,7 +14,7 @@ namespace Microsoft.Extensions.Logging.Console
/// A logger that writes messages in the console.
/// </summary>
[UnsupportedOSPlatform("browser")]
internal sealed class ConsoleLogger : ILogger
internal sealed class ConsoleLogger : ILogger, IBufferedLogger
{
private readonly string _name;
private readonly ConsoleLoggerProcessor _queueProcessor;
Expand Down Expand Up @@ -69,6 +70,35 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
_queueProcessor.EnqueueMessage(new LogMessageEntry(computedAnsiString, logAsError: logLevel >= Options.LogToStandardErrorThreshold));
}

/// <inheritdoc />
public void LogRecords(IEnumerable<BufferedLogRecord> records)
{
ThrowHelper.ThrowIfNull(records);

StringWriter writer = t_stringWriter ??= new StringWriter();

var sb = writer.GetStringBuilder();
foreach (var rec in records)
{
var logEntry = new LogEntry<BufferedLogRecord>(rec.LogLevel, _name, rec.EventId, rec, null, static (s, _) => s.FormattedMessage ?? string.Empty);
Formatter.Write(in logEntry, null, writer);

if (sb.Length == 0)
{
continue;
}

string computedAnsiString = sb.ToString();
sb.Clear();
_queueProcessor.EnqueueMessage(new LogMessageEntry(computedAnsiString, logAsError: rec.LogLevel >= Options.LogToStandardErrorThreshold));
}

if (sb.Capacity > 1024)
{
sb.Capacity = 1024;
}
}

/// <inheritdoc />
public bool IsEnabled(LogLevel logLevel)
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -28,20 +28,34 @@ public JsonConsoleFormatter(IOptionsMonitor<JsonConsoleFormatterOptions> options

public override void Write<TState>(in LogEntry<TState> logEntry, IExternalScopeProvider? scopeProvider, TextWriter textWriter)
{
string message = logEntry.Formatter(logEntry.State, logEntry.Exception);
if (logEntry.Exception == null && message == null)
if (logEntry.State is BufferedLogRecord bufferedRecord)
{
return;
string message = bufferedRecord.FormattedMessage ?? string.Empty;
WriteInternal(null, textWriter, message, bufferedRecord.LogLevel, logEntry.Category, bufferedRecord.EventId.Id, bufferedRecord.Exception,
bufferedRecord.Attributes.Count > 0, null, bufferedRecord.Attributes, bufferedRecord.Timestamp);
}
else
{
string message = logEntry.Formatter(logEntry.State, logEntry.Exception);
if (logEntry.Exception == null && message == null)
{
return;
}

// 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>>);
DateTimeOffset stamp = FormatterOptions.TimestampFormat != null
? (FormatterOptions.UseUtcTimestamp ? DateTimeOffset.UtcNow : DateTimeOffset.Now)
: DateTimeOffset.MinValue;

// 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?.ToString(),
logEntry.State != null, logEntry.State?.ToString(), logEntry.State as IReadOnlyList<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)
private void WriteInternal(IExternalScopeProvider? scopeProvider, TextWriter textWriter, string? message, LogLevel logLevel,
string category, int eventId, string? exception, bool hasState, string? stateMessage, IReadOnlyList<KeyValuePair<string, object?>>? stateProperties,
DateTimeOffset stamp)
{
const int DefaultBufferSize = 1024;
using (var output = new PooledByteBufferWriter(DefaultBufferSize))
Expand All @@ -52,8 +66,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));
Expand All @@ -62,7 +75,7 @@ private void WriteInternal(IExternalScopeProvider? scopeProvider, TextWriter tex

if (exception != null)
{
writer.WriteString(nameof(Exception), exception.ToString());
writer.WriteString(nameof(Exception), exception);
}

if (hasState)
Expand All @@ -71,7 +84,7 @@ private void WriteInternal(IExternalScopeProvider? scopeProvider, TextWriter tex
writer.WriteString("Message", stateMessage);
if (stateProperties != null)
{
foreach (KeyValuePair<string, object> item in stateProperties)
foreach (KeyValuePair<string, object?> item in stateProperties)
{
WriteItem(writer, item);
}
Expand Down Expand Up @@ -131,11 +144,11 @@ private void WriteScopeInformation(Utf8JsonWriter writer, IExternalScopeProvider
writer.WriteStartArray("Scopes");
scopeProvider.ForEachScope((scope, state) =>
{
if (scope is IEnumerable<KeyValuePair<string, object>> scopeItems)
if (scope is IEnumerable<KeyValuePair<string, object?>> scopeItems)
{
state.WriteStartObject();
state.WriteString("Message", scope.ToString());
foreach (KeyValuePair<string, object> item in scopeItems)
foreach (KeyValuePair<string, object?> item in scopeItems)
{
WriteItem(state, item);
}
Expand All @@ -150,7 +163,7 @@ private void WriteScopeInformation(Utf8JsonWriter writer, IExternalScopeProvider
}
}

private static void WriteItem(Utf8JsonWriter writer, KeyValuePair<string, object> item)
private static void WriteItem(Utf8JsonWriter writer, KeyValuePair<string, object?> item)
{
var key = item.Key;
switch (item.Value)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -46,19 +46,27 @@ public void Dispose()

public override void Write<TState>(in LogEntry<TState> logEntry, IExternalScopeProvider? scopeProvider, TextWriter textWriter)
{
string message = logEntry.Formatter(logEntry.State, logEntry.Exception);
if (logEntry.Exception == null && message == null)
if (logEntry.State is BufferedLogRecord bufferedRecord)
{
return;
string message = bufferedRecord.FormattedMessage ?? string.Empty;
WriteInternal(null, textWriter, message, bufferedRecord.LogLevel, bufferedRecord.EventId.Id, bufferedRecord.Exception, logEntry.Category, bufferedRecord.Timestamp);
}
else
{
string message = logEntry.Formatter(logEntry.State, logEntry.Exception);
if (logEntry.Exception == null && message == null)
{
return;
}

// 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);
// 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?.ToString(), logEntry.Category, GetCurrentDateTime());
}
}

private void WriteInternal(IExternalScopeProvider? scopeProvider, TextWriter textWriter, string message, LogLevel logLevel,
int eventId, Exception? exception, string category)
int eventId, string? exception, string category, DateTimeOffset stamp)
{
ConsoleColors logLevelColors = GetLogLevelConsoleColors(logLevel);
string logLevelString = GetLogLevelString(logLevel);
Expand All @@ -67,8 +75,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)
{
Expand Down Expand Up @@ -114,7 +121,7 @@ private void WriteInternal(IExternalScopeProvider? scopeProvider, TextWriter tex
if (exception != null)
{
// exception message
WriteMessage(textWriter, exception.ToString(), singleLine);
WriteMessage(textWriter, exception, singleLine);
}
if (singleLine)
{
Expand Down Expand Up @@ -148,7 +155,9 @@ static void WriteReplacing(TextWriter writer, string oldValue, string newValue,

private DateTimeOffset GetCurrentDateTime()
{
return FormatterOptions.UseUtcTimestamp ? DateTimeOffset.UtcNow : DateTimeOffset.Now;
return FormatterOptions.TimestampFormat != null
? (FormatterOptions.UseUtcTimestamp ? DateTimeOffset.UtcNow : DateTimeOffset.Now)
: DateTimeOffset.MinValue;
}

private static string GetLogLevelString(LogLevel logLevel)
Expand Down
Loading

0 comments on commit 223249f

Please sign in to comment.