Stop network appenders stalling and losing events by FreeAndNil · Pull Request #314 · apache/logging-log4net

FreeAndNil · 2026-09-01T19:09:36Z

Follow-ups from the second security scan, on top of #313.

Adds log4net.Util.BackgroundSender: one sending thread, a bounded queue,
shutdown under a single deadline, counted losses, and a Flush that can answer
honestly. The MailKit SmtpAppender and RemoteSyslogAppender use it.

Both SmtpAppenders bound one send to 15s. MailKit's own timeout is per
operation, not a budget, so the MailKit one uses a CancellationToken deadline:
measured 14.2s overall against a 3s per-operation timeout.
RemoteSyslogAppender replaces its own pump, whose queue was unbounded and whose
connect sat outside the guard, so a failure there ended it unobserved. It also
stops opening a second UDP socket it never used.
AdoNetAppender: the 3.4.0 per-event retry cost 513 round trips for a batch that
fails outright, measured. Capped at five consecutive failures.
Flush(int) now reports false when events are still buffered, which is what a
lossy appender always is.
BackgroundSender is public but [EditorBrowsable(Never)] - because log4net.Ext.Mail is deliberately not strong named and so cannot be a friend assembly.

Behaviour changes worth a look: mail failures reach the error handler after the
logging call has returned, queued mail is lost if the process is killed, and
Flush returns false where it returned true.

Also renames the unreleased 3.4.1 to 3.5.0, since this adds public API.

An appender sends while it holds the appender lock, so a slow sink stalls the logging call and every thread queued behind it. BackgroundSender hands the work to one thread with a bounded queue: the caller waits at most the enqueue timeout. It avoids what the RemoteSyslogAppender pump gets wrong. The queue is bounded, the whole pump body is guarded so a fault cannot pass unobserved, Close drains under one deadline and then cancels the send in flight, and drops are counted and reported. Flush(timeout) can answer honestly because its marker travels in the queue. Nothing the pump thread calls may throw, the error handler included, since an escaping exception there would take the process down. No appender uses it yet.

The next release adds public API, so it is a minor one. scripts/update-version.ps1 assumes the old version is the released one, so it also set Log4NetPackageVersion and the examples version to 3.4.1; both belong at 3.4.0. package-lock.json is not covered by the script at all.

Tests had no access to IsFatal or the EnsureNotNull family and hand-rolled the checks instead. Linking it needs NotNullAttribute and ValidatedNotNullAttribute too, or the compiler reports CS0122.

SmtpClient.Timeout defaults to 100 seconds and the appender never set it. The mail goes out under the appender lock, so a server that accepts the connection and then stops answering suspended every thread logging through the appender for two minutes. There is no value meaning "wait forever": SmtpClient rejects a negative timeout and treats 0 as "do not wait", so SendTimeoutMillis rejects both.

An appender sends while it holds the appender lock, so a slow sink stalls the logging call and every thread queued behind it. BackgroundSender hands the work to one thread with a bounded queue: the caller waits at most the enqueue timeout. It avoids what the RemoteSyslogAppender pump gets wrong. The queue is bounded, the whole pump body is guarded so a fault cannot pass unobserved, Close drains under one deadline and then cancels the send in flight, and drops are counted and reported. Flush(timeout) can answer honestly because its marker travels in the queue. Nothing the pump thread calls may throw, the error handler included, since an escaping exception there would take the process down. No appender uses it yet.

The next release adds public API, so it is a minor one. scripts/update-version.ps1 assumes the old version is the released one, so it also set Log4NetPackageVersion and the examples version to 3.4.1; both belong at 3.4.0. package-lock.json is not covered by the script at all.

Tests had no access to IsFatal or the EnsureNotNull family and hand-rolled the checks instead. Linking it needs NotNullAttribute and ValidatedNotNullAttribute too, or the compiler reports CS0122.

SmtpClient.Timeout defaults to 100 seconds and the appender never set it. The mail goes out under the appender lock, so a server that accepts the connection and then stops answering suspended every thread logging through the appender for two minutes. There is no value meaning "wait forever": SmtpClient rejects a negative timeout and treats 0 as "do not wait", so SendTimeoutMillis rejects both.

MailKit waits 100 seconds per operation by default and the mail goes out under the appender lock, so an unresponsive server suspended every thread logging through it. SendTimeoutMillis is a deadline for the whole send, passed as a CancellationToken: a per operation timeout still permits a multiple of itself overall. Measured, a server delaying 2s per step finished in 14.2s against a 3s per operation timeout, and in 3.1s against a 3s deadline. Disconnect keeps no token, as it runs in the finally and would otherwise replace the failure that got us there.

The mail went out under the appender lock, so the thread that logged, and every thread behind it, waited for the SMTP server. It is now handed to a BackgroundSender holding at most SendQueueSize mails (500), and a logging call waits at most EnqueueTimeoutMillis (5000) for room. Behaviour changes: failures reach the error handler after the logging call has returned, queued mail is lost if the process is killed, and Flush now honours its timeout. A failed send no longer reports the queue-pressure message as well, which was wrong: nothing was dropped for lack of room.

Flush(int) returned true unconditionally. For a lossy appender, flushing does nothing at all and every buffered event stays in the buffer, so the answer was simply untrue. The timeout stays unused and is now documented as such: IFlushable already says it only applies to appenders that send asynchronously.

The appender sends through the connection its pump owns and never touched the one inherited from UdpAppender, so that socket existed only to bind localPort a second time and be closed again at shutdown. Connecting also moved inside the guard, with a message of its own. It sat outside, so a failure ended the pump unobserved and every later event queued behind a sender that was no longer running.

The appender's own pump held an unbounded queue, so a syslog server that stopped accepting datagrams grew it until the process ran out of memory. Shutdown waited five seconds and then abandoned a drain that had no limit of its own. It now holds SendQueueSize datagrams (500), a logging call waits at most EnqueueTimeoutMillis (5000) for room, losses are counted, and Flush honours its timeout: this appender sends asynchronously, so unlike a buffering one the timeout means something here.

Retrying after a rolled back transaction was added in 3.4.0 to save the events around the one the database rejected. A batch that fails outright, a missing table or permission, then cost one round trip per event: measured 21 for a batch of 20, so 513 for a full buffer where there had been 1. It gives up after five consecutive failures. Failures spread through a batch do not count towards that, so a single rejected event still costs only itself. SendBuffer contains per-event failures and returns normally, so the retry loop had no way to tell one from a success. A private flag gives it one.

It is the re-opened 1231d72-f009, which the second scan reports as a prior fix that was incomplete rather than as a new finding. da18b6f-f004 is the Ext.Mail batch loss and has nothing to do with it. The other 19 citations across 3.4.0 and 3.5.0 were checked against both reports and match.

Flush(bool) only moves the buffer into the queue; Flush(int) waits for the sender. The test used the first and asserted immediately, so it passed on Linux and failed on macOS and Windows. RequiresALayout asserted that nothing was sent without waiting either, which an asynchronous send makes true regardless.