FreeAndNil commented on PR #331:
URL: https://github.com/apache/logging-log4net/pull/331#issuecomment-6122214142
Implementation plan for #331, kept here for the record. Revised after the
merge so that it describes the change as it landed.
<details>
<summary>Plan</summary>
# PR #331: stop reading every exception as a hung-up client
## The defect
`TelnetAppender.SocketHandler.Send`,
`src/log4net/Appender/TelnetAppender.cs:455`:
```csharp
try
{
client.Send(message);
}
catch (Exception e) when (!e.IsFatal())
{
// The client has closed the connection, remove it from our list
client.Dispose();
RemoveClient(client);
}
```
Any non-fatal exception is read as "this client hung up", and the client is
disconnected with
nothing written anywhere. That is how f013 turned into a mass disconnect: a
lone surrogate threw
while encoding, and every connected client was dropped in turn. f013 itself
is fixed at the source,
`SocketClient.Send` escapes through
`ContentEscape.EscapeUnpairedSurrogates`, but the catch that
misread it is untouched.
The agent instructions already name this: "A catch of `Exception` always
carries `when
(!e.IsFatal())`. The filter is not a licence to widen: a catch that handles
one expected exception
keeps naming that type."
Two commits: the fix, and a test-only pass over the provoked internal
logging.
## Why it is safe to narrow now, and was not before
Since #318 nothing calls `Send` on the logging thread. The path is
`Append` -> `_sender.TryEnqueue` -> `BackgroundSender<string>` pump ->
`SendToClients` ->
`_handler.Send`. The pump wraps the callback, `BackgroundSender.cs:261-264`:
```csharp
catch (Exception e) when (!e.IsFatal())
{
CountLost();
Report($"[{_name}] Failed to send a logging event.", e);
}
```
So an exception that escapes `Send` is counted, reported through the
appender's `ErrorHandler`, and
the pump carries on. The old reason to swallow everything, that a throw
would reach the
application, no longer holds.
## Commit 1: the change
`SocketHandler.Send`: two catch clauses in the loop over the clients.
- `catch (Exception e) when (e is SocketException or IOException or
ObjectDisposedException)`
disconnects, as before: the socket operations, what a `StreamWriter` over
a `NetworkStream`
wraps a `SocketException` in, and a client disposed concurrently by
`Dispose` or a second
failure. Only these mean the client is gone.
- `catch (Exception e) when (!e.IsFatal())` is our own bug. It captures the
first one as an
`ExceptionDispatchInfo` and the loop goes on, so the remaining clients are
still served; after
the loop `failure?.Throw()` raises it with its stack intact, and the pump
reports it.
The comment in the `SocketClient` constructor, which said that `Send` reads
a throw as a hung up
client, now says the escaping keeps a future gap costing one character
rather than failing the
write.
`SocketHandler` is `protected`, so a subclass calling `Send` sees those
exceptions where it saw
none. Say so in the commit message and the changelog.
## Commit 1: the test
`src/log4net.Tests/Appender/TelnetAppenderTest.cs`, NUnit 4, real sockets.
One new test,
`AnUnexpectedSendFailureKeepsTheClientConnected`: **an unexpected exception
from a send leaves
the client connected and still serves the others.** No black-box route
reaches it, since the three
narrowed types are the only ones a real socket raises, so drive the handler
directly through
`ReflectionExtensions`:
- Construct `SocketHandler` on the loopback address and a free port with
`NonPublicNestedType("SocketHandler").Construct<IDisposable>(...)`,
connect two `TcpClient`s and
wait, with a bounded poll over the private `_clients` list, until both are
registered.
- Replace the first client's `_writer` with a `StreamWriter` over an
`UnflushableStream`, a
`MemoryStream` whose `Flush` throws `NotSupportedException` while armed.
The first client fails
and the second shows that the loop ran to the end.
- `handler.Invoke("Send", [payload])` must throw with that inner exception,
the second client
must receive the payload, read with a bounded loop and a receive timeout,
and the client list
must still hold two. Disarm the stream in a `finally`, or disposing the
writer throws and hides
whichever assertion failed.
**Revert to fail**, in place, not with `git stash`: with the wide catch
back, the first client is
dropped and the throw never comes; with a rethrow inside the loop instead of
after it, the second
client never receives. Each half of the change fails the test on its own.
## The thing to note, not silently accept
`OnlyOnceErrorHandler` sets `IsEnabled = false` after the first error,
`OnlyOnceErrorHandler.cs:115`.
So under the default handler a genuine bug on this path is reported once and
every later one is as
silent as today. That is project-wide, not specific to this change, and
fixing it is not part of
#331.
## Commit 2: the internal logging that reaches the console
Unrelated to the catch, but test hygiene on the same rule, and small.
Measured on `net10.0`, the
suite emits ten `log4net:ERROR` or `WARN` lines that tests provoke on
purpose and let reach stderr.
Wrap each in `LogLog.ExecuteWithoutEmittingInternalMessages`, with a one
line comment saying the
message is provoked:
- `AdoNetAppenderTest.NoBufferingTest` and `BufferingTest`: no `CommandText`
and no `Layout`, both
warned about on purpose. The activation, the configuration and the logging
calls go inside the
wrapper, the assertions on the command stay outside.
- `XmlConfiguratorTest.ConfigureWithUnkownConfigFile` and
`LogLogTest.LogReceivedAdapter`: the
`LogReceivedAdapter` is fed either way, so the wrapper only keeps the
message off the console.
- `StringFormatTest.TestFormatString`: the deliberately broken format call.
Ten messages down to two. The two left are
`LogLogTest.EmitInternalMessages`, which asserts the
console output itself; a comment there says so. Do not wrap a message a test
does not intend to
provoke, find out why it is there instead.
Also in this commit: the agent instructions get the `ReflectionExtensions`
convention from #326,
replacing the sentence that pointed at the old `BindingFlags` pattern.
## Changelog
`src/changelog/3.5.0/331-telnet-unexpected-send-failure.xml`,
`type="fixed"`, both `id` and `link`
on `<issue>`. Prose, no bullets. Name what it means: an unexpected failure
while writing to a
Telnet client is now reported instead of silently disconnecting that client,
only the three
exception types disconnect, anything else is raised once the remaining
clients have been served,
and a `SocketHandler` subclass calling `Send` sees those exceptions where it
saw none. Close with
`(fixed by @FreeAndNil)`; there is no finding id, this came out of the #318
review.
## Verification
```
dotnet build src/log4net.sln # 0 warnings
dotnet test src/log4net.Tests/log4net.Tests.csproj
```
## House rules
Branch `Feature/331-telnet-send-failure` off local `master`, not from
`origin/master`. Leave the
work unstaged, write the commit messages to `.git/plans/331/commit-1.txt`
and `commit-2.txt` and
stop. The maintainer commits.
</details>
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
