Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
11 changes: 8 additions & 3 deletions CLAUDE.md
Original file line number Diff line number Diff line change
Expand Up @@ -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<T>`, `Invoke<T>`, `GetFieldValue<T>`, `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
Expand Down
15 changes: 15 additions & 0 deletions src/changelog/3.5.0/331-telnet-unexpected-send-failure.xml
Original file line number Diff line number Diff line change
@@ -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="fixed">
<issue id="331" link="https://github.com/apache/logging-log4net/pull/331"/>
<description format="asciidoc">
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)
</description>
</entry>
34 changes: 22 additions & 12 deletions src/log4net.Tests/Appender/AdoNetAppenderTest.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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));
}
Expand All @@ -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));
}
Expand Down
97 changes: 97 additions & 0 deletions src/log4net.Tests/Appender/TelnetAppenderTest.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -437,6 +439,101 @@ public void ListenAddressBindsOnlyThatAddress()
}
}

/// <summary>
/// A write can fail for a reason that is not a dead client, which once cost every client at once.
/// </summary>
[Test]
public void AnUnexpectedSendFailureKeepsTheClientConnected()
{
int port = FindFreeTcpPort();
Type handlerType = typeof(TelnetAppender).NonPublicNestedType("SocketHandler");
using IDisposable handler = handlerType.Construct<IDisposable>([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<NotSupportedException>());
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<IList>("_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");
}
}

/// <summary>A stream that takes writes and refuses to flush them while armed.</summary>
private sealed class UnflushableStream : MemoryStream
{
/// <summary>Whether a flush fails. Disarm before disposing the writer that holds it.</summary>
internal bool FailOnFlush { get; set; } = true;

/// <inheritdoc/>
public override void Flush()
{
if (FailOnFlush)
{
throw new NotSupportedException();
}
}
}

/// <summary>
/// Asks the OS for a currently unused TCP port - a fixed port would collide with
/// other tests or processes on the build machine.
Expand Down
4 changes: 3 additions & 1 deletion src/log4net.Tests/Config/XmlConfiguratorTest.cs
Original file line number Diff line number Diff line change
Expand Up @@ -48,7 +48,9 @@ public void ConfigureWithUnkownConfigFile()
List<LogLog> 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"));
Expand Down
5 changes: 4 additions & 1 deletion src/log4net.Tests/Core/StringFormatTest.cs
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@
using log4net.Core;
using log4net.Layout;
using log4net.Repository;
using log4net.Util;
using log4net.Tests.Appender;

using NUnit.Framework;
Expand Down Expand Up @@ -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();

Expand Down
11 changes: 8 additions & 3 deletions src/log4net.Tests/Util/LogLogTest.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down Expand Up @@ -86,9 +87,13 @@ public void LogReceivedAdapter()
List<LogLog> 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));
}
Expand Down
15 changes: 12 additions & 3 deletions src/log4net/Appender/TelnetAppender.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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())
Expand Down Expand Up @@ -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();
}

/// <summary>
Expand Down
Loading