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..67a48770 --- /dev/null +++ b/src/changelog/3.5.0/318-telnet-background-send.xml @@ -0,0 +1,15 @@ + + + + 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, `enqueueTimeoutMillis` caps logging at 20 events per second; set it to 0 to drop + immediately instead of waiting (audit da18b6fd-f014, implemented by @FreeAndNil) + diff --git a/src/changelog/3.5.0/318-telnet-loopback-default.xml b/src/changelog/3.5.0/318-telnet-loopback-default.xml new file mode 100644 index 00000000..2361c159 --- /dev/null +++ b/src/changelog/3.5.0/318-telnet-loopback-default.xml @@ -0,0 +1,13 @@ + + + + `TelnetAppender` now listens on `127.0.0.1` by default instead of every + interface. The stream is unauthenticated and unencrypted, so any host that could reach the port + could read the application's log, and every documented example already used loopback. Watching the + log from another machine is now opt-in: set `listenAddress` to `0.0.0.0` or `::` to restore the old + behaviour. The `SocketHandler(port, sendTimeoutMillis)` constructor defaults the same way (audit + da18b6fd-f012, implemented by @FreeAndNil) + diff --git a/src/log4net.Tests/Appender/AnsiColorTerminalAppenderTest.cs b/src/log4net.Tests/Appender/AnsiColorTerminalAppenderTest.cs index 222dce26..36806f03 100644 --- a/src/log4net.Tests/Appender/AnsiColorTerminalAppenderTest.cs +++ b/src/log4net.Tests/Appender/AnsiColorTerminalAppenderTest.cs @@ -22,6 +22,7 @@ using log4net.Appender; using log4net.Core; +using log4net.Tests.Appender.Internal; using log4net.Layout; using NUnit.Framework; @@ -82,23 +83,8 @@ public void TheResetCodesGoBeforeATrailingLineBreak(string message, string expec Console.SetOut(previous); } - Assert.That(errorHandler.Message, Is.Empty, "the event must not be dropped"); + Assert.That(errorHandler.Messages, Is.Empty, "the event must not be dropped"); Assert.That(captured.ToString(), Is.EqualTo(expected)); } - /// Collects what the appender reports, so a dropped event is visible. - private sealed class RecordingErrorHandler : IErrorHandler - { - /// Everything reported so far. - internal string Message { get; private set; } = string.Empty; - - /// - public void Error(string message) => Message += message + '\n'; - - /// - public void Error(string message, Exception e) => Message += message + '\n'; - - /// - public void Error(string message, Exception? e, ErrorCode errorCode) => Message += message + '\n'; - } } diff --git a/src/log4net.Tests/Appender/Internal/RecordingErrorHandler.cs b/src/log4net.Tests/Appender/Internal/RecordingErrorHandler.cs new file mode 100644 index 00000000..d851b586 --- /dev/null +++ b/src/log4net.Tests/Appender/Internal/RecordingErrorHandler.cs @@ -0,0 +1,44 @@ +#region Apache License +// +// Licensed to the Apache Software Foundation (ASF) under one or more +// contributor license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright ownership. +// The ASF licenses this file to you under the Apache License, Version 2.0 +// (the "License"); you may not use this file except in compliance with +// the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +#endregion + +using System; +using System.Collections.Generic; + +using log4net.Core; + +namespace log4net.Tests.Appender.Internal; + +/// +/// Collects what an appender reports instead of letting it reach the console, so a test can +/// assert on it and a provoked error adds no noise to the suite output. +/// +internal sealed class RecordingErrorHandler : IErrorHandler +{ + /// Reported messages, in the order they were reported. + internal List Messages { get; } = []; + + /// + public void Error(string message) => Messages.Add(message); + + /// + public void Error(string message, Exception e) => Messages.Add(message); + + /// + public void Error(string message, Exception? e, ErrorCode errorCode) => Messages.Add(message); +} 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; + /// + /// Connects, reads the welcome message and then stops reading, so this client's receive window + /// fills and writes to it block. The opposite of , for testing that a client + /// which stops reading cannot hold up the threads that log. + /// + 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); + } + /// /// Runs the client (in a task) /// diff --git a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs index 149d191b..9eb299a2 100644 --- a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs +++ b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs @@ -51,22 +51,6 @@ private sealed class RemoteAppender : RemoteSyslogAppender internal System.Net.Sockets.UdpClient? InheritedClient => Client; } - /// Collects reported errors instead of letting them reach the console. - private sealed class RecordingErrorHandler : IErrorHandler - { - /// Reported messages. - internal List Messages { get; } = []; - - /// - public void Error(string message, Exception? e, ErrorCode errorCode) => Messages.Add(message); - - /// - public void Error(string message, Exception e) => Messages.Add(message); - - /// - public void Error(string message) => Messages.Add(message); - } - private const int FlushTimeoutMillis = 30_000; /// diff --git a/src/log4net.Tests/Appender/SmtpAppenderTest.cs b/src/log4net.Tests/Appender/SmtpAppenderTest.cs index 259cfd9c..3489567a 100644 --- a/src/log4net.Tests/Appender/SmtpAppenderTest.cs +++ b/src/log4net.Tests/Appender/SmtpAppenderTest.cs @@ -18,7 +18,6 @@ #endregion using System; -using System.Collections.Generic; using System.Diagnostics; using System.Net; using System.Net.Sockets; @@ -27,9 +26,9 @@ using log4net.Appender; using log4net.Config; -using log4net.Core; using log4net.Layout; using log4net.Repository; +using log4net.Tests.Appender.Internal; using log4net.Util; using NUnit.Framework; @@ -120,19 +119,4 @@ public void AnUnresponsiveServerDoesNotStallTheLoggingCall() } } - /// Collects reported errors instead of letting them reach the console. - private sealed class RecordingErrorHandler : IErrorHandler - { - /// Reported messages. - internal List Messages { get; } = []; - - /// - public void Error(string message, Exception? e, ErrorCode errorCode) => Messages.Add(message); - - /// - public void Error(string message, Exception e) => Messages.Add(message); - - /// - public void Error(string message) => Messages.Add(message); - } } diff --git a/src/log4net.Tests/Appender/TelnetAppenderTest.cs b/src/log4net.Tests/Appender/TelnetAppenderTest.cs index c0df92b4..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; @@ -239,12 +241,158 @@ public void SendTimeoutMillisRejectsNegativeValuesButAllowsZero() } /// - /// The appender accepts connections on every interface unless told otherwise, which is the - /// behaviour it has always had. + /// The stream is unauthenticated, so an appender nobody configured an address for must not be + /// reachable from another machine. /// [Test] - public void ListenAddressDefaultsToEveryInterface() - => Assert.That(new TelnetAppender().ListenAddress, Is.EqualTo(IPAddress.Any)); + public void ListenAddressDefaultsToLoopback() + => Assert.That(new TelnetAppender().ListenAddress, Is.EqualTo(IPAddress.Loopback)); + + /// + /// Remote monitoring is still available, it just has to be asked for. + /// + [TestCase("::", TestName = "EveryIPv6InterfaceCanBeAskedFor")] + [TestCase("0.0.0.0", TestName = "EveryIPv4InterfaceCanBeAskedFor")] + public void EveryInterfaceCanBeAskedFor(string address) + => Assert.That(new TelnetAppender { ListenAddress = IPAddress.Parse(address) }.ListenAddress, + Is.EqualTo(IPAddress.Parse(address))); + + /// + /// 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. + /// + [Test] + public void SendQueueDefaults() + { + TelnetAppender appender = new(); + + Assert.That(appender.SendQueueSize, Is.EqualTo(500)); + Assert.That(appender.EnqueueTimeoutMillis, Is.EqualTo(50)); + } + + /// + /// A queue of no size cannot hold anything, and a negative wait has no meaning. + /// + [Test] + public void SendQueueSettingsRejectMeaninglessValues() + { + TelnetAppender appender = new(); + + Assert.That(() => appender.SendQueueSize = 0, Throws.TypeOf()); + Assert.That(() => appender.EnqueueTimeoutMillis = -1, Throws.TypeOf()); + + appender.EnqueueTimeoutMillis = 0; + Assert.That(appender.EnqueueTimeoutMillis, Is.EqualTo(0)); + } + + /// + /// 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. + /// + [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 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); + } + } + + /// + /// 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. + /// + [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" }); /// /// Binding to the loopback address has to keep the port unreachable from other machines, which diff --git a/src/log4net/Appender/TelnetAppender.cs b/src/log4net/Appender/TelnetAppender.cs index 903cd0d5..110a4908 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; @@ -37,10 +38,11 @@ namespace log4net.Appender; /// /// The TelnetAppender accepts socket connections and streams logging messages back to the client. /// The output is provided in a telnet-friendly way so that a log can be monitored over a TCP/IP socket. -/// This allows simple remote monitoring of application logging. /// /// -/// The default is 23 (the telnet port). +/// The default is 23 (the telnet port) and the default +/// is , so monitoring from another +/// machine has to be turned on deliberately. /// /// /// This appender is a diagnostic tool for trusted networks. As with any other appender @@ -54,23 +56,79 @@ namespace log4net.Appender; /// Nicko Cadell public class TelnetAppender : AppenderSkeleton { + private const int CloseTimeoutMillis = 5_000; + private SocketHandler? _handler; + private BackgroundSender? _sender; private int _listeningPort = 23; private int _sendTimeoutMillis = 5_000; - private IPAddress _listenAddress = IPAddress.Any; + private int _sendQueueSize = 500; + private int _enqueueTimeoutMillis = 50; + private IPAddress _listenAddress = IPAddress.Loopback; + + /// + /// Gets or sets how many rendered events may wait to be written to the clients. + /// + /// A positive number of events. The default is 500. + /// + /// + /// 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. + /// + /// + /// The value specified is not positive. + 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; + } + } + + /// + /// Gets or sets how long, in milliseconds, a logging call may wait for room in the send queue. + /// + /// A number of milliseconds, or 0 to drop immediately. The default is 50. + /// + /// + /// 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; 0 drops immediately instead of waiting. + /// + /// + /// The value specified is negative. + public int EnqueueTimeoutMillis + { + get => _enqueueTimeoutMillis; + set + { + if (value < 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for EnqueueTimeoutMillis is negative."); + } + _enqueueTimeoutMillis = value; + } + } /// /// Gets or sets the address to listen on. /// /// - /// The local address to accept connections on. The default is , every - /// interface of the machine. + /// The local address to accept connections on. The default is , + /// the machine the application runs on. /// /// /// - /// Set this to to accept connections only from the machine the - /// application runs on, which is what the diagnostic use this appender is meant for usually - /// needs. + /// The stream is unauthenticated and unencrypted, so reaching it from another machine is opt-in: + /// set this to or for that, and keep + /// untrusted parties away from the port. /// /// /// The value specified is . @@ -165,10 +223,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 sender) + { + _sender = null; + sender.Close(CloseTimeoutMillis); + sender.Dispose(); + } + _handler?.Dispose(); _handler = null; } + /// + public override bool Flush(int millisecondsTimeout) => _sender?.Flush(millisecondsTimeout) ?? true; + /// /// This appender requires a to be set. /// @@ -183,7 +252,8 @@ public override void ActivateOptions() try { LogLog.Debug(_declaringType, $"Creating SocketHandler to listen on [{_listenAddress}]:[{_listeningPort}]"); - _handler = new SocketHandler(_listenAddress, _listeningPort, _sendTimeoutMillis); + _handler = new(_listenAddress, _listeningPort, _sendTimeoutMillis); + _sender = new(nameof(TelnetAppender), SendQueueSize, SendToClients, Report); } catch (Exception ex) { @@ -192,6 +262,26 @@ public override void ActivateOptions() } } + /// + /// Writes one rendered event to every client, on the background thread. + /// + private void SendToClients(string message, CancellationToken cancellationToken) => _handler?.Send(message); + + /// + /// Reports a send failure through the appender's error handler. + /// + private void Report(string message, Exception? exception) + { + if (exception is null) + { + ErrorHandler.Error(message); + } + else + { + ErrorHandler.Error(message, exception); + } + } + /// /// Writes the logging event to each connected client. /// @@ -200,7 +290,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); } } @@ -325,11 +416,12 @@ public SocketHandler(int port) /// block before that client is disconnected, or 0 to block indefinitely /// /// - /// Creates a socket handler on the specified local server port. + /// Creates a socket handler on the specified local server port, listening on + /// . /// /// public SocketHandler(int port, int sendTimeoutMillis) - : this(IPAddress.Any, port, sendTimeoutMillis) + : this(IPAddress.Loopback, port, sendTimeoutMillis) { } /// 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 6751ca0c..9e01eade 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 @@ -51,10 +51,12 @@ The default is `23`, the telnet port. `listenAddress`:: The local address to accept connections on. -The default is `0.0.0.0`, every interface of the machine. +The default is `127.0.0.1`, the machine the application runs on, which is what diagnostic use +usually needs. + -Set it to `127.0.0.1` to accept connections only from the machine the application runs on, which is -what diagnostic use usually needs. +The stream is unauthenticated and unencrypted, so watching it from another machine is opt-in: set +this to `0.0.0.0` for every IPv4 interface, or `::` for every IPv6 one, and keep untrusted parties +away from the port. An IPv6 address may be given instead, and the listening socket follows its family. `sendTimeoutMillis`:: @@ -62,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; `0` drops immediately instead +of waiting. [#telnetappender-trust] == Intended use and trust model @@ -82,17 +97,17 @@ The appender therefore performs no authentication of its own. [WARNING] ==== -The connection is *unauthenticated* and *unencrypted*, and by default the appender listens on *all -network interfaces*. +The connection is *unauthenticated* and *unencrypted*. There is no option to require a credential or to enable TLS. Any client that can reach the port receives the full rendered log stream, including whatever the layout renders: user names, session identifiers, request parameters, stack traces. -Keeping untrusted parties away from the port is the operator's responsibility, exactly as it is -for a log file: +The appender listens on `127.0.0.1` only, so that stays on the local machine until you widen +`listenAddress`, and keeping untrusted parties away from the port is then the operator's +responsibility, exactly as it is for a log file: -* Set `listenAddress` to `127.0.0.1` unless clients on other machines really have to connect. -* Only enable this appender on a trusted network. +* Widen `listenAddress` only if clients on other machines really have to connect. +* Only do so on a trusted network. * Restrict access to the port with a host firewall or network policy. * Prefer it for local or short-lived diagnostics rather than as a permanent logging destination. ====