This is an automated email from the ASF dual-hosted git repository. FreeAndNil pushed a commit to branch Feature/318-telnet-default in repository https://gitbox.apache.org/repos/asf/logging-log4net.git
commit a48c0141f5b82438664883180d9943d620fa53b4 Author: Jan Friedrich <[email protected]> AuthorDate: Fri Sep 4 09:09:40 2026 +0200 write to Telnet clients from a background thread #318 - Clients were written to serially under the appender lock, so one that stopped reading blocked every logging thread for sendTimeoutMillis. - Events are queued now, sendQueueSize 500, enqueueTimeoutMillis 50. - A full queue drops from the telnet stream, never from the log. - While the queue stays full the 50ms wait caps logging at 20 events/s; 0 drops. audit da18b6fd-f014 --- src/changelog/3.5.0/318-telnet-background-send.xml | 15 +++ .../Appender/Internal/SimpleTelnetClient.cs | 18 +++ src/log4net.Tests/Appender/TelnetAppenderTest.cs | 139 +++++++++++++++++++++ src/log4net/Appender/TelnetAppender.cs | 93 +++++++++++++- .../configuration/appenders/telnetappender.adoc | 23 +++- 5 files changed, 282 insertions(+), 6 deletions(-) diff --git a/src/changelog/3.5.0/318-telnet-background-send.xml b/src/changelog/3.5.0/318-telnet-background-send.xml new file mode 100644 index 00000000..db190127 --- /dev/null +++ b/src/changelog/3.5.0/318-telnet-background-send.xml @@ -0,0 +1,15 @@ +<?xml version="1.0" encoding="UTF-8"?> +<entry xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; + xmlns="https://logging.apache.org/xml/ns"; + xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"; + type="changed"> + <issue id="318" link="https://github.com/apache/logging-log4net/pull/318"/> + <description format="asciidoc">Write to `TelnetAppender` clients from a background thread. Clients + were written to under the appender lock, so one that stopped reading blocked every thread that + logs for `sendTimeoutMillis`, and the writes are serial, so 20 connected clients cost 20 times + that on a single event. Events are queued now, bounded by the new `sendQueueSize` (500), and a + logging call waits at most `enqueueTimeoutMillis` (50) for room before the event is dropped from + the telnet stream, counted and reported. Only the telnet view is lost, never the log. While the + queue stays full that wait caps logging at 20 events per second; set it to 0 to drop instead + (audit da18b6fd-f014, implemented by @FreeAndNil)</description> +</entry> diff --git a/src/log4net.Tests/Appender/Internal/SimpleTelnetClient.cs b/src/log4net.Tests/Appender/Internal/SimpleTelnetClient.cs index bc13c8c9..02b933ee 100644 --- a/src/log4net.Tests/Appender/Internal/SimpleTelnetClient.cs +++ b/src/log4net.Tests/Appender/Internal/SimpleTelnetClient.cs @@ -40,6 +40,24 @@ internal sealed class SimpleTelnetClient( private readonly TcpClient _client = new(); private volatile bool _disposing; + /// <summary> + /// Connects, reads the welcome message and then stops reading, so this client's receive window + /// fills and writes to it block. The opposite of <see cref="Run"/>, for testing that a client + /// which stops reading cannot hold up the threads that log. + /// </summary> + internal void ConnectAndStopReading() + { + // The kernel clamps this to its minimum, 2304 bytes on Linux, so asking for less buys nothing: + // measured, 1, 128, 512 and 1024 all block the writer after the same 960 KB, while 4096 needs + // 1748 KB and 16384 needs 2364 KB. The rest of the threshold is the writer's own send buffer, + // which is not reachable from here. + _client.ReceiveBufferSize = 1_024; + _client.ReceiveTimeout = 30_000; + _client.Connect(new IPEndPoint(IPAddress.Loopback, port)); + // Reading one byte of the welcome message proves the appender accepted the connection. + _client.GetStream().Read(new byte[1], 0, 1); + } + /// <summary> /// Runs the client (in a task) /// </summary> diff --git a/src/log4net.Tests/Appender/TelnetAppenderTest.cs b/src/log4net.Tests/Appender/TelnetAppenderTest.cs index 9b0bb3b2..bd5f2572 100644 --- a/src/log4net.Tests/Appender/TelnetAppenderTest.cs +++ b/src/log4net.Tests/Appender/TelnetAppenderTest.cs @@ -18,6 +18,7 @@ #endregion using System; +using System.Collections.Generic; using System.Diagnostics; using System.Net; using System.Net.Sockets; @@ -30,6 +31,7 @@ using log4net.Layout; using log4net.Repository; using log4net.Tests.Appender.Internal; +using log4net.Util; using NUnit.Framework; namespace log4net.Tests.Appender; @@ -255,6 +257,143 @@ public void EveryInterfaceCanBeAskedFor(string address) => Assert.That(new TelnetAppender { ListenAddress = IPAddress.Parse(address) }.ListenAddress, Is.EqualTo(IPAddress.Parse(address))); + /// <summary> + /// Clients are written to from a background thread, so the queue has to be bounded and the wait + /// for room short: it is the only delay a connected client can impose on the application. + /// </summary> + [Test] + public void SendQueueDefaults() + { + TelnetAppender appender = new(); + + Assert.That(appender.SendQueueSize, Is.EqualTo(500)); + Assert.That(appender.EnqueueTimeoutMillis, Is.EqualTo(50)); + } + + /// <summary> + /// A queue of no size cannot hold anything, and a negative wait has no meaning. + /// </summary> + [Test] + public void SendQueueSettingsRejectMeaninglessValues() + { + TelnetAppender appender = new(); + + Assert.That(() => appender.SendQueueSize = 0, Throws.TypeOf<ArgumentOutOfRangeException>()); + Assert.That(() => appender.EnqueueTimeoutMillis = -1, Throws.TypeOf<ArgumentOutOfRangeException>()); + + appender.EnqueueTimeoutMillis = 0; + Assert.That(appender.EnqueueTimeoutMillis, Is.EqualTo(0)); + } + + /// <summary> + /// A client that connects and then stops reading fills its receive window, and writing to it + /// used to block the logging thread for the whole send timeout, once per client. Logging must + /// now return promptly however badly the client behaves. + /// </summary> + [Test] + [NonParallelizable] + public void SlowReadersDoNotDelayLogging() + { + const int deadReaderCount = 4; + const int sendTimeoutMillis = 2_000; + // A loopback write blocks once roughly 1 MB is outstanding against the client's 1 KB receive + // buffer, measured, so send comfortably past that. + const int eventCount = 400; + + int port = FindFreeTcpPort(); + TelnetAppender appender = new() + { + Port = port, + ListenAddress = IPAddress.Loopback, + Layout = new PatternLayout("%message%newline"), + SendTimeoutMillis = sendTimeoutMillis + }; + appender.ActivateOptions(); + + List<SimpleTelnetClient> deadReaders = []; + try + { + for (int i = 0; i < deadReaderCount; i++) + { + SimpleTelnetClient deadReader = new(_ => { }, port); + deadReaders.Add(deadReader); + deadReader.ConnectAndStopReading(); + } + + string message = new('x', 4_096); + Stopwatch stopwatch = Stopwatch.StartNew(); + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + for (int i = 0; i < eventCount; i++) + { + appender.DoAppend(CreateEvent(message)); + } + }); + stopwatch.Stop(); + + // Writing synchronously costs SendTimeoutMillis per stalled client before it is evicted, + // serially and under the appender lock: 8s here, and 100s with the 20-client cap and the + // default timeout. Queueing costs the enqueue wait at worst. + Assert.That(stopwatch.Elapsed, + Is.LessThan(TimeSpan.FromMilliseconds(deadReaderCount * sendTimeoutMillis / 2)), + "logging blocked behind clients that stopped reading"); + } + finally + { + // Let the pump finish before Close waits for a drain. + foreach (SimpleTelnetClient deadReader in deadReaders) + { + deadReader.Dispose(); + } + LogLog.ExecuteWithoutEmittingInternalMessages(appender.Close); + } + } + + /// <summary> + /// A queue that cannot keep up drops, rather than growing or making the logging thread wait. + /// The loss costs the telnet stream only, so it is counted and reported once instead of per + /// event, which would be a denial of service of its own. + /// </summary> + [Test] + [NonParallelizable] + public void AFullQueueDropsAndReportsOnce() + { + int port = FindFreeTcpPort(); + RecordingErrorHandler errorHandler = new(); + TelnetAppender appender = new() + { + Port = port, + ListenAddress = IPAddress.Loopback, + Layout = new PatternLayout("%message%newline"), + // A queue this small fills as soon as the client stops reading, and nothing waits for room. + SendQueueSize = 4, + EnqueueTimeoutMillis = 0, + ErrorHandler = errorHandler + }; + appender.ActivateOptions(); + + using SimpleTelnetClient deadReader = new(_ => { }, port); + try + { + deadReader.ConnectAndStopReading(); + + for (int i = 0; i < 200; i++) + { + appender.DoAppend(CreateEvent(new string('x', 4_096))); + } + + Assert.That(errorHandler.Messages.FindAll(m => m.IndexOf("was dropped", StringComparison.Ordinal) >= 0), + Has.Count.EqualTo(1), "the drop must be reported exactly once, however many events are lost"); + } + finally + { + appender.Close(); + } + } + + private static LoggingEvent CreateEvent(string message) + => new(new LoggingEventData { Level = Level.Info, Message = message, LoggerName = "TelnetTest" }); + /// <summary> /// Binding to the loopback address has to keep the port unreachable from other machines, which /// is what an operator asking for it wants. diff --git a/src/log4net/Appender/TelnetAppender.cs b/src/log4net/Appender/TelnetAppender.cs index b38a9373..4ab54b1f 100644 --- a/src/log4net/Appender/TelnetAppender.cs +++ b/src/log4net/Appender/TelnetAppender.cs @@ -24,6 +24,7 @@ using System.Text; using System.IO; using System.Linq; +using System.Threading; using log4net.Appender.Internal; using log4net.Core; using log4net.Util; @@ -55,11 +56,68 @@ namespace log4net.Appender; /// <author>Nicko Cadell</author> public class TelnetAppender : AppenderSkeleton { + private const int CloseTimeoutMillis = 5_000; + private SocketHandler? _handler; + private BackgroundSender<string>? _sender; private int _listeningPort = 23; private int _sendTimeoutMillis = 5_000; + private int _sendQueueSize = 500; + private int _enqueueTimeoutMillis = 50; private IPAddress _listenAddress = IPAddress.Loopback; + /// <summary> + /// Gets or sets how many rendered events may wait to be written to the clients. + /// </summary> + /// <value>A positive number of events. The default is 500.</value> + /// <remarks> + /// <para> + /// Clients are written to from a background thread, so that a client which stops reading cannot + /// hold up the threads that log. Events queue up while that thread works, and are dropped once + /// the queue is full, which costs the telnet stream but never the log. + /// </para> + /// </remarks> + /// <exception cref="ArgumentOutOfRangeException">The value specified is not positive.</exception> + public int SendQueueSize + { + get => _sendQueueSize; + set + { + if (value <= 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for SendQueueSize is not positive."); + } + _sendQueueSize = value; + } + } + + /// <summary> + /// Gets or sets how long, in milliseconds, a logging call may wait for room in the send queue. + /// </summary> + /// <value>A number of milliseconds, or 0 to drop immediately. The default is 50.</value> + /// <remarks> + /// <para> + /// This is the only delay a connected client can impose on the application. While the queue + /// stays full it caps logging at 20 events per second, so set it to 0 to drop instead of + /// waiting. + /// </para> + /// </remarks> + /// <exception cref="ArgumentOutOfRangeException">The value specified is negative.</exception> + public int EnqueueTimeoutMillis + { + get => _enqueueTimeoutMillis; + set + { + if (value < 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for EnqueueTimeoutMillis is negative."); + } + _enqueueTimeoutMillis = value; + } + } + /// <summary> /// Gets or sets the address to listen on. /// </summary> @@ -166,10 +224,21 @@ protected override void OnClose() { base.OnClose(); + // Drain on a deadline, so a client that stopped reading cannot hold up shutdown. + if (_sender is BackgroundSender<string> sender) + { + _sender = null; + sender.Close(CloseTimeoutMillis); + sender.Dispose(); + } + _handler?.Dispose(); _handler = null; } + /// <inheritdoc/> + public override bool Flush(int millisecondsTimeout) => _sender?.Flush(millisecondsTimeout) ?? true; + /// <summary> /// This appender requires a <see cref="Layout"/> to be set. /// </summary> @@ -185,6 +254,7 @@ public override void ActivateOptions() { LogLog.Debug(_declaringType, $"Creating SocketHandler to listen on [{_listenAddress}]:[{_listeningPort}]"); _handler = new(_listenAddress, _listeningPort, _sendTimeoutMillis); + _sender = new(nameof(TelnetAppender), SendQueueSize, SendToClients, Report); } catch (Exception ex) { @@ -193,6 +263,26 @@ public override void ActivateOptions() } } + /// <summary> + /// Writes one rendered event to every client, on the background thread. + /// </summary> + private void SendToClients(string message, CancellationToken cancellationToken) => _handler?.Send(message); + + /// <summary> + /// Reports a send failure through the appender's error handler. + /// </summary> + private void Report(string message, Exception? exception) + { + if (exception is null) + { + ErrorHandler.Error(message); + } + else + { + ErrorHandler.Error(message, exception); + } + } + /// <summary> /// Writes the logging event to each connected client. /// </summary> @@ -201,7 +291,8 @@ protected override void Append(LoggingEvent loggingEvent) { if (_handler is not null && _handler.HasConnections) { - _handler.Send(RenderLoggingEvent(loggingEvent)); + // Queued, not written: a client that stops reading must not hold up the logging thread. + _sender?.TryEnqueue(RenderLoggingEvent(loggingEvent), EnqueueTimeoutMillis); } } diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/telnetappender.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/telnetappender.adoc index adc29c1e..d212dcdd 100644 --- a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/telnetappender.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/telnetappender.adoc @@ -64,11 +64,24 @@ How long, in milliseconds, a write to a client may block before that client is t and disconnected. The default is `5000`. + -Clients are written to synchronously while the appender lock is held, so a client that connects -and then stops reading lets TCP flow control fill its receive window. -A finite timeout bounds how long that client can hold up the threads that log through this -appender. -Setting the value to `0` restores blocking indefinitely and is not recommended. +Clients are written to from a background thread, so this no longer delays the application: it is +how long a client that stopped reading holds up the stream before it is dropped. +`0` blocks indefinitely and is not recommended. + +`sendQueueSize`:: +How many rendered events may wait to be written to the clients. +The default is `500`. ++ +A full queue drops the event from the telnet stream, counted and reported once. +Only the telnet view is lost; every other appender still receives the event. + +`enqueueTimeoutMillis`:: +How long, in milliseconds, a logging call may wait for room in the send queue. +The default is `50`. ++ +This is the only delay a client can impose on the application. +While the queue stays full it caps logging at 20 events per second, so set it to `0` to drop +instead of waiting. [#telnetappender-trust] == Intended use and trust model
