Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Enabling console logger queue length and mode to be configurable #70186

Merged
merged 21 commits into from
Jun 21, 2022
Merged
Show file tree
Hide file tree
Changes from 16 commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -62,6 +62,8 @@ public ConsoleLoggerOptions() { }
[System.ObsoleteAttribute("ConsoleLoggerOptions.IncludeScopes has been deprecated. Use ConsoleFormatterOptions.IncludeScopes instead.")]
public bool IncludeScopes { get { throw null; } set { } }
public Microsoft.Extensions.Logging.LogLevel LogToStandardErrorThreshold { get { throw null; } set { } }
public int MaxQueueLength { get { throw null; } set { } }
public Microsoft.Extensions.Logging.Console.ConsoleLoggerBufferFullMode QueueFullMode { get { throw null; } set { } }
[System.ObsoleteAttribute("ConsoleLoggerOptions.TimestampFormat has been deprecated. Use ConsoleFormatterOptions.TimestampFormat instead.")]
public string? TimestampFormat { get { throw null; } set { } }
[System.ObsoleteAttribute("ConsoleLoggerOptions.UseUtcTimestamp has been deprecated. Use ConsoleFormatterOptions.UseUtcTimestamp instead.")]
Expand All @@ -77,6 +79,11 @@ public ConsoleLoggerProvider(Microsoft.Extensions.Options.IOptionsMonitor<Micros
public void Dispose() { }
public void SetScopeProvider(Microsoft.Extensions.Logging.IExternalScopeProvider scopeProvider) { }
}
public enum ConsoleLoggerBufferFullMode
maryamariyan marked this conversation as resolved.
Show resolved Hide resolved
{
Wait = 0,
DropWrite = 1,
}
public partial class JsonConsoleFormatterOptions : Microsoft.Extensions.Logging.Console.ConsoleFormatterOptions
{
public JsonConsoleFormatterOptions() { }
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -63,5 +63,42 @@ public ConsoleLoggerFormat Format
/// </summary>
[System.ObsoleteAttribute("ConsoleLoggerOptions.UseUtcTimestamp has been deprecated. Use ConsoleFormatterOptions.UseUtcTimestamp instead.")]
public bool UseUtcTimestamp { get; set; }

private ConsoleLoggerBufferFullMode _bufferFullMode = ConsoleLoggerBufferFullMode.Wait;
/// <summary>
/// Gets or sets the desired console logger behavior when buffer becomes full. Defaults to <c>Wait</c>.
maryamariyan marked this conversation as resolved.
Show resolved Hide resolved
/// </summary>
public ConsoleLoggerBufferFullMode QueueFullMode
{
get => _bufferFullMode;
set
{
if (value != ConsoleLoggerBufferFullMode.Wait && value != ConsoleLoggerBufferFullMode.DropWrite)
{
throw new ArgumentOutOfRangeException(SR.Format(SR.BufferModeNotSupported, nameof(value)));
}
_bufferFullMode = value;
}
}

internal const int DefaultMaxQueueLengthValue = 2500;
private int _maxQueuedMessages = DefaultMaxQueueLengthValue;

/// <summary>
/// Gets or sets the maximum number of enqueued messages. Defaults to 2500.
maryamariyan marked this conversation as resolved.
Show resolved Hide resolved
/// </summary>
public int MaxQueueLength
{
get => _maxQueuedMessages;
set
{
if (value <= 0)
{
throw new ArgumentOutOfRangeException(nameof(value), value, $"{nameof(value)} must be larger than zero.");
maryamariyan marked this conversation as resolved.
Show resolved Hide resolved
}

_maxQueuedMessages = value;
}
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -2,8 +2,10 @@
// The .NET Foundation licenses this file to you under the MIT license.

using System;
using System.Collections.Concurrent;
using System.Collections.Generic;
using System.Diagnostics;
using System.Diagnostics.CodeAnalysis;
using System.Diagnostics.Metrics;
using System.Runtime.Versioning;
using System.Threading;

Expand All @@ -12,16 +14,56 @@ namespace Microsoft.Extensions.Logging.Console
[UnsupportedOSPlatform("browser")]
internal class ConsoleLoggerProcessor : IDisposable
{
private const int _maxQueuedMessages = 1024;
private readonly Queue<LogMessageEntry> _messageQueue;
private volatile int _messagesDropped;
private bool _isAddingCompleted;
private int _maxQueuedMessages = ConsoleLoggerOptions.DefaultMaxQueueLengthValue;
public int MaxQueueLength
{
get => _maxQueuedMessages;
set
{
if (value <= 0)
{
throw new ArgumentOutOfRangeException(nameof(value), value, $"{nameof(value)} must be larger than zero.");
}

private readonly BlockingCollection<LogMessageEntry> _messageQueue = new BlockingCollection<LogMessageEntry>(_maxQueuedMessages);
lock (_messageQueue)
{
_maxQueuedMessages = value;
Monitor.PulseAll(_messageQueue);
maryamariyan marked this conversation as resolved.
Show resolved Hide resolved
}
}
}
private ConsoleLoggerBufferFullMode _fullMode = ConsoleLoggerBufferFullMode.Wait;
public ConsoleLoggerBufferFullMode FullMode
{
get => _fullMode;
set
{
if (value != ConsoleLoggerBufferFullMode.Wait && value != ConsoleLoggerBufferFullMode.DropWrite)
{
throw new ArgumentOutOfRangeException(nameof(value), value, $"{nameof(value)} is not a supported buffer mode value.");
}

lock (_messageQueue)
{
// _fullMode is used inside the lock and is safer to guard setter with lock as well
// this set is not expected to happen frequently
_fullMode = value;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why don't we need a Monitor.PulseAll(_messageQueue); here?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

no thread would be waiting on full mode to change

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

what about my comment here #70186 (comment)?

Copy link
Member Author

@maryamariyan maryamariyan Jun 21, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

oh seems like this comment is related, #70186 (comment)
updated.

}
}
}
private readonly Thread _outputThread;

public IConsole Console { get; }
public IConsole ErrorConsole { get; }

public ConsoleLoggerProcessor(IConsole console, IConsole errorConsole)
public ConsoleLoggerProcessor(IConsole console, IConsole errorConsole, ConsoleLoggerBufferFullMode fullMode, int maxQueueLength)
{
_messageQueue = new Queue<LogMessageEntry>();
FullMode = fullMode;
MaxQueueLength = maxQueueLength;
Console = console;
ErrorConsole = errorConsole;
// Start Console message queue processor
Expand All @@ -35,59 +77,128 @@ public ConsoleLoggerProcessor(IConsole console, IConsole errorConsole)

public virtual void EnqueueMessage(LogMessageEntry message)
maryamariyan marked this conversation as resolved.
Show resolved Hide resolved
{
if (!_messageQueue.IsAddingCompleted)
// cannot enqueue when adding is completed
if (!Enqueue(message))
{
try
{
_messageQueue.Add(message);
return;
}
catch (InvalidOperationException) { }
WriteMessage(message);
}
}

// Adding is completed so just log the message
// internal for testing
internal void WriteMessage(LogMessageEntry entry)
{
try
{
WriteMessage(message);
IConsole console = entry.LogAsError ? ErrorConsole : Console;
console.Write(entry.Message);
}
catch
{
CompleteAdding();
maryamariyan marked this conversation as resolved.
Show resolved Hide resolved
}
catch (Exception) { }
}

// for testing
internal void WriteMessage(LogMessageEntry entry)
private void ProcessLogQueue()
{
IConsole console = entry.LogAsError ? ErrorConsole : Console;
console.Write(entry.Message);
while (TryDequeue(out LogMessageEntry message))
{
WriteMessage(message);
}
}

private void ProcessLogQueue()
public bool Enqueue(LogMessageEntry item)
{
try
lock (_messageQueue)
{
foreach (LogMessageEntry message in _messageQueue.GetConsumingEnumerable())
while (_messageQueue.Count >= MaxQueueLength && !_isAddingCompleted)
{
if (FullMode == ConsoleLoggerBufferFullMode.DropWrite)
{
_messagesDropped++;
return true;
}

maryamariyan marked this conversation as resolved.
Show resolved Hide resolved
Debug.Assert(FullMode == ConsoleLoggerBufferFullMode.Wait);
Monitor.Wait(_messageQueue);
}

if (!_isAddingCompleted)
{
WriteMessage(message);
Debug.Assert(_messageQueue.Count < MaxQueueLength);
bool startedEmpty = _messageQueue.Count == 0;
if (_messagesDropped > 0)
{
_messageQueue.Enqueue(new LogMessageEntry(
message: _messagesDropped + SR.WarningMessageOnDrop + Environment.NewLine,
maryamariyan marked this conversation as resolved.
Show resolved Hide resolved
logAsError: true
));

_messagesDropped = 0;
}

// if we just logged the dropped message warning this could push the queue size to
// MaxLength + 1, that shouldn't be a problem. It won't grow any further until it is less than
// MaxLength once again.
_messageQueue.Enqueue(item);

// if the queue started empty it could be at 1 or 2 now
if (startedEmpty)
{
// pulse for wait in Dequeue
Monitor.PulseAll(_messageQueue);
}

return true;
}
}
catch

return false;
}

public bool TryDequeue(out LogMessageEntry item)
{
lock (_messageQueue)
{
try
while (_messageQueue.Count == 0 && !_isAddingCompleted)
{
Monitor.Wait(_messageQueue);
}

if (_messageQueue.Count > 0 && !_isAddingCompleted)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So after the Dispose is called - we won't log any messages that are still in buffer?
@vlada-shubina as FYI

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

To elaborate more

  • Dispose calls CompleteAdding which tries to lock _messageQueue and then marks _isAddingCompleted with true
  • ProcessLogQueue calls TryDequeue in a loop, per single item. For each call it needs to lock _messageQueue to be able to return item to be logged by ProcessLogQueue
  • If _isAddingCompleted is true the TryDequeue will return false - even if _messageQueue.Count is nonempty

Those facts bring the following concerns:

  • The CompleteAdding and TryDequeue races for same lock. Once CompleteAdding wins, nothing more is logged, even if items are still queued - this seems to be a bug.
  • TryDequeue tries to acquire lock for each single item being logged - I'm surprised this ends up being faster then using low-lock BlockingCollection. If it really is - should the BlockingCollection be actualy revised?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@JanKrivanek if you can provide a sample code to demonstrate the concerns, you may open a new issue and we can track looking at that there. Thanks for your feedback.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am seeing you already logged #79812. We'll try to look at that at some point.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sample repro: https://github.com/JanKrivanek/ConsoleLogging

Showing that messages are being dropped in 7.0 version of logging.

{
_messageQueue.CompleteAdding();
item = _messageQueue.Dequeue();
if (_messageQueue.Count == MaxQueueLength - 1)
{
// pulse for wait in Enqueue
Monitor.PulseAll(_messageQueue);
}

return true;
}
catch { }

item = default;
return false;
}
}

public void Dispose()
{
_messageQueue.CompleteAdding();
CompleteAdding();

try
{
_outputThread.Join(1500); // with timeout in-case Console is locked by user input
}
catch (ThreadStateException) { }
}

private void CompleteAdding()
{
lock (_messageQueue)
{
Monitor.PulseAll(_messageQueue);
_isAddingCompleted = true;
}
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -43,10 +43,6 @@ public ConsoleLoggerProvider(IOptionsMonitor<ConsoleLoggerOptions> options, IEnu
_options = options;
_loggers = new ConcurrentDictionary<string, ConsoleLogger>();
SetFormatters(formatters);

ReloadLoggerOptions(options.CurrentValue);
_optionsReloadToken = _options.OnChange(ReloadLoggerOptions);

IConsole? console;
IConsole? errorConsole;
if (DoesConsoleSupportAnsi())
Expand All @@ -59,7 +55,14 @@ public ConsoleLoggerProvider(IOptionsMonitor<ConsoleLoggerOptions> options, IEnu
console = new AnsiParsingLogConsole();
errorConsole = new AnsiParsingLogConsole(stdErr: true);
}
_messageQueue = new ConsoleLoggerProcessor(console, errorConsole);
_messageQueue = new ConsoleLoggerProcessor(
console,
errorConsole,
options.CurrentValue.QueueFullMode,
options.CurrentValue.MaxQueueLength);

ReloadLoggerOptions(options.CurrentValue);
_optionsReloadToken = _options.OnChange(ReloadLoggerOptions);
}

[UnsupportedOSPlatformGuard("windows")]
Expand Down Expand Up @@ -123,6 +126,9 @@ private void ReloadLoggerOptions(ConsoleLoggerOptions options)
#pragma warning restore CS0618
}

_messageQueue.FullMode = options.QueueFullMode;
_messageQueue.MaxQueueLength = options.MaxQueueLength;

foreach (KeyValuePair<string, ConsoleLogger> logger in _loggers)
{
logger.Value.Options = options;
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,20 @@
// 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.Console
{
/// <summary>
/// Determines the console logger behavior when buffer becomes full.
maryamariyan marked this conversation as resolved.
Show resolved Hide resolved
/// </summary>
public enum ConsoleLoggerBufferFullMode
{
/// <summary>
/// Blocks the logging threads once the buffer limit is reached.
maryamariyan marked this conversation as resolved.
Show resolved Hide resolved
/// </summary>
Wait,
/// <summary>
/// Drops new log messages when the buffer is full
maryamariyan marked this conversation as resolved.
Show resolved Hide resolved
/// </summary>
DropWrite
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -120,4 +120,10 @@
<data name="BufferMaximumSizeExceeded" xml:space="preserve">
<value>Cannot allocate a buffer of size {0}.</value>
</data>
<data name="BufferModeNotSupported" xml:space="preserve">
<value>{0} is not a supported buffer mode value.</value>
maryamariyan marked this conversation as resolved.
Show resolved Hide resolved
</data>
<data name="WarningMessageOnDrop" xml:space="preserve">
<value> message(s) dropped because of queue size limit. Increase the queue size or decrease logging verbosity to avoid this. You may change `ConsoleLoggerBufferFullMode` to stop dropping messages.</value>
maryamariyan marked this conversation as resolved.
Show resolved Hide resolved
</data>
</root>
Original file line number Diff line number Diff line change
Expand Up @@ -38,7 +38,9 @@ internal static (ConsoleLogger Logger, ConsoleSink Sink, ConsoleSink ErrorSink,
var errorSink = new ConsoleSink();
var console = new TestConsole(sink);
var errorConsole = new TestConsole(errorSink);
var consoleLoggerProcessor = new TestLoggerProcessor(console, errorConsole);
var bufferMode = options == null ? ConsoleLoggerBufferFullMode.Wait : options.QueueFullMode;
var maxQueueLength = options == null ? ConsoleLoggerOptions.DefaultMaxQueueLengthValue : options.MaxQueueLength;
var consoleLoggerProcessor = new TestLoggerProcessor(console, errorConsole, bufferMode, maxQueueLength);

var formatters = new ConcurrentDictionary<string, ConsoleFormatter>(ConsoleLoggerTest.GetFormatters(simpleOptions, systemdOptions, jsonOptions).ToDictionary(f => f.Name));

Expand Down
Loading