From 2d40819c6b24f65cbb47fb649ce6210c05b0f62e Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Sun, 27 Sep 2026 23:18:17 +0200 Subject: [PATCH 1/2] report an unexpected Telnet send failure instead of dropping the client #331 SocketHandler.Send read every non-fatal exception as a hung up connection, so a defect in what we write cost every client in turn. That is how f013 became a mass disconnect. * Only SocketException, IOException and ObjectDisposedException disconnect. Anything else is raised after the loop and reported by BackgroundSender. * SocketHandler is protected, so a subclass calling Send sees exceptions it did not before. --- CLAUDE.md | 11 ++- .../331-telnet-unexpected-send-failure.xml | 15 +++ .../Appender/TelnetAppenderTest.cs | 97 +++++++++++++++++++ src/log4net/Appender/TelnetAppender.cs | 15 ++- 4 files changed, 132 insertions(+), 6 deletions(-) create mode 100644 src/changelog/3.5.0/331-telnet-unexpected-send-failure.xml diff --git a/CLAUDE.md b/CLAUDE.md index 8792b2c3..8d847051 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -140,9 +140,14 @@ almost always be doing. with `[SetUp]`/`[TearDown]` for per-test state. - Use an expression body for a single-statement test: `public void X() => Assert.That(...);`. - **`log4net` has no `InternalsVisibleTo`**, so private and internal members are exercised through - reflection, not by widening their accessibility. See `SystemInfoTest`, `LevelMappingTest` and - `UserNameFixingTest` for the `BindingFlags.Static | BindingFlags.NonPublic` pattern. - `log4net.Ext.Mail` does grant `InternalsVisibleTo` to its own test project. + reflection, not by widening their accessibility. `log4net.Ext.Mail` does grant + `InternalsVisibleTo` to its own test project. +- **That reflection goes through `ReflectionExtensions`** in `src/log4net.Tests/Util/`, namespace + `log4net.Tests`, so no test spells out `BindingFlags` itself: `NonPublicNestedType`, + `Construct`, `Invoke`, `GetFieldValue`, `SetFieldValue`, on a `Type` for the static + members and on an instance for the instance ones. Pass the arguments as an explicit `[a, b]`; + an expanded `params` argument trips CS8620 in a C# 14 extension block, which + `WarningsAsErrors=nullable` makes a build error. - **NUnit constructs one fixture instance for the whole fixture**, so an instance field that records what a test observed accumulates across the tests in it. Clear such state in `[SetUp]`. - Drive a test over a background thread with gates (`ManualResetEventSlim`), never with diff --git a/src/changelog/3.5.0/331-telnet-unexpected-send-failure.xml b/src/changelog/3.5.0/331-telnet-unexpected-send-failure.xml new file mode 100644 index 00000000..f409494d --- /dev/null +++ b/src/changelog/3.5.0/331-telnet-unexpected-send-failure.xml @@ -0,0 +1,15 @@ + + + + + report an unexpected failure while writing to a Telnet client instead of disconnecting it. + `TelnetAppender` read every non-fatal exception as a hung up connection, so a defect in what was + written cost the connection of every client in turn. Only `SocketException`, `IOException` and + `ObjectDisposedException` disconnect now; anything else is raised once the remaining clients have + been served and is reported through the error handler. `SocketHandler` is protected, so a subclass + calling `Send` sees those exceptions where it saw none (fixed by @FreeAndNil) + + diff --git a/src/log4net.Tests/Appender/TelnetAppenderTest.cs b/src/log4net.Tests/Appender/TelnetAppenderTest.cs index bd5f2572..5a06c23e 100644 --- a/src/log4net.Tests/Appender/TelnetAppenderTest.cs +++ b/src/log4net.Tests/Appender/TelnetAppenderTest.cs @@ -18,8 +18,10 @@ #endregion using System; +using System.Collections; using System.Collections.Generic; using System.Diagnostics; +using System.IO; using System.Net; using System.Net.Sockets; using System.Text; @@ -437,6 +439,101 @@ public void ListenAddressBindsOnlyThatAddress() } } + /// + /// A write can fail for a reason that is not a dead client, which once cost every client at once. + /// + [Test] + public void AnUnexpectedSendFailureKeepsTheClientConnected() + { + int port = FindFreeTcpPort(); + Type handlerType = typeof(TelnetAppender).NonPublicNestedType("SocketHandler"); + using IDisposable handler = handlerType.Construct([IPAddress.Loopback, port, 0]); + + using TcpClient first = new(); + using TcpClient second = new(); + first.Connect(IPAddress.Loopback, port); + second.Connect(IPAddress.Loopback, port); + WaitForClients(2); + + // Only the first client fails, so the second one shows the loop ran to the end. + object firstClient = Clients()[0]!; + using UnflushableStream poison = new(); + using StreamWriter poisonedWriter = new(poison); + firstClient.SetFieldValue("_writer", poisonedWriter); + + const string payload = "the second client must still get this"; + try + { + Assert.That(() => handler.Invoke("Send", [payload]), + Throws.InnerException.TypeOf()); + Assert.That(ReadFrom(second), Does.Contain(payload), "the failing client stopped the send"); + Assert.That(Clients(), Has.Count.EqualTo(2), "a client was dropped over our own bug"); + } + finally + { + // Or disposing the writer below throws and hides whichever assertion failed. + poison.FailOnFlush = false; + } + + IList Clients() => handler.GetFieldValue("_clients"); + + string ReadFrom(TcpClient client) + { + StringBuilder text = new(); + client.ReceiveTimeout = (int)_receiveTimeout.TotalMilliseconds; + byte[] buffer = new byte[512]; + Stopwatch stopwatch = Stopwatch.StartNew(); + while (!text.ToString().Contains(payload, StringComparison.Ordinal) && stopwatch.Elapsed < _receiveTimeout) + { + int read; + try + { + read = client.GetStream().Read(buffer, 0, buffer.Length); + } + catch (IOException) + { + // Nothing arrived, so return what did and let the assertion say what was missing. + break; + } + + if (read == 0) + { + // The peer closed, so no more is coming. + break; + } + + text.Append(Encoding.UTF8.GetString(buffer, 0, read)); + } + return text.ToString(); + } + + void WaitForClients(int expected) + { + Stopwatch stopwatch = Stopwatch.StartNew(); + while (Clients().Count < expected && stopwatch.Elapsed < _receiveTimeout) + { + Thread.Sleep(10); + } + Assert.That(Clients(), Has.Count.EqualTo(expected), "the clients did not connect"); + } + } + + /// A stream that takes writes and refuses to flush them while armed. + private sealed class UnflushableStream : MemoryStream + { + /// Whether a flush fails. Disarm before disposing the writer that holds it. + internal bool FailOnFlush { get; set; } = true; + + /// + public override void Flush() + { + if (FailOnFlush) + { + throw new NotSupportedException(); + } + } + } + /// /// Asks the OS for a currently unused TCP port - a fixed port would collide with /// other tests or processes on the build machine. diff --git a/src/log4net/Appender/TelnetAppender.cs b/src/log4net/Appender/TelnetAppender.cs index 110a4908..ff7600f2 100644 --- a/src/log4net/Appender/TelnetAppender.cs +++ b/src/log4net/Appender/TelnetAppender.cs @@ -21,6 +21,7 @@ using System.Collections.Generic; using System.Net; using System.Net.Sockets; +using System.Runtime.ExceptionServices; using System.Text; using System.IO; using System.Linq; @@ -339,7 +340,7 @@ public SocketClient(Socket socket) try { // Belt and braces. Send escapes what cannot be encoded; this keeps a future gap costing - // one character rather than every client, since Send reads a throw as a hung up client. + // one character rather than failing the write. _writer = new(new NetworkStream(socket), new UTF8Encoding(false)); } catch (Exception e) when (!e.IsFatal()) @@ -461,19 +462,27 @@ public void Send(string message) } // Send outside lock. + ExceptionDispatchInfo? failure = null; foreach (SocketClient client in localClients) { try { client.Send(message); } - catch (Exception e) when (!e.IsFatal()) + catch (Exception e) when (e is SocketException or IOException or ObjectDisposedException) { - // The client has closed the connection, remove it from our list + // Only these mean the client is gone. client.Dispose(); RemoveClient(client); } + catch (Exception e) when (!e.IsFatal()) + { + // Our own bug. Serve the rest, then let the background sender report it. + failure ??= ExceptionDispatchInfo.Capture(e); + } } + + failure?.Throw(); } /// From 977832e45ebb00b54b0b358d93e1d69ab016699e Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Sun, 27 Sep 2026 23:20:55 +0200 Subject: [PATCH 2/2] keep the provoked internal logging out of the test output #331 Five tests provoked log4net:ERROR or WARN on purpose and let it reach stderr. * AdoNetAppenderTest twice, XmlConfiguratorTest, LogLogTest and StringFormatTest once each. * Ten messages down to two. The two left are LogLogTest.EmitInternalMessages, which asserts the console output itself. --- .../Appender/AdoNetAppenderTest.cs | 34 ++++++++++++------- .../Config/XmlConfiguratorTest.cs | 4 ++- src/log4net.Tests/Core/StringFormatTest.cs | 5 ++- src/log4net.Tests/Util/LogLogTest.cs | 11 ++++-- 4 files changed, 37 insertions(+), 17 deletions(-) diff --git a/src/log4net.Tests/Appender/AdoNetAppenderTest.cs b/src/log4net.Tests/Appender/AdoNetAppenderTest.cs index c03f99b4..fd30f72f 100644 --- a/src/log4net.Tests/Appender/AdoNetAppenderTest.cs +++ b/src/log4net.Tests/Appender/AdoNetAppenderTest.cs @@ -47,12 +47,17 @@ public void NoBufferingTest() BufferSize = -1, ConnectionType = typeof(Log4NetConnection).AssemblyQualifiedName! }; - adoNetAppender.ActivateOptions(); + // No CommandText and no Layout, both warned about on purpose. + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + adoNetAppender.ActivateOptions(); - BasicConfigurator.Configure(rep, adoNetAppender); + BasicConfigurator.Configure(rep, adoNetAppender); + + ILog log = LogManager.GetLogger(rep.Name, "NoBufferingTest"); + log.Debug("Message"); + }); - ILog log = LogManager.GetLogger(rep.Name, "NoBufferingTest"); - log.Debug("Message"); Assert.That(Log4NetCommand.MostRecentInstance, Is.Not.Null); Assert.That(Log4NetCommand.MostRecentInstance.ExecuteNonQueryCount, Is.EqualTo(1)); } @@ -69,17 +74,22 @@ public void BufferingTest() BufferSize = bufferSize, ConnectionType = typeof(Log4NetConnection).AssemblyQualifiedName! }; - adoNetAppender.ActivateOptions(); + // No CommandText and no Layout, both warned about on purpose. + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + adoNetAppender.ActivateOptions(); - BasicConfigurator.Configure(rep, adoNetAppender); + BasicConfigurator.Configure(rep, adoNetAppender); - ILog log = LogManager.GetLogger(rep.Name, "BufferingTest"); - for (int i = 0; i < bufferSize; i++) - { + ILog log = LogManager.GetLogger(rep.Name, "BufferingTest"); + for (int i = 0; i < bufferSize; i++) + { + log.Debug("Message"); + Assert.That(Log4NetCommand.MostRecentInstance, Is.Null); + } log.Debug("Message"); - Assert.That(Log4NetCommand.MostRecentInstance, Is.Null); - } - log.Debug("Message"); + }); + Assert.That(Log4NetCommand.MostRecentInstance, Is.Not.Null); Assert.That(Log4NetCommand.MostRecentInstance.ExecuteNonQueryCount, Is.EqualTo(bufferSize + 1)); } diff --git a/src/log4net.Tests/Config/XmlConfiguratorTest.cs b/src/log4net.Tests/Config/XmlConfiguratorTest.cs index 51988c72..5e94222d 100644 --- a/src/log4net.Tests/Config/XmlConfiguratorTest.cs +++ b/src/log4net.Tests/Config/XmlConfiguratorTest.cs @@ -48,7 +48,9 @@ public void ConfigureWithUnkownConfigFile() List configurationMessages = []; using LogLog.LogReceivedAdapter _ = new(configurationMessages); - typeof(XmlConfigurator).Invoke("InternalConfigure", [repository, getConfigSection]); + // The adapter is fed either way, so this only keeps it off the console. + LogLog.ExecuteWithoutEmittingInternalMessages( + () => typeof(XmlConfigurator).Invoke("InternalConfigure", [repository, getConfigSection])); Assert.That(configurationMessages, Has.Count.EqualTo(1)); Assert.That(configurationMessages[0].Message, Contains.Substring(SystemInfo.EntryAssemblyLocation + ".config")); diff --git a/src/log4net.Tests/Core/StringFormatTest.cs b/src/log4net.Tests/Core/StringFormatTest.cs index b6879b7e..fd94e6dd 100644 --- a/src/log4net.Tests/Core/StringFormatTest.cs +++ b/src/log4net.Tests/Core/StringFormatTest.cs @@ -24,6 +24,7 @@ using log4net.Core; using log4net.Layout; using log4net.Repository; +using log4net.Util; using log4net.Tests.Appender; using NUnit.Framework; @@ -105,7 +106,9 @@ public void TestFormatString() stringAppender.Reset(); // *** - log1.InfoFormat("IGNORE THIS WARNING - EXCEPTION EXPECTED Before {0} After {1} {2}", "Middle", "End"); + // Provoked on purpose, so keep it off the console. + LogLog.ExecuteWithoutEmittingInternalMessages(() => + log1.InfoFormat("IGNORE THIS WARNING - EXCEPTION EXPECTED Before {0} After {1} {2}", "Middle", "End")); Assert.That(stringAppender.GetString(), Is.EqualTo(StringFormatError), "Test formatting error"); stringAppender.Reset(); diff --git a/src/log4net.Tests/Util/LogLogTest.cs b/src/log4net.Tests/Util/LogLogTest.cs index 94acb385..6875efcd 100644 --- a/src/log4net.Tests/Util/LogLogTest.cs +++ b/src/log4net.Tests/Util/LogLogTest.cs @@ -58,6 +58,7 @@ public void EmitInternalMessages() TraceListenerCounter listTraceListener = new(); Trace.Listeners.Clear(); Trace.Listeners.Add(listTraceListener); + // Emitting is the subject here, so these two reach the console by design. LogLog.Error(GetType(), "Hello"); LogLog.Error(GetType(), "World"); Trace.Flush(); @@ -86,9 +87,13 @@ public void LogReceivedAdapter() List messages = []; using LogLog.LogReceivedAdapter _ = new(messages); - LogLog.Debug(GetType(), "Won't be recorded"); - LogLog.Error(GetType(), "This will be recorded."); - LogLog.Error(GetType(), "This will be recorded."); + // The adapter is fed either way, so this only keeps it off the console. + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + LogLog.Debug(GetType(), "Won't be recorded"); + LogLog.Error(GetType(), "This will be recorded."); + LogLog.Error(GetType(), "This will be recorded."); + }); Assert.That(messages, Has.Count.EqualTo(2)); }