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

)

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

@@ -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.ConsoleLoggerQueueFullMode 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.")]
@@ -77,6 +79,11 @@ public ConsoleLoggerProvider(Microsoft.Extensions.Options.IOptionsMonitor<Micros
         public void Dispose() { }
         public void SetScopeProvider(Microsoft.Extensions.Logging.IExternalScopeProvider scopeProvider) { }
     }
+    public enum ConsoleLoggerQueueFullMode
+    {
+        Wait = 0,
+        DropWrite = 1,
+    }
     public partial class JsonConsoleFormatterOptions : Microsoft.Extensions.Logging.Console.ConsoleFormatterOptions
     {
         public JsonConsoleFormatterOptions() { }

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

@@ -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 ConsoleLoggerQueueFullMode _queueFullMode = ConsoleLoggerQueueFullMode.Wait;
+        /// <summary>
+        /// Gets or sets the desired console logger behavior when the queue becomes full. Defaults to <c>Wait</c>.
+        /// </summary>
+        public ConsoleLoggerQueueFullMode QueueFullMode
+        {
+            get => _queueFullMode;
+            set
+            {
+                if (value != ConsoleLoggerQueueFullMode.Wait && value != ConsoleLoggerQueueFullMode.DropWrite)
+                {
+                    throw new ArgumentOutOfRangeException(SR.Format(SR.QueueModeNotSupported, nameof(value)));
+                }
+                _queueFullMode = value;
+            }
+        }
+
+        internal const int DefaultMaxQueueLengthValue = 2500;
+        private int _maxQueuedMessages = DefaultMaxQueueLengthValue;
+
+        /// <summary>
+        /// Gets or sets the maximum number of enqueued messages. Defaults to 2500.
+        /// </summary>
+        public int MaxQueueLength
+        {
+            get => _maxQueuedMessages;
+            set
+            {
+                if (value <= 0)
+                {
+                    throw new ArgumentOutOfRangeException(SR.Format(SR.MaxQueueLengthBadValue, nameof(value)));
+                }
+
+                _maxQueuedMessages = value;
+            }
+        }
     }
 }

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

@@ -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;
 
@@ -12,16 +14,57 @@ 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(SR.Format(SR.MaxQueueLengthBadValue, nameof(value)));
+                }
 
-        private readonly BlockingCollection<LogMessageEntry> _messageQueue = new BlockingCollection<LogMessageEntry>(_maxQueuedMessages);
+                lock (_messageQueue)
+                {
+                    _maxQueuedMessages = value;
+                    Monitor.PulseAll(_messageQueue);
+                }
+            }
+        }
+        private ConsoleLoggerQueueFullMode _fullMode = ConsoleLoggerQueueFullMode.Wait;
+        public ConsoleLoggerQueueFullMode FullMode
+        {
+            get => _fullMode;
+            set
+            {
+                if (value != ConsoleLoggerQueueFullMode.Wait && value != ConsoleLoggerQueueFullMode.DropWrite)
+                {
+                    throw new ArgumentOutOfRangeException(SR.Format(SR.QueueModeNotSupported, nameof(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;
+                    Monitor.PulseAll(_messageQueue);
+                }
+            }
+        }
         private readonly Thread _outputThread;
 
         public IConsole Console { get; }
         public IConsole ErrorConsole { get; }
 
-        public ConsoleLoggerProcessor(IConsole console, IConsole errorConsole)
+        public ConsoleLoggerProcessor(IConsole console, IConsole errorConsole, ConsoleLoggerQueueFullMode fullMode, int maxQueueLength)
         {
+            _messageQueue = new Queue<LogMessageEntry>();
+            FullMode = fullMode;
+            MaxQueueLength = maxQueueLength;
             Console = console;
             ErrorConsole = errorConsole;
             // Start Console message queue processor
@@ -35,59 +78,128 @@ public ConsoleLoggerProcessor(IConsole console, IConsole errorConsole)
 
         public virtual void EnqueueMessage(LogMessageEntry message)
         {
-            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();
             }
-            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 == ConsoleLoggerQueueFullMode.DropWrite)
+                    {
+                        _messagesDropped++;
+                        return true;
+                    }
+
+                    Debug.Assert(FullMode == ConsoleLoggerQueueFullMode.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: SR.Format(SR.WarningMessageOnDrop + Environment.NewLine, _messagesDropped),
+                            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)
                 {
-                    _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)
+            {
+                _isAddingCompleted = true;
+                Monitor.PulseAll(_messageQueue);
+            }
+        }
     }
 }

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

@@ -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())
@@ -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")]
@@ -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;

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

@@ -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 the queue becomes full.
+    /// </summary>
+    public enum ConsoleLoggerQueueFullMode
+    {
+        /// <summary>
+        /// Blocks the logging threads once the queue limit is reached.
+        /// </summary>
+        Wait,
+        /// <summary>
+        /// Drops new log messages when the queue is full.
+        /// </summary>
+        DropWrite
+    }
+}

src/libraries/Microsoft.Extensions.Logging.Console/src/Resources/Strings.resx

@@ -120,4 +120,13 @@
   <data name="BufferMaximumSizeExceeded" xml:space="preserve">
     <value>Cannot allocate a buffer of size {0}.</value>
   </data>
+  <data name="QueueModeNotSupported" xml:space="preserve">
+    <value>{0} is not a supported queue mode value.</value>
+  </data>
+  <data name="MaxQueueLengthBadValue" xml:space="preserve">
+    <value>{0} must be larger than zero.</value>
+  </data>
+  <data name="WarningMessageOnDrop" xml:space="preserve">
+    <value>{0} message(s) dropped because of queue size limit. Increase the queue size or decrease logging verbosity to avoid this. You may change `ConsoleLoggerQueueFullMode` to stop dropping messages.</value>
+  </data>
 </root>

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

@@ -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 ? ConsoleLoggerQueueFullMode.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));