Prevent Telnet clients reaching or stalling the application

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, `enqueueTimeoutMillis` caps logging at 20 events per second; set it to 0 to drop
+  immediately instead of waiting (audit da18b6fd-f014, implemented by @FreeAndNil)</description>
+</entry>

src/changelog/3.5.0/318-telnet-loopback-default.xml

@@ -0,0 +1,13 @@
+<?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">`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)</description>
+</entry>

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));
   }
 
-  /// <summary>Collects what the appender reports, so a dropped event is visible.</summary>
-  private sealed class RecordingErrorHandler : IErrorHandler
-  {
-    /// <summary>Everything reported so far.</summary>
-    internal string Message { get; private set; } = string.Empty;
-
-    /// <inheritdoc/>
-    public void Error(string message) => Message += message + '\n';
-
-    /// <inheritdoc/>
-    public void Error(string message, Exception e) => Message += message + '\n';
-
-    /// <inheritdoc/>
-    public void Error(string message, Exception? e, ErrorCode errorCode) => Message += message + '\n';
-  }
 }

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;
+
+/// <summary>
+/// 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.
+/// </summary>
+internal sealed class RecordingErrorHandler : IErrorHandler
+{
+  /// <summary>Reported messages, in the order they were reported.</summary>
+  internal List<string> Messages { get; } = [];
+
+  /// <inheritdoc/>
+  public void Error(string message) => Messages.Add(message);
+
+  /// <inheritdoc/>
+  public void Error(string message, Exception e) => Messages.Add(message);
+
+  /// <inheritdoc/>
+  public void Error(string message, Exception? e, ErrorCode errorCode) => Messages.Add(message);
+}

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>

src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs

@@ -51,22 +51,6 @@ private sealed class RemoteAppender : RemoteSyslogAppender
     internal System.Net.Sockets.UdpClient? InheritedClient => Client;
   }
 
-  /// <summary>Collects reported errors instead of letting them reach the console.</summary>
-  private sealed class RecordingErrorHandler : IErrorHandler
-  {
-    /// <summary>Reported messages.</summary>
-    internal List<string> Messages { get; } = [];
-
-    /// <inheritdoc/>
-    public void Error(string message, Exception? e, ErrorCode errorCode) => Messages.Add(message);
-
-    /// <inheritdoc/>
-    public void Error(string message, Exception e) => Messages.Add(message);
-
-    /// <inheritdoc/>
-    public void Error(string message) => Messages.Add(message);
-  }
-
   private const int FlushTimeoutMillis = 30_000;
 
   /// <summary>

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()
     }
   }
 
-  /// <summary>Collects reported errors instead of letting them reach the console.</summary>
-  private sealed class RecordingErrorHandler : IErrorHandler
-  {
-    /// <summary>Reported messages.</summary>
-    internal List<string> Messages { get; } = [];
-
-    /// <inheritdoc/>
-    public void Error(string message, Exception? e, ErrorCode errorCode) => Messages.Add(message);
-
-    /// <inheritdoc/>
-    public void Error(string message, Exception e) => Messages.Add(message);
-
-    /// <inheritdoc/>
-    public void Error(string message) => Messages.Add(message);
-  }
 }

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()
   }
 
   /// <summary>
-  /// 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.
   /// </summary>
   [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));
+
+  /// <summary>
+  /// Remote monitoring is still available, it just has to be asked for.
+  /// </summary>
+  [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)));
+
+  /// <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