From a6d28365ffd7d7e91f4bed0d2183365bad568f96 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 21:06:49 +0200 Subject: [PATCH 01/12] add a background sender for appenders that do network I/O #314 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. --- .../Util/BackgroundSenderTest.cs | 304 +++++++++++++++ src/log4net/Util/BackgroundSender.cs | 349 ++++++++++++++++++ 2 files changed, 653 insertions(+) create mode 100644 src/log4net.Tests/Util/BackgroundSenderTest.cs create mode 100644 src/log4net/Util/BackgroundSender.cs diff --git a/src/log4net.Tests/Util/BackgroundSenderTest.cs b/src/log4net.Tests/Util/BackgroundSenderTest.cs new file mode 100644 index 00000000..ab2174a8 --- /dev/null +++ b/src/log4net.Tests/Util/BackgroundSenderTest.cs @@ -0,0 +1,304 @@ +#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 System.Diagnostics; +using System.Linq; +using System.Threading; + +using log4net.Util; + +using NUnit.Framework; + +namespace log4net.Tests.Util; + +/// +/// Tests for . +/// +[TestFixture] +public class BackgroundSenderTest +{ + /// How long a test waits for the background thread before calling it a failure. + private const int WaitMillis = 30_000; + + private readonly List _sent = []; + private readonly List _reported = []; + + /// + /// NUnit reuses one fixture instance for every test in it, so the recordings have to be + /// cleared between them. + /// + [SetUp] + public void ClearRecordings() + { + lock (_sent) + { + _sent.Clear(); + } + + lock (_reported) + { + _reported.Clear(); + } + } + + private int[] Sent + { + get + { + lock (_sent) + { + return [.. _sent]; + } + } + } + + private void Record(int item) + { + lock (_sent) + { + _sent.Add(item); + } + } + + private void Report(string message, Exception? exception) + { + lock (_reported) + { + _reported.Add(message); + } + } + + private BackgroundSender CreateSender(int capacity, Action send) + => new("test", capacity, send, Report); + + /// + /// A queue without room for at least one item cannot work. + /// + [TestCase(0)] + [TestCase(-1)] + public void ConstructorRejectsCapacityBelowOne(int capacity) + => Assert.That(() => CreateSender(capacity, (_, _) => { }), + Throws.TypeOf()); + + /// + /// One thread delivers, so order is the order the items were queued in. + /// + [Test] + public void ItemsAreSentInTheOrderTheyWereQueued() + { + const int itemCount = 100; + using BackgroundSender sender = CreateSender(itemCount, (item, _) => Record(item)); + + for (int i = 0; i < itemCount; i++) + { + Assert.That(sender.TryEnqueue(i, WaitMillis), Is.True); + } + + Assert.That(sender.Flush(WaitMillis), Is.True); + Assert.That(Sent, Is.EqualTo(Enumerable.Range(0, itemCount).ToArray())); + Assert.That(sender.DroppedItemCount, Is.EqualTo(0)); + } + + /// + /// A full queue must not hold the logging call up when the caller allows no wait. + /// + [Test] + [System.Diagnostics.CodeAnalysis.SuppressMessage("Reliability", "CA2016:Forward the CancellationToken parameter to methods that take one", + Justification = "Stands for a sink that does not cooperate with cancellation.")] + public void AFullQueueDropsInsteadOfBlockingTheCaller() + { + using ManualResetEventSlim sendEntered = new(false); + using ManualResetEventSlim release = new(false); + using BackgroundSender sender = CreateSender(2, (item, _) => + { + sendEntered.Set(); + release.Wait(WaitMillis); + Record(item); + }); + + // Park the only sending thread, so that nothing leaves the queue from here on. + Assert.That(sender.TryEnqueue(1, WaitMillis), Is.True); + Assert.That(sendEntered.Wait(WaitMillis), Is.True); + + // Fill the two slots, then prove the next one is dropped rather than waited for. + Assert.That(sender.TryEnqueue(2, WaitMillis), Is.True); + Assert.That(sender.TryEnqueue(3, WaitMillis), Is.True); + + Stopwatch stopwatch = Stopwatch.StartNew(); + Assert.That(sender.TryEnqueue(4, 0), Is.False); + stopwatch.Stop(); + + Assert.That(sender.DroppedItemCount, Is.EqualTo(1)); + Assert.That(stopwatch.ElapsedMilliseconds, Is.LessThan(WaitMillis)); + + release.Set(); + Assert.That(sender.Flush(WaitMillis), Is.True); + Assert.That(Sent, Is.EqualTo(new[] { 1, 2, 3 })); + } + + /// + /// Closing sends what is still queued, rather than discarding it like the popped batch did. + /// + [Test] + public void CloseSendsWhatIsStillQueued() + { + const int itemCount = 10; + BackgroundSender sender = CreateSender(itemCount, (item, _) => Record(item)); + try + { + for (int i = 0; i < itemCount; i++) + { + Assert.That(sender.TryEnqueue(i, WaitMillis), Is.True); + } + + sender.Close(WaitMillis); + Assert.That(Sent, Has.Length.EqualTo(itemCount)); + Assert.That(sender.DroppedItemCount, Is.EqualTo(0)); + } + finally + { + sender.Dispose(); + } + } + + /// + /// An unresponsive sink must not make closing the appender hang. What is left is dropped, + /// counted and reported. + /// + [Test] + public void CloseGivesUpOnAnUnresponsiveSink() + { + const int closeTimeoutMillis = 200; + using ManualResetEventSlim sendEntered = new(false); + BackgroundSender sender = CreateSender(5, (item, token) => + { + sendEntered.Set(); + // Answers only when Close runs out of patience and cancels. + token.WaitHandle.WaitOne(WaitMillis); + Record(item); + }); + try + { + Assert.That(sender.TryEnqueue(1, WaitMillis), Is.True); + Assert.That(sendEntered.Wait(WaitMillis), Is.True); + Assert.That(sender.TryEnqueue(2, WaitMillis), Is.True); + Assert.That(sender.TryEnqueue(3, WaitMillis), Is.True); + + Stopwatch stopwatch = Stopwatch.StartNew(); + sender.Close(closeTimeoutMillis); + stopwatch.Stop(); + + Assert.That(stopwatch.ElapsedMilliseconds, Is.LessThan(WaitMillis)); + Assert.That(sender.DroppedItemCount, Is.EqualTo(2)); + Assert.That(_reported, Is.Not.Empty); + } + finally + { + sender.Dispose(); + } + } + + /// + /// Once the sender has stopped, queueing fails instead of filling a queue nobody empties. + /// + [Test] + public void NothingIsAcceptedAfterClose() + { + BackgroundSender sender = CreateSender(5, (item, _) => Record(item)); + try + { + sender.Close(WaitMillis); + + Assert.That(sender.IsFaulted, Is.True); + Assert.That(sender.TryEnqueue(1, WaitMillis), Is.False); + Assert.That(sender.Flush(WaitMillis), Is.False); + Assert.That(Sent, Is.Empty); + } + finally + { + sender.Dispose(); + } + } + + /// + /// A send that throws costs its own item and nothing else. + /// + [Test] + public void AFailedSendDoesNotStopTheOnesAfterIt() + { + using BackgroundSender sender = CreateSender(10, (item, _) => + { + if (item == 1) + { + throw new InvalidOperationException("simulated send failure"); + } + + Record(item); + }); + + for (int i = 0; i < 4; i++) + { + Assert.That(sender.TryEnqueue(i, WaitMillis), Is.True); + } + + Assert.That(sender.Flush(WaitMillis), Is.True); + Assert.That(Sent, Is.EqualTo(new[] { 0, 2, 3 })); + Assert.That(sender.DroppedItemCount, Is.EqualTo(1)); + } + + /// + /// An error handler that throws must not take the sending thread, and with it the process, down. + /// + [Test] + [NonParallelizable] + public void AnErrorHandlerThatThrowsDoesNotStopTheSender() + { + List internalMessages = []; + + // The sender is disposed inside the wrapped action, because closing it reports the drop + // total through the same throwing handler. + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + using LogLog.LogReceivedAdapter adapter = new(internalMessages); + using BackgroundSender sender = new("test", 10, (item, _) => + { + if (item == 1) + { + throw new InvalidOperationException("simulated send failure"); + } + + Record(item); + }, + (_, _) => throw new InvalidOperationException("simulated error handler failure")); + + for (int i = 0; i < 4; i++) + { + Assert.That(sender.TryEnqueue(i, WaitMillis), Is.True); + } + + Assert.That(sender.Flush(WaitMillis), Is.True); + Assert.That(sender.IsFaulted, Is.False); + }); + + Assert.That(Sent, Is.EqualTo(new[] { 0, 2, 3 })); + Assert.That(internalMessages, Is.Not.Empty); + } +} diff --git a/src/log4net/Util/BackgroundSender.cs b/src/log4net/Util/BackgroundSender.cs new file mode 100644 index 00000000..833b3ccd --- /dev/null +++ b/src/log4net/Util/BackgroundSender.cs @@ -0,0 +1,349 @@ +#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.Concurrent; +using System.ComponentModel; +using System.Threading; +using System.Threading.Tasks; + +namespace log4net.Util; + +/// +/// Hands work to a single background thread so that an appender does not perform +/// slow I/O while it holds the appender lock. +/// +/// The type of the queued work items. +/// +/// +/// An appender that sends over the network blocks the thread that made the logging call, +/// and every other thread logging to the same appender behind it, for as long as the sink +/// takes to answer. Queueing the work instead bounds that wait to the enqueue timeout. +/// +/// +/// The queue has a fixed capacity. Work is delivered in the order it was queued, by one +/// thread, so a send implementation does not need to be thread safe. Items that could not +/// be queued or sent are counted in . +/// +/// +/// Public only because log4net.Ext.Mail is deliberately not strong named and so cannot be +/// a friend assembly. It is infrastructure, not part of the surface an application configures. +/// +/// +[EditorBrowsable(EditorBrowsableState.Never)] +public sealed class BackgroundSender : IDisposable +{ + private readonly BlockingCollection _queue; + private readonly Action _send; + private readonly Action _reportError; + private readonly string _name; + private readonly Thread _pump; + private readonly CancellationTokenSource _shutdown = new(); + private int _droppedItemCount; + private int _dropReported; + private int _faultReported; + private volatile bool _isFaulted; + + /// + /// Creates a queue and starts its background thread. + /// + /// Name of the owning appender, used in error messages. + /// The maximum number of items the queue holds. Must be positive. + /// + /// Delivers one item. Called on the background thread only. May throw: the exception is + /// reported and the item dropped. The token is cancelled once has run + /// out of time, so an implementation that can abort its I/O should pass it on. + /// + /// Reports a message and its optional exception, typically to an error handler. + public BackgroundSender(string name, int capacity, Action send, + Action reportError) + { + _name = name.EnsureNotNull(); + _send = send.EnsureNotNull(); + _reportError = reportError.EnsureNotNull(); + if (capacity <= 0) + { + throw new ArgumentOutOfRangeException(nameof(capacity), capacity, "The capacity must be positive."); + } + + _queue = new(capacity); + _pump = new(Pump) + { + IsBackground = true, + Name = $"log4net {name} sender" + }; + _pump.Start(); + } + + /// + /// The number of items that were not delivered, because the queue was full, closed or faulted, + /// or because sending them threw. + /// + public int DroppedItemCount => Volatile.Read(ref _droppedItemCount); + + /// + /// Whether the background thread has stopped for good. Nothing more will be delivered. + /// + public bool IsFaulted => _isFaulted; + + /// + /// Queues one item for delivery. + /// + /// The item to deliver. + /// + /// How long to wait for room in a full queue. Zero returns immediately, which loses the item + /// rather than delaying the logging call. + /// + /// if the item was queued, if it was dropped. + public bool TryEnqueue(T item, int millisecondsTimeout) + { + if (!_isFaulted) + { + try + { + if (_queue.TryAdd(new Item(item), millisecondsTimeout)) + { + return true; + } + } + catch (Exception e) when (!e.IsFatal()) + { + // Closed, or CompleteAdding ran, while this call was in flight. + } + } + + CountDrop(); + return false; + } + + /// + /// Waits until everything queued before this call has been sent. + /// + /// The maximum time to wait. + /// + /// if the queue drained in time, on timeout + /// or if the background thread is no longer running. + /// + /// + /// + /// A marker is placed at the end of the queue and awaited, so a caller is not held up by + /// items queued after it asked. + /// + /// + public bool Flush(int millisecondsTimeout) + { + if (_isFaulted) + { + return false; + } + + TaskCompletionSource marker = new(TaskCreationOptions.RunContinuationsAsynchronously); + int startTicks = Environment.TickCount; + try + { + if (!_queue.TryAdd(new Item(marker), millisecondsTimeout)) + { + return false; + } + } + catch (Exception e) when (!e.IsFatal()) + { + // Closed while this call was in flight. + return false; + } + + return marker.Task.Wait(Remaining(startTicks, millisecondsTimeout)); + } + + /// + /// Stops the queue, sending what is still in it until the time runs out. + /// + /// The maximum time to spend draining. + /// + /// + /// Never throws. Once the time is up the send in flight is cancelled and the remaining items + /// are counted as dropped, so closing an appender cannot hang on an unresponsive sink. + /// + /// + public void Close(int millisecondsTimeout) + { + try + { + _queue.CompleteAdding(); + if (!_pump.Join(Math.Max(millisecondsTimeout, 0))) + { + // Out of time: stop the send in flight and let the pump drop the rest. + _shutdown.Cancel(); + _pump.Join(CancelGraceMillis); + } + } + catch (Exception e) when (!e.IsFatal()) + { + Report($"[{_name}] Failed to shut the background sender down.", e); + } + + int dropped = DroppedItemCount; + if (dropped > 0) + { + Report($"[{_name}] {dropped} logging event(s) were not sent.", null); + } + } + + /// + public void Dispose() + { + Close(0); + + // Disposing these while the pump still runs would throw on the pump thread, which is + // an unhandled exception. If it did not stop in time, leave them to the finalizers. + if (!_pump.IsAlive) + { + _shutdown.Dispose(); + _queue.Dispose(); + } + } + + /// + /// Reports without ever throwing. An supplied by a caller may + /// throw, and on the pump thread that would be an unhandled exception. + /// + private void Report(string message, Exception? exception) + { + try + { + _reportError(message, exception); + } + catch (Exception e) when (!e.IsFatal()) + { + LogLog.Error(_declaringType, $"[{_name}] The error handler threw.", e); + } + } + + private void Pump() + { + try + { + foreach (Item item in _queue.GetConsumingEnumerable()) + { + if (item.Marker is TaskCompletionSource marker) + { + marker.TrySetResult(true); + continue; + } + + if (_shutdown.IsCancellationRequested) + { + // Closing and out of time. Drain the queue without sending, so that Close returns. + CountDrop(); + continue; + } + + try + { + _send(item.Payload!, _shutdown.Token); + } + catch (Exception e) when (!e.IsFatal()) + { + CountDrop(); + Report($"[{_name}] Failed to send a logging event.", e); + } + } + } + catch (Exception e) when (!e.IsFatal()) + { + // Nothing will be sent from here on, so say so once and let TryEnqueue fail fast + // instead of filling a queue that nobody empties. + _isFaulted = true; + if (Interlocked.Exchange(ref _faultReported, 1) == 0) + { + Report($"[{_name}] The background sender stopped. No further events will be sent.", e); + } + } + finally + { + _isFaulted = true; + ReleaseWaiters(); + } + } + + /// + /// Releases anyone waiting in once the pump is gone, rather than + /// letting them wait out their timeout for a marker that will never be reached. + /// + private void ReleaseWaiters() + { + try + { + while (_queue.TryTake(out Item item)) + { + if (item.Marker is TaskCompletionSource marker) + { + marker.TrySetResult(true); + } + else + { + CountDrop(); + } + } + } + catch (Exception e) when (!e.IsFatal()) + { + // The queue may already be disposed. Nothing left to release. + LogLog.Debug(_declaringType, $"[{_name}] Could not drain the queue on shutdown.", e); + } + } + + private void CountDrop() + { + Interlocked.Increment(ref _droppedItemCount); + if (Interlocked.Exchange(ref _dropReported, 1) == 0) + { + Report($"[{_name}] A logging event was dropped. The sink is not keeping up or is unreachable. " + + "Further drops are counted and reported when the appender closes.", null); + } + } + + private static int Remaining(int startTicks, int millisecondsTimeout) + { + if (millisecondsTimeout == Timeout.Infinite) + { + return Timeout.Infinite; + } + + int elapsed = unchecked(Environment.TickCount - startTicks); + return Math.Max(millisecondsTimeout - elapsed, 0); + } + + private const int CancelGraceMillis = 1_000; + + private static readonly Type _declaringType = typeof(BackgroundSender); + + /// + /// Either a payload or a flush marker: markers travel in the queue so that they observe + /// the order the items were queued in. + /// + private readonly record struct Item(T? Payload, TaskCompletionSource? Marker) + { + internal Item(T payload) : this(payload, null) + { } + + internal Item(TaskCompletionSource marker) : this(default, marker) + { } + } +} From 2c9a14aa129adddcd088a002f5f0fe29db9c207d Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 21:28:42 +0200 Subject: [PATCH 02/12] rename the unreleased 3.4.1 to 3.5.0 #314 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. --- doc/MailTemplate.Announce.txt | 10 +++++----- doc/MailTemplate.Result.txt | 4 ++-- doc/MailTemplate.txt | 6 +++--- package-lock.json | 4 ++-- package.json | 2 +- pom.xml | 2 +- scripts/build-preview.ps1 | 2 +- scripts/build-release.ps1 | 2 +- src/Directory.Build.props | 2 +- src/changelog/{3.4.1 => 3.5.0}/.release-notes.adoc.ftl | 0 src/changelog/{3.4.1 => 3.5.0}/.release.xml | 4 ++-- .../162-quiet-app-settings-in-a-native-host.xml | 0 .../313-redact-connection-string-allowlist.xml | 0 .../{3.4.1 => 3.5.0}/313-require-powershell-74.xml | 0 .../313-verify-release-keys-bypass.xml | 0 .../modules/ROOT/partials/supported-versions.adoc | 2 +- 16 files changed, 20 insertions(+), 20 deletions(-) rename src/changelog/{3.4.1 => 3.5.0}/.release-notes.adoc.ftl (100%) rename src/changelog/{3.4.1 => 3.5.0}/.release.xml (83%) rename src/changelog/{3.4.1 => 3.5.0}/162-quiet-app-settings-in-a-native-host.xml (100%) rename src/changelog/{3.4.1 => 3.5.0}/313-redact-connection-string-allowlist.xml (100%) rename src/changelog/{3.4.1 => 3.5.0}/313-require-powershell-74.xml (100%) rename src/changelog/{3.4.1 => 3.5.0}/313-verify-release-keys-bypass.xml (100%) diff --git a/doc/MailTemplate.Announce.txt b/doc/MailTemplate.Announce.txt index 16cc17ff..1a240b07 100644 --- a/doc/MailTemplate.Announce.txt +++ b/doc/MailTemplate.Announce.txt @@ -1,16 +1,16 @@ To: announce@apache.org, dev@logging.apache.org -Subject: [ANNOUNCE] Apache log4net 3.4.1 released +Subject: [ANNOUNCE] Apache log4net 3.5.0 released Hi, -the Apache log4net team is pleased to announce the 3.4.1 release. +the Apache log4net team is pleased to announce the 3.5.0 release. For further information (support, download, etc.) see - https://logging.apache.org/log4net/release-notes.html -- https://github.com/apache/logging-log4net/releases/tag/rel%2F3.4.1 -- https://www.nuget.org/packages/log4net/3.4.1 -- https://www.nuget.org/packages/log4net.Ext.Mail/3.4.1 +- https://github.com/apache/logging-log4net/releases/tag/rel%2F3.5.0 +- https://www.nuget.org/packages/log4net/3.5.0 +- https://www.nuget.org/packages/log4net.Ext.Mail/3.5.0 Highlights of this release: diff --git a/doc/MailTemplate.Result.txt b/doc/MailTemplate.Result.txt index 1fced0d7..cb5bd438 100644 --- a/doc/MailTemplate.Result.txt +++ b/doc/MailTemplate.Result.txt @@ -1,5 +1,5 @@ To: dev@logging.apache.org -Subject: [RESULT][VOTE] Release Apache Log4net 3.4.1 +Subject: [RESULT][VOTE] Release Apache Log4net 3.5.0 and here is my +1. @@ -9,6 +9,6 @@ I will continue the release process. Jan --------------------------------------------------------------------------------------------------- -This is a vote to release the Apache Log4net 3.4.1. +This is a vote to release the Apache Log4net 3.5.0. ... diff --git a/doc/MailTemplate.txt b/doc/MailTemplate.txt index 51b1bc53..43e3480e 100644 --- a/doc/MailTemplate.txt +++ b/doc/MailTemplate.txt @@ -1,12 +1,12 @@ To: dev@logging.apache.org -Subject: [VOTE] Release Apache Log4net 3.4.1 +Subject: [VOTE] Release Apache Log4net 3.5.0 -This is a vote to release the Apache Log4net 3.4.1. +This is a vote to release the Apache Log4net 3.5.0. Website: https://logging.staged.apache.org/log4net/release-notes.html GitHub: https://github.com/apache/logging-log4net Commit: -Distribution: https://dist.apache.org/repos/dist/dev/logging/log4net/3.4.1 +Distribution: https://dist.apache.org/repos/dist/dev/logging/log4net/3.5.0 Signing key: 0x7D24496A230E29D6349A99EF583E491578F02D5D Review kit: https://logging.staged.apache.org/log4net/release-review.html diff --git a/package-lock.json b/package-lock.json index 20a6862c..ddbe14eb 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1,12 +1,12 @@ { "name": "log4net", - "version": "3.4.1", + "version": "3.5.0", "lockfileVersion": 3, "requires": true, "packages": { "": { "name": "log4net", - "version": "3.4.1", + "version": "3.5.0", "license": "Apache-2.0", "devDependencies": { "@antora/cli": "^3.2.0-rc.2", diff --git a/package.json b/package.json index 5c751db7..f64eacca 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "log4net", - "version": "3.4.1", + "version": "3.5.0", "description": "Log4Net is a logging framework for .NET", "repository": { "type": "git", diff --git a/pom.xml b/pom.xml index 08b56804..b3ac80f1 100644 --- a/pom.xml +++ b/pom.xml @@ -25,7 +25,7 @@ pom org.apache.logging.log4net apache-log4net - 3.4.1 + 3.5.0 Apache log4net Logging framework for Microsoft .NET Framework. https://logging.apache.org/log4net diff --git a/scripts/build-preview.ps1 b/scripts/build-preview.ps1 index 7c6926ad..4b535934 100644 --- a/scripts/build-preview.ps1 +++ b/scripts/build-preview.ps1 @@ -1,7 +1,7 @@ #Requires -Version 7.4 param( - $Version = '3.4.1', + $Version = '3.5.0', $Preview = '1' ) diff --git a/scripts/build-release.ps1 b/scripts/build-release.ps1 index d5bbfd51..de2f0c1e 100644 --- a/scripts/build-release.ps1 +++ b/scripts/build-release.ps1 @@ -1,7 +1,7 @@ #Requires -Version 7.4 param( - $Version = '3.4.1' + $Version = '3.5.0' ) Set-StrictMode -Version Latest diff --git a/src/Directory.Build.props b/src/Directory.Build.props index 90cfaa4b..5b60be69 100644 --- a/src/Directory.Build.props +++ b/src/Directory.Build.props @@ -22,7 +22,7 @@ $(NoWarn);CS1591 - 3.4.1 + 3.5.0 3.4.0 4.17.0 4.5.0 diff --git a/src/changelog/3.4.1/.release-notes.adoc.ftl b/src/changelog/3.5.0/.release-notes.adoc.ftl similarity index 100% rename from src/changelog/3.4.1/.release-notes.adoc.ftl rename to src/changelog/3.5.0/.release-notes.adoc.ftl diff --git a/src/changelog/3.4.1/.release.xml b/src/changelog/3.5.0/.release.xml similarity index 83% rename from src/changelog/3.4.1/.release.xml rename to src/changelog/3.5.0/.release.xml index 85240f86..4bba497b 100644 --- a/src/changelog/3.4.1/.release.xml +++ b/src/changelog/3.5.0/.release.xml @@ -2,5 +2,5 @@ \ No newline at end of file + date="2026-11-01" + version="3.5.0"/> \ No newline at end of file diff --git a/src/changelog/3.4.1/162-quiet-app-settings-in-a-native-host.xml b/src/changelog/3.5.0/162-quiet-app-settings-in-a-native-host.xml similarity index 100% rename from src/changelog/3.4.1/162-quiet-app-settings-in-a-native-host.xml rename to src/changelog/3.5.0/162-quiet-app-settings-in-a-native-host.xml diff --git a/src/changelog/3.4.1/313-redact-connection-string-allowlist.xml b/src/changelog/3.5.0/313-redact-connection-string-allowlist.xml similarity index 100% rename from src/changelog/3.4.1/313-redact-connection-string-allowlist.xml rename to src/changelog/3.5.0/313-redact-connection-string-allowlist.xml diff --git a/src/changelog/3.4.1/313-require-powershell-74.xml b/src/changelog/3.5.0/313-require-powershell-74.xml similarity index 100% rename from src/changelog/3.4.1/313-require-powershell-74.xml rename to src/changelog/3.5.0/313-require-powershell-74.xml diff --git a/src/changelog/3.4.1/313-verify-release-keys-bypass.xml b/src/changelog/3.5.0/313-verify-release-keys-bypass.xml similarity index 100% rename from src/changelog/3.4.1/313-verify-release-keys-bypass.xml rename to src/changelog/3.5.0/313-verify-release-keys-bypass.xml diff --git a/src/site/antora/modules/ROOT/partials/supported-versions.adoc b/src/site/antora/modules/ROOT/partials/supported-versions.adoc index fe4a816a..00233dce 100644 --- a/src/site/antora/modules/ROOT/partials/supported-versions.adoc +++ b/src/site/antora/modules/ROOT/partials/supported-versions.adoc @@ -25,7 +25,7 @@ | 3.x | **[active]#Active#** -| 3.4.1 +| 3.5.0 | 2024-09-12 | | From 225dea0fa4d2766b72c382e43997e953b43dacae Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 21:28:58 +0200 Subject: [PATCH 03/12] link Log4NetAssert into the test project #314 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. --- src/log4net.Tests/log4net.Tests.csproj | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/log4net.Tests/log4net.Tests.csproj b/src/log4net.Tests/log4net.Tests.csproj index 38b00638..50ee6553 100644 --- a/src/log4net.Tests/log4net.Tests.csproj +++ b/src/log4net.Tests/log4net.Tests.csproj @@ -22,6 +22,9 @@ + + + From ff8c00aaa2cb4155758f13be5e9729e4f73905f6 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 21:29:35 +0200 Subject: [PATCH 04/12] bound a send in SmtpAppender to 15 seconds #314 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. --- .../3.5.0/314-smtpappender-send-timeout.xml | 13 ++ .../Appender/SmtpAppenderTest.cs | 138 ++++++++++++++++++ src/log4net/Appender/SmtpAppender.cs | 24 +++ 3 files changed, 175 insertions(+) create mode 100644 src/changelog/3.5.0/314-smtpappender-send-timeout.xml create mode 100644 src/log4net.Tests/Appender/SmtpAppenderTest.cs diff --git a/src/changelog/3.5.0/314-smtpappender-send-timeout.xml b/src/changelog/3.5.0/314-smtpappender-send-timeout.xml new file mode 100644 index 00000000..17fa2805 --- /dev/null +++ b/src/changelog/3.5.0/314-smtpappender-send-timeout.xml @@ -0,0 +1,13 @@ + + + + + bound a single send in `SmtpAppender` to 15 seconds. `SmtpClient.Timeout` defaults to 100 + seconds and the appender never set it, and the mail goes out while the appender lock is held, so + a server that accepted the connection and then stopped answering suspended every thread logging + through the appender. Configurable with `SendTimeoutMillis` (implemented by @FreeAndNil) + + diff --git a/src/log4net.Tests/Appender/SmtpAppenderTest.cs b/src/log4net.Tests/Appender/SmtpAppenderTest.cs new file mode 100644 index 00000000..259cfd9c --- /dev/null +++ b/src/log4net.Tests/Appender/SmtpAppenderTest.cs @@ -0,0 +1,138 @@ +#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 System.Diagnostics; +using System.Net; +using System.Net.Sockets; +using System.Threading; +using System.Threading.Tasks; + +using log4net.Appender; +using log4net.Config; +using log4net.Core; +using log4net.Layout; +using log4net.Repository; +using log4net.Util; + +using NUnit.Framework; + +namespace log4net.Tests.Appender; + +#pragma warning disable CS0618 // obsolete, but still shipped + +/// +/// Tests for . +/// +[TestFixture] +public class SmtpAppenderTest +{ + /// An unbounded send stalls every thread logging through the appender. + [Test] + public void SendTimeoutMillisDefaultsToFifteenSeconds() + => Assert.That(new SmtpAppender().SendTimeoutMillis, Is.EqualTo(15_000)); + + /// treats 0 as "do not wait". + [TestCase(0)] + [TestCase(-1)] + public void SendTimeoutMillisRejectsValuesThatAreNotPositive(int value) + => Assert.That(() => new SmtpAppender().SendTimeoutMillis = value, + Throws.TypeOf()); + + /// A silent server must not hold the logging call for the 100 second default. + [Test] + [System.Diagnostics.CodeAnalysis.SuppressMessage("Reliability", "CA2000:Dispose objects before losing scope", + Justification = "TcpListener is not IDisposable on net462. Stop() in the finally.")] + public void AnUnresponsiveServerDoesNotStallTheLoggingCall() + { + const int sendTimeoutMillis = 1_000; + const int generousBoundMillis = 30_000; + + using ManualResetEventSlim finished = new(false); + TcpListener listener = new(IPAddress.Loopback, 0); + listener.Start(); + int port = ((IPEndPoint)listener.LocalEndpoint).Port; + + // Accepts, then stays silent: the greeting never comes. + Task stub = Task.Run(() => + { + try + { + using TcpClient client = listener.AcceptTcpClient(); + finished.Wait(generousBoundMillis); + } + catch (Exception e) when (!e.IsFatal()) + { + // Stopped while the accept was pending. + } + }); + + RecordingErrorHandler errorHandler = new(); + try + { + SmtpAppender appender = new() + { + SmtpHost = "127.0.0.1", + Port = port, + From = "from@example.com", + To = "to@example.com", + Subject = "test", + BufferSize = 1, + Layout = new PatternLayout("%message"), + SendTimeoutMillis = sendTimeoutMillis, + ErrorHandler = errorHandler + }; + appender.ActivateOptions(); + + ILoggerRepository repository = LogManager.CreateRepository(Guid.NewGuid().ToString()); + BasicConfigurator.Configure(repository, appender); + ILog log = LogManager.GetLogger(repository.Name, nameof(AnUnresponsiveServerDoesNotStallTheLoggingCall)); + + Stopwatch stopwatch = Stopwatch.StartNew(); + log.Error("Message"); + stopwatch.Stop(); + + Assert.That(stopwatch.ElapsedMilliseconds, Is.LessThan(generousBoundMillis)); + Assert.That(errorHandler.Messages, Is.Not.Empty); + } + finally + { + finished.Set(); + listener.Stop(); + stub.Wait(generousBoundMillis); + } + } + + /// Collects reported errors instead of letting them reach the console. + private sealed class RecordingErrorHandler : IErrorHandler + { + /// Reported messages. + internal List Messages { get; } = []; + + /// + public void Error(string message, Exception? e, ErrorCode errorCode) => Messages.Add(message); + + /// + public void Error(string message, Exception e) => Messages.Add(message); + + /// + public void Error(string message) => Messages.Add(message); + } +} diff --git a/src/log4net/Appender/SmtpAppender.cs b/src/log4net/Appender/SmtpAppender.cs index 65dc221a..face8aec 100644 --- a/src/log4net/Appender/SmtpAppender.cs +++ b/src/log4net/Appender/SmtpAppender.cs @@ -295,6 +295,28 @@ protected override void SendBuffer(LoggingEvent[] events) /// protected override bool RequiresLayout => true; + /// + /// How long one send may take before it is abandoned. Defaults to 15000. + /// + /// + /// The mail goes out under the appender lock, and + /// waits 100 seconds by default. There is no "wait forever" value: 0 means "do not wait". + /// + /// The value specified is not positive. + public int SendTimeoutMillis + { + get => _sendTimeoutMillis; + set + { + if (value <= 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for SendTimeoutMillis is not positive."); + } + _sendTimeoutMillis = value; + } + } + /// /// Send the email message /// @@ -312,6 +334,7 @@ protected virtual void SendEmail(string messageBody) smtpClient.Port = Port; smtpClient.DeliveryMethod = SmtpDeliveryMethod.Network; smtpClient.EnableSsl = EnableSsl; + smtpClient.Timeout = SendTimeoutMillis; if (Authentication == SmtpAuthentication.Basic) { @@ -349,6 +372,7 @@ protected virtual void SendEmail(string messageBody) smtpClient.Send(mailMessage); } + private int _sendTimeoutMillis = 15_000; private string? _to; private string? _cc; private string? _bcc; From a7f6ad499416a0ec4a89b3fb203a2d6caa1c52d3 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 21:38:50 +0200 Subject: [PATCH 05/12] bound a send in the MailKit SmtpAppender to 15 seconds #314 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. --- .../3.5.0/314-ext-mail-send-timeout.xml | 14 ++++++ .../Appender/FakeSmtpTransport.cs | 29 +++++++++-- .../Appender/SmtpAppenderTest.cs | 50 +++++++++++++++++++ .../Appender/Internal/ISmtpTransport.cs | 19 +++++-- .../Appender/Internal/MailKitSmtpTransport.cs | 22 ++++++-- src/log4net.Ext.Mail/Appender/SmtpAppender.cs | 36 +++++++++++-- .../configuration/appenders/smtpappender.adoc | 6 +++ 7 files changed, 159 insertions(+), 17 deletions(-) create mode 100644 src/changelog/3.5.0/314-ext-mail-send-timeout.xml diff --git a/src/changelog/3.5.0/314-ext-mail-send-timeout.xml b/src/changelog/3.5.0/314-ext-mail-send-timeout.xml new file mode 100644 index 00000000..2a8a0469 --- /dev/null +++ b/src/changelog/3.5.0/314-ext-mail-send-timeout.xml @@ -0,0 +1,14 @@ + + + + + bound a whole send in the MailKit based `SmtpAppender` to 15 seconds. MailKit waits 100 seconds + per operation by default, and the mail goes out while the appender lock is held, so an + unresponsive server suspended every thread logging through the appender. `SendTimeoutMillis` is a + deadline for the send as a whole, because a per operation timeout still allows a multiple of + itself overall (implemented by @FreeAndNil) + + diff --git a/src/log4net.Ext.Mail.Tests/Appender/FakeSmtpTransport.cs b/src/log4net.Ext.Mail.Tests/Appender/FakeSmtpTransport.cs index 47ba1e5f..a8f50c3d 100644 --- a/src/log4net.Ext.Mail.Tests/Appender/FakeSmtpTransport.cs +++ b/src/log4net.Ext.Mail.Tests/Appender/FakeSmtpTransport.cs @@ -21,6 +21,7 @@ using System.Collections.Generic; using System.Linq; using System.Net; +using System.Threading; using System.Text; using log4net.Ext.Mail.Appender.Internal; @@ -67,36 +68,46 @@ internal sealed class FakeSmtpTransport : ISmtpTransport /// internal Exception? SendException { get; set; } + /// When set, every call that takes a token waits this long, honouring it. + internal int DelayMillisPerCall { get; set; } + + public int Timeout { get; set; } + public bool IsConnected { get; private set; } public bool IsAuthenticated { get; private set; } - public void Connect(string host, int port, SecureSocketOptions secureSocketOptions) + public void Connect(string host, int port, SecureSocketOptions secureSocketOptions, + CancellationToken cancellationToken) { Calls.Add(nameof(Connect)); + Delay(cancellationToken); ConnectedHost = host; ConnectedPort = port; SecureSocketOptions = secureSocketOptions; IsConnected = true; } - public void Authenticate(ICredentials credentials) + public void Authenticate(ICredentials credentials, CancellationToken cancellationToken) { Calls.Add(nameof(Authenticate)); + Delay(cancellationToken); Credentials = credentials; IsAuthenticated = true; } - public void Authenticate(SaslMechanism mechanism) + public void Authenticate(SaslMechanism mechanism, CancellationToken cancellationToken) { Calls.Add(nameof(Authenticate)); + Delay(cancellationToken); SaslMechanism = mechanism; IsAuthenticated = true; } - public void Send(MimeMessage message) + public void Send(MimeMessage message, CancellationToken cancellationToken) { Calls.Add(nameof(Send)); + Delay(cancellationToken); if (SendException is Exception exception) { throw exception; @@ -116,6 +127,16 @@ public void Dispose() Calls.Add(nameof(Dispose)); IsDisposed = true; } + + private void Delay(CancellationToken cancellationToken) + { + if (DelayMillisPerCall > 0) + { + cancellationToken.WaitHandle.WaitOne(DelayMillisPerCall); + } + + cancellationToken.ThrowIfCancellationRequested(); + } } /// diff --git a/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs b/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs index 33810395..5d0dae3b 100644 --- a/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs +++ b/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs @@ -21,6 +21,7 @@ using System.Collections.Generic; using System.Net; using System.Net.Mail; +using System.Diagnostics; using System.Text; using log4net.Core; using log4net.Ext.Mail.Appender; @@ -615,4 +616,53 @@ public void DefaultConstructorUsesTheMailKitTransport() Assert.That(appender.BodyEncoding, Is.EqualTo(Encoding.UTF8)); Assert.That(appender.EnableSsl, Is.False); } + + /// An unbounded send stalls every thread logging through the appender. + [Test] + public void SendTimeoutMillisDefaultsToFifteenSeconds() + => Assert.That(CreateAppender().SendTimeoutMillis, Is.EqualTo(15_000)); + + /// Neither 0 nor a negative value is a usable deadline. + [TestCase(0)] + [TestCase(-1)] + public void SendTimeoutMillisRejectsValuesThatAreNotPositive(int value) + => Assert.That(() => CreateAppender().SendTimeoutMillis = value, + Throws.TypeOf()); + + /// MailKit needs it too, for the reads and writes between the cancellation checks. + [Test] + public void TheTimeoutReachesTheTransport() + { + const int sendTimeoutMillis = 1_234; + SmtpAppender appender = CreateAppender(); + appender.SendTimeoutMillis = sendTimeoutMillis; + + Append(appender); + + Assert.That(_transport.Timeout, Is.EqualTo(sendTimeoutMillis)); + } + + /// + /// Every single operation stays inside the timeout here, their sum does not. A per operation + /// timeout would let this run on; the deadline stops it. + /// + [Test] + public void TheDeadlineCoversTheWholeSendAndNotOneOperation() + { + const int sendTimeoutMillis = 300; + const int delayMillisPerCall = 200; + const int generousBoundMillis = 5_000; + + SmtpAppender appender = CreateAppender(); + appender.SendTimeoutMillis = sendTimeoutMillis; + _transport.DelayMillisPerCall = delayMillisPerCall; + + Stopwatch stopwatch = Stopwatch.StartNew(); + Append(appender); + stopwatch.Stop(); + + Assert.That(_transport.SentMails, Is.Empty); + Assert.That(_errorHandler.Message, Does.Contain("Error occurred while sending e-mail notification.")); + Assert.That(stopwatch.ElapsedMilliseconds, Is.LessThan(generousBoundMillis)); + } } diff --git a/src/log4net.Ext.Mail/Appender/Internal/ISmtpTransport.cs b/src/log4net.Ext.Mail/Appender/Internal/ISmtpTransport.cs index 65ef28c6..6f470f38 100644 --- a/src/log4net.Ext.Mail/Appender/Internal/ISmtpTransport.cs +++ b/src/log4net.Ext.Mail/Appender/Internal/ISmtpTransport.cs @@ -19,6 +19,7 @@ using System; using System.Net; +using System.Threading; using MailKit.Security; using MimeKit; @@ -40,6 +41,11 @@ namespace log4net.Ext.Mail.Appender.Internal; /// internal interface ISmtpTransport : IDisposable { + /// + /// The timeout for a single network operation, in milliseconds. + /// + int Timeout { get; set; } + /// /// Gets a value indicating whether the transport is connected to a server. /// @@ -56,26 +62,31 @@ internal interface ISmtpTransport : IDisposable /// The name or address of the SMTP server. /// The port the SMTP server is listening on. /// The transport security to use. - void Connect(string host, int port, SecureSocketOptions secureSocketOptions); + /// Abandons the operation when the deadline passes. + void Connect(string host, int port, SecureSocketOptions secureSocketOptions, + CancellationToken cancellationToken); /// /// Authenticates using the supplied and whichever /// SASL mechanism the server and client agree on. /// /// The credentials to authenticate with. - void Authenticate(ICredentials credentials); + /// Abandons the operation when the deadline passes. + void Authenticate(ICredentials credentials, CancellationToken cancellationToken); /// /// Authenticates using an explicit SASL . /// /// The SASL mechanism to authenticate with. - void Authenticate(SaslMechanism mechanism); + /// Abandons the operation when the deadline passes. + void Authenticate(SaslMechanism mechanism, CancellationToken cancellationToken); /// /// Sends the specified . /// /// The message to send. - void Send(MimeMessage message); + /// Abandons the operation when the deadline passes. + void Send(MimeMessage message, CancellationToken cancellationToken); /// /// Disconnects from the SMTP server. diff --git a/src/log4net.Ext.Mail/Appender/Internal/MailKitSmtpTransport.cs b/src/log4net.Ext.Mail/Appender/Internal/MailKitSmtpTransport.cs index 69768242..3381ed77 100644 --- a/src/log4net.Ext.Mail/Appender/Internal/MailKitSmtpTransport.cs +++ b/src/log4net.Ext.Mail/Appender/Internal/MailKitSmtpTransport.cs @@ -18,6 +18,7 @@ #endregion using System.Net; +using System.Threading; using MailKit.Net.Smtp; using MailKit.Security; using MimeKit; @@ -32,6 +33,13 @@ internal sealed class MailKitSmtpTransport : ISmtpTransport { private readonly SmtpClient _client = new(); + /// + public int Timeout + { + get => _client.Timeout; + set => _client.Timeout = value; + } + /// public bool IsConnected => _client.IsConnected; @@ -39,17 +47,21 @@ internal sealed class MailKitSmtpTransport : ISmtpTransport public bool IsAuthenticated => _client.IsAuthenticated; /// - public void Connect(string host, int port, SecureSocketOptions secureSocketOptions) - => _client.Connect(host, port, secureSocketOptions); + public void Connect(string host, int port, SecureSocketOptions secureSocketOptions, + CancellationToken cancellationToken) + => _client.Connect(host, port, secureSocketOptions, cancellationToken); /// - public void Authenticate(ICredentials credentials) => _client.Authenticate(credentials); + public void Authenticate(ICredentials credentials, CancellationToken cancellationToken) + => _client.Authenticate(credentials, cancellationToken); /// - public void Authenticate(SaslMechanism mechanism) => _client.Authenticate(mechanism); + public void Authenticate(SaslMechanism mechanism, CancellationToken cancellationToken) + => _client.Authenticate(mechanism, cancellationToken); /// - public void Send(MimeMessage message) => _client.Send(message); + public void Send(MimeMessage message, CancellationToken cancellationToken) + => _client.Send(message, cancellationToken); /// public void Disconnect(bool quit) => _client.Disconnect(quit); diff --git a/src/log4net.Ext.Mail/Appender/SmtpAppender.cs b/src/log4net.Ext.Mail/Appender/SmtpAppender.cs index e2d631a4..f6179971 100644 --- a/src/log4net.Ext.Mail/Appender/SmtpAppender.cs +++ b/src/log4net.Ext.Mail/Appender/SmtpAppender.cs @@ -20,6 +20,7 @@ using System; using System.IO; using System.Net; +using System.Threading; using System.Net.Mail; using System.Text; @@ -375,33 +376,60 @@ protected override void SendBuffer(LoggingEvent[] events) /// the body text to include in the mail protected virtual void SendEmail(string messageBody) { + using CancellationTokenSource deadline = new(SendTimeoutMillis); using MimeMessage message = CreateMessage(messageBody); using ISmtpTransport transport = _transportFactory().EnsureNotNull(); + transport.Timeout = SendTimeoutMillis; - transport.Connect(SmtpHost.EnsureNotNullOrEmpty(), Port, ResolveSecureSocketOptions()); + transport.Connect(SmtpHost.EnsureNotNullOrEmpty(), Port, ResolveSecureSocketOptions(), deadline.Token); try { switch (Authentication) { case SmtpAuthentication.Basic: - transport.Authenticate(new NetworkCredential(Username, Password)); + transport.Authenticate(new NetworkCredential(Username, Password), deadline.Token); break; case SmtpAuthentication.Ntlm: - transport.Authenticate(new SaslMechanismNtlm(new NetworkCredential(Username, Password))); + transport.Authenticate(new SaslMechanismNtlm(new NetworkCredential(Username, Password)), deadline.Token); break; case SmtpAuthentication.None: default: break; } - transport.Send(message); + transport.Send(message, deadline.Token); } finally { + // No token: already cancelled, it would replace the failure that got us here. transport.Disconnect(true); } } + /// + /// A deadline for the whole send, in milliseconds. Defaults to 15000. + /// + /// + /// MailKit's own timeout applies per operation, so a server answering just inside it can still + /// take a multiple of it. The mail goes out under the appender lock. + /// + /// The value specified is not positive. + public int SendTimeoutMillis + { + get => _sendTimeoutMillis; + set + { + if (value <= 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for SendTimeoutMillis is not positive."); + } + _sendTimeoutMillis = value; + } + } + + private int _sendTimeoutMillis = 15_000; + /// /// Builds the for the given body text from the configured options. /// diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc index 0c33679b..d0403f78 100644 --- a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc @@ -189,6 +189,10 @@ This example authenticates against a mail server that requires an encrypted conn |`port` |The port the SMTP server listens on. Defaults to `25`. +|`sendTimeoutMillis` +|How long one send may take before it is abandoned, in milliseconds. Defaults to `15000`. +The mail goes out under the appender lock, so an unresponsive server would otherwise stall logging. + |`enableSsl` |Whether to require transport security. Defaults to `false`. Shorthand for `transportSecurity`: `true` selects `Required`, `false` selects `None`. @@ -280,6 +284,8 @@ The options above are named exactly as in the legacy appender, but a few behave MailKit cannot reuse the Windows logon session of the current thread or process, which the legacy appender did. * Semicolon-delimited recipient lists in `to`, `cc` and `bcc` are parsed correctly. * `transportSecurity` has no counterpart in the legacy appender, which offers only `enableSsl`. +* `sendTimeoutMillis` is a deadline for the whole send here, while in the legacy appender it bounds +the one `SmtpClient.Send` call. Both default to `15000`. `enableSsl` keeps its meaning, so a migrated configuration secures the connection exactly as before. If the legacy appender reached your server with `enableSsl` set to `true`, so does this one. From 02b66be086f2614c351be99a79db526a563958e1 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 22:01:21 +0200 Subject: [PATCH 06/12] send mail from a background thread in the MailKit SmtpAppender #314 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. --- .../3.5.0/314-ext-mail-background-sender.xml | 15 +++ .../Appender/SmtpAppenderTest.cs | 32 ++++++- src/log4net.Ext.Mail/Appender/SmtpAppender.cs | 95 ++++++++++++++++++- .../Util/BackgroundSenderTest.cs | 4 + src/log4net/Util/BackgroundSender.cs | 23 +++-- .../configuration/appenders/smtpappender.adoc | 11 +++ 6 files changed, 168 insertions(+), 12 deletions(-) create mode 100644 src/changelog/3.5.0/314-ext-mail-background-sender.xml diff --git a/src/changelog/3.5.0/314-ext-mail-background-sender.xml b/src/changelog/3.5.0/314-ext-mail-background-sender.xml new file mode 100644 index 00000000..f16ce22f --- /dev/null +++ b/src/changelog/3.5.0/314-ext-mail-background-sender.xml @@ -0,0 +1,15 @@ + + + + + send mail from a background thread in the MailKit based `SmtpAppender`. The mail used to go out + while the appender lock was held, so the thread that logged, and every thread behind it, waited + for the SMTP server. The queue holds `sendQueueSize` mails (500) and a logging call waits at most + `enqueueTimeoutMillis` (5000) for room in it. Failures are still reported to the error handler, + but after the logging call has returned, and `Flush` now honours its timeout + (implemented by @FreeAndNil) + + diff --git a/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs b/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs index 5d0dae3b..21fc6599 100644 --- a/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs +++ b/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs @@ -107,8 +107,12 @@ private static void Append(SmtpAppender appender, string message = "log message" { appender.ActivateOptions(); appender.DoAppend(CreateEvent(message)); + // Sending is asynchronous. + appender.Flush(FlushTimeoutMillis); } + private const int FlushTimeoutMillis = 30_000; + [Test] public void SendsOneMailPerEventWhenNotBuffering() { @@ -498,7 +502,7 @@ public void SendFailureIsReportedToTheErrorHandlerAndNotThrown() Assert.DoesNotThrow(() => Append(appender)); - Assert.That(_errorHandler.Message, Does.Contain("Error occurred while sending e-mail notification.")); + Assert.That(_errorHandler.Message, Does.Contain("Failed to send a logging event.")); Assert.That(_errorHandler.Message, Does.Contain("relay refused")); } @@ -551,6 +555,7 @@ public void EachSendUsesAFreshTransport() appender.DoAppend(CreateEvent("first")); appender.DoAppend(CreateEvent("second")); + appender.Flush(FlushTimeoutMillis); Assert.That(transports, Has.Count.EqualTo(2)); Assert.That(transports[0].SentMails[0].Body, Does.Contain("first")); @@ -662,7 +667,30 @@ public void TheDeadlineCoversTheWholeSendAndNotOneOperation() stopwatch.Stop(); Assert.That(_transport.SentMails, Is.Empty); - Assert.That(_errorHandler.Message, Does.Contain("Error occurred while sending e-mail notification.")); + Assert.That(_errorHandler.Message, Does.Contain("Failed to send a logging event.")); Assert.That(stopwatch.ElapsedMilliseconds, Is.LessThan(generousBoundMillis)); } + + /// Bounded, so an unreachable server cannot grow the queue without limit. + [Test] + public void SendQueueSizeDefaultsTo500() + => Assert.That(CreateAppender().SendQueueSize, Is.EqualTo(500)); + + /// The longest a logging call waits when the queue is full. + [Test] + public void EnqueueTimeoutMillisDefaultsTo5000() + => Assert.That(CreateAppender().EnqueueTimeoutMillis, Is.EqualTo(5_000)); + + /// A queue with no room for anything cannot work. + [TestCase(0)] + [TestCase(-1)] + public void SendQueueSizeRejectsValuesThatAreNotPositive(int value) + => Assert.That(() => CreateAppender().SendQueueSize = value, + Throws.TypeOf()); + + /// 0 is allowed and never waits, a negative wait is meaningless. + [Test] + public void EnqueueTimeoutMillisRejectsANegativeValue() + => Assert.That(() => CreateAppender().EnqueueTimeoutMillis = -1, + Throws.TypeOf()); } diff --git a/src/log4net.Ext.Mail/Appender/SmtpAppender.cs b/src/log4net.Ext.Mail/Appender/SmtpAppender.cs index f6179971..9e4085c0 100644 --- a/src/log4net.Ext.Mail/Appender/SmtpAppender.cs +++ b/src/log4net.Ext.Mail/Appender/SmtpAppender.cs @@ -331,7 +331,16 @@ protected override void SendBuffer(LoggingEvent[] events) writer.Write(footer); } - SendEmail(writer.ToString()); + string body = writer.ToString(); + if (_sender is BackgroundSender sender) + { + // A full queue is reported by the sender itself. + sender.TryEnqueue(body, EnqueueTimeoutMillis); + } + else + { + SendEmail(body); + } } catch (Exception e) when (!e.IsFatal()) { @@ -339,6 +348,90 @@ protected override void SendBuffer(LoggingEvent[] events) } } + /// + public override void ActivateOptions() + { + base.ActivateOptions(); + CloseSender(); + _sender = new(nameof(SmtpAppender), SendQueueSize, (body, _) => SendEmail(body), Report); + } + + /// + public override bool Flush(int millisecondsTimeout) + { + base.Flush(); + return _sender?.Flush(millisecondsTimeout) ?? true; + } + + /// + protected override void OnClose() + { + base.OnClose(); + CloseSender(); + } + + /// + /// How many rendered mails may wait to be sent. Defaults to 500. + /// + /// The value specified is not positive. + public int SendQueueSize + { + get => _sendQueueSize; + set + { + if (value <= 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for SendQueueSize is not positive."); + } + _sendQueueSize = value; + } + } + + /// + /// How long a logging call waits for room in a full queue. Defaults to 5000, 0 never waits. + /// + /// The value specified is negative. + public int EnqueueTimeoutMillis + { + get => _enqueueTimeoutMillis; + set + { + if (value < 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for EnqueueTimeoutMillis is negative."); + } + _enqueueTimeoutMillis = value; + } + } + + private void CloseSender() + { + if (_sender is BackgroundSender sender) + { + _sender = null; + sender.Close(SendTimeoutMillis); + sender.Dispose(); + } + } + + private void Report(string message, Exception? exception) + { + if (exception is null) + { + ErrorHandler.Error(message); + } + else + { + ErrorHandler.Error(message, exception); + } + } + + private BackgroundSender? _sender; + private int _sendQueueSize = 500; + private int _enqueueTimeoutMillis = 5_000; + /// /// This appender requires a to be set. /// diff --git a/src/log4net.Tests/Util/BackgroundSenderTest.cs b/src/log4net.Tests/Util/BackgroundSenderTest.cs index ab2174a8..a4280f32 100644 --- a/src/log4net.Tests/Util/BackgroundSenderTest.cs +++ b/src/log4net.Tests/Util/BackgroundSenderTest.cs @@ -262,6 +262,10 @@ public void AFailedSendDoesNotStopTheOnesAfterIt() Assert.That(sender.Flush(WaitMillis), Is.True); Assert.That(Sent, Is.EqualTo(new[] { 0, 2, 3 })); Assert.That(sender.DroppedItemCount, Is.EqualTo(1)); + + // A failed send is not queue pressure and must not be reported as such. + Assert.That(_reported, Has.Some.Contains("Failed to send")); + Assert.That(_reported, Has.None.Contains("queue is full")); } /// diff --git a/src/log4net/Util/BackgroundSender.cs b/src/log4net/Util/BackgroundSender.cs index 833b3ccd..81e37446 100644 --- a/src/log4net/Util/BackgroundSender.cs +++ b/src/log4net/Util/BackgroundSender.cs @@ -128,7 +128,7 @@ public bool TryEnqueue(T item, int millisecondsTimeout) } } - CountDrop(); + ReportQueueFull(); return false; } @@ -249,8 +249,8 @@ private void Pump() if (_shutdown.IsCancellationRequested) { - // Closing and out of time. Drain the queue without sending, so that Close returns. - CountDrop(); + // Closing and out of time. Drain without sending, so that Close returns. + CountLost(); continue; } @@ -260,7 +260,7 @@ private void Pump() } catch (Exception e) when (!e.IsFatal()) { - CountDrop(); + CountLost(); Report($"[{_name}] Failed to send a logging event.", e); } } @@ -298,7 +298,7 @@ private void ReleaseWaiters() } else { - CountDrop(); + CountLost(); } } } @@ -309,13 +309,18 @@ private void ReleaseWaiters() } } - private void CountDrop() + private void CountLost() => Interlocked.Increment(ref _droppedItemCount); + + /// + /// A full or closed queue, unlike a failed send, which reports for itself. + /// + private void ReportQueueFull() { - Interlocked.Increment(ref _droppedItemCount); + CountLost(); if (Interlocked.Exchange(ref _dropReported, 1) == 0) { - Report($"[{_name}] A logging event was dropped. The sink is not keeping up or is unreachable. " - + "Further drops are counted and reported when the appender closes.", null); + Report($"[{_name}] A logging event was dropped: the queue is full or closed. " + + "Further losses are counted and reported when the sender closes.", null); } } diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc index d0403f78..e28f30cd 100644 --- a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/smtpappender.adoc @@ -219,6 +219,13 @@ See xref:#mailkit-smtpappender-transport-security[]. |`bodyEncoding` |The encoding of the message body, for example `utf-8`. Defaults to `utf-8`. +|`sendQueueSize` +|How many rendered mails may wait to be sent. Defaults to `500`. + +|`enqueueTimeoutMillis` +|How long a logging call waits for room in a full queue, in milliseconds. Defaults to `5000`. +`0` never waits and discards the mail instead. + |`bufferSize` |How many log events to buffer into one email. See xref:manual/configuration/appenders.adoc[]. @@ -286,6 +293,10 @@ MailKit cannot reuse the Windows logon session of the current thread or process, * `transportSecurity` has no counterpart in the legacy appender, which offers only `enableSsl`. * `sendTimeoutMillis` is a deadline for the whole send here, while in the legacy appender it bounds the one `SmtpClient.Send` call. Both default to `15000`. +* The mail is handed to a background thread rather than sent by the thread that logged, so a slow +server no longer stalls logging. Failures are reported to the error handler as before, but after +the logging call has returned, and mail still queued is lost if the process is killed. +`sendQueueSize` and `enqueueTimeoutMillis` bound the queue. `enableSsl` keeps its meaning, so a migrated configuration secures the connection exactly as before. If the legacy appender reached your server with `enableSsl` set to `true`, so does this one. From 7083581b6aeb56d12facae6189d0e72a61178497 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 22:13:00 +0200 Subject: [PATCH 07/12] report a buffering appender that is still holding events #314 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. --- .../314-flush-reports-buffered-events.xml | 12 ++++++ src/log4net.Ext.Mail/Appender/SmtpAppender.cs | 5 ++- .../Appender/BufferingAppenderTest.cs | 37 ++++++++++++++++++- .../Appender/BufferingAppenderSkeleton.cs | 14 +++++-- 4 files changed, 62 insertions(+), 6 deletions(-) create mode 100644 src/changelog/3.5.0/314-flush-reports-buffered-events.xml diff --git a/src/changelog/3.5.0/314-flush-reports-buffered-events.xml b/src/changelog/3.5.0/314-flush-reports-buffered-events.xml new file mode 100644 index 00000000..535f067d --- /dev/null +++ b/src/changelog/3.5.0/314-flush-reports-buffered-events.xml @@ -0,0 +1,12 @@ + + + + + report a buffering appender that is still holding events from `Flush`. It returned `true` + unconditionally, including for a `lossy` appender, where flushing deliberately does nothing and + every buffered event stays where it was (implemented by @FreeAndNil) + + diff --git a/src/log4net.Ext.Mail/Appender/SmtpAppender.cs b/src/log4net.Ext.Mail/Appender/SmtpAppender.cs index 9e4085c0..1c2bd3da 100644 --- a/src/log4net.Ext.Mail/Appender/SmtpAppender.cs +++ b/src/log4net.Ext.Mail/Appender/SmtpAppender.cs @@ -359,8 +359,9 @@ public override void ActivateOptions() /// public override bool Flush(int millisecondsTimeout) { - base.Flush(); - return _sender?.Flush(millisecondsTimeout) ?? true; + bool buffered = base.Flush(millisecondsTimeout); + bool queued = _sender?.Flush(millisecondsTimeout) ?? true; + return buffered && queued; } /// diff --git a/src/log4net.Tests/Appender/BufferingAppenderTest.cs b/src/log4net.Tests/Appender/BufferingAppenderTest.cs index 6a9cf1d5..0040ced9 100644 --- a/src/log4net.Tests/Appender/BufferingAppenderTest.cs +++ b/src/log4net.Tests/Appender/BufferingAppenderTest.cs @@ -100,4 +100,39 @@ public void TestBufferSize5() logger.Log(typeof(BufferingAppenderTest), Level.Warn, "Message 8", null); Assert.That(_countingAppender.Counter, Is.EqualTo(6), "Test 2 event in buffer. 6 event sent"); } -} \ No newline at end of file + + /// The buffer is emptied, so the answer is yes. + [Test] + public void FlushReportsSuccessWhenTheBufferIsEmptied() + { + SetupRepository(); + _bufferingForwardingAppender.BufferSize = 5; + _bufferingForwardingAppender.ActivateOptions(); + + ILogger logger = _hierarchy.GetLogger("test"); + logger.Log(typeof(BufferingAppenderTest), Level.Warn, "Message", null); + + Assert.That(_bufferingForwardingAppender.Flush(0), Is.True); + Assert.That(_countingAppender.Counter, Is.EqualTo(1)); + } + + /// + /// A lossy appender keeps its events until something triggers them, so reporting that they + /// were flushed would be untrue. + /// + [Test] + public void FlushReportsFailureWhileALossyBufferKeepsItsEvents() + { + SetupRepository(); + _bufferingForwardingAppender.BufferSize = 5; + _bufferingForwardingAppender.Lossy = true; + _bufferingForwardingAppender.Evaluator = new LevelEvaluator(Level.Off); + _bufferingForwardingAppender.ActivateOptions(); + + ILogger logger = _hierarchy.GetLogger("test"); + logger.Log(typeof(BufferingAppenderTest), Level.Warn, "Message", null); + + Assert.That(_bufferingForwardingAppender.Flush(0), Is.False); + Assert.That(_countingAppender.Counter, Is.EqualTo(0)); + } +} diff --git a/src/log4net/Appender/BufferingAppenderSkeleton.cs b/src/log4net/Appender/BufferingAppenderSkeleton.cs index 31fff5b9..eb1154a0 100644 --- a/src/log4net/Appender/BufferingAppenderSkeleton.cs +++ b/src/log4net/Appender/BufferingAppenderSkeleton.cs @@ -201,12 +201,20 @@ protected BufferingAppenderSkeleton(bool eventMustBeFixed) /// /// Flushes any buffered log data. /// - /// The maximum time to wait for logging events to be flushed. - /// if all logging events were flushed successfully, else . + /// + /// Unused: the buffer is sent on the calling thread, so there is nothing to wait for. + /// + /// + /// when events are still buffered afterwards, which is what a + /// appender does: it keeps them until a triggering event arrives. + /// public override bool Flush(int millisecondsTimeout) { Flush(); - return true; + lock (LockObj) + { + return _cyclicBuffer is null || _cyclicBuffer.Length == 0; + } } /// From 6736d8c20f7b6a4eb9928e2c9543d5658ff62c1a Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 22:27:26 +0200 Subject: [PATCH 08/12] do not open a second UDP socket in RemoteSyslogAppender #314 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. --- .../314-remote-syslog-socket-and-connect.xml | 14 ++++ .../Appender/Internal/UdpMock.cs | 16 ++++- .../Appender/RemoteSyslogAppenderTest.cs | 65 +++++++++++++++++++ src/log4net/Appender/RemoteSyslogAppender.cs | 28 +++++++- 4 files changed, 119 insertions(+), 4 deletions(-) create mode 100644 src/changelog/3.5.0/314-remote-syslog-socket-and-connect.xml diff --git a/src/changelog/3.5.0/314-remote-syslog-socket-and-connect.xml b/src/changelog/3.5.0/314-remote-syslog-socket-and-connect.xml new file mode 100644 index 00000000..fb2185c7 --- /dev/null +++ b/src/changelog/3.5.0/314-remote-syslog-socket-and-connect.xml @@ -0,0 +1,14 @@ + + + + + stop `RemoteSyslogAppender` from opening a second, unused UDP socket. It sends through the + connection its background pump owns, but also inherited one from `UdpAppender` that nothing ever + used, which bound `localPort` twice. A pump that cannot connect now reports it as well, instead + of ending unobserved and leaving every later event queued behind a sender that is gone + (implemented by @FreeAndNil) + + diff --git a/src/log4net.Tests/Appender/Internal/UdpMock.cs b/src/log4net.Tests/Appender/Internal/UdpMock.cs index 152c625e..3d06e74f 100644 --- a/src/log4net.Tests/Appender/Internal/UdpMock.cs +++ b/src/log4net.Tests/Appender/Internal/UdpMock.cs @@ -17,6 +17,7 @@ // #endregion +using System; using System.Collections.Generic; using System.Net; using System.Threading.Tasks; @@ -44,9 +45,20 @@ internal sealed class UdpMock : IUdpConnection /// internal (int LocalPort, IPAddress Host, int RemotePort)? ConnectedTo { get; private set; } + /// + /// When set, throws this. + /// + internal Exception? ConnectException { get; set; } + /// - public void Connect(int localPort, IPAddress host, int remotePort) - => ConnectedTo = (localPort, host, remotePort); + public void Connect(int localPort, IPAddress host, int remotePort) + { + ConnectedTo = (localPort, host, remotePort); + if (ConnectException is Exception exception) + { + throw exception; + } + } /// public void Dispose() => WasDisposed = true; diff --git a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs index a9f6ed44..dc56907a 100644 --- a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs +++ b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs @@ -17,6 +17,7 @@ // #endregion +using System; using System.Collections.Generic; using System.Linq; using System.Text; @@ -46,6 +47,70 @@ private sealed class RemoteAppender : RemoteSyslogAppender /// protected override IUdpConnection CreateUdpConnection() => Mock; + + /// The socket the base class would have opened. + internal System.Net.Sockets.UdpClient? InheritedClient => Client; + } + + /// Collects reported errors instead of letting them reach the console. + private sealed class RecordingErrorHandler : IErrorHandler + { + /// Reported messages. + internal List Messages { get; } = []; + + /// + public void Error(string message, Exception? e, ErrorCode errorCode) => Messages.Add(message); + + /// + public void Error(string message, Exception e) => Messages.Add(message); + + /// + public void Error(string message) => Messages.Add(message); + } + + /// + /// This appender sends through the connection its pump owns, so the inherited one would be a + /// second socket, holding a second binding of LocalPort, that nothing ever uses. + /// + [Test] + public void TheInheritedSocketIsNotOpened() + { + RemoteAppender appender = new() + { + RemoteAddress = new System.Net.IPAddress([127, 0, 0, 1]), + Layout = new PatternLayout("%message") + }; + appender.ActivateOptions(); + try + { + Assert.That(appender.InheritedClient, Is.Null); + } + finally + { + appender.Close(); + } + } + + /// + /// Connecting happens outside the send loop, so a failure there used to fault the pump with + /// nobody watching and every later event queued behind a sender that was gone. + /// + [Test] + public void AConnectFailureIsReported() + { + RecordingErrorHandler errorHandler = new(); + RemoteAppender appender = new() + { + RemoteAddress = new System.Net.IPAddress([127, 0, 0, 1]), + Layout = new PatternLayout("%message"), + ErrorHandler = errorHandler + }; + appender.Mock.ConnectException = new InvalidOperationException("simulated connect failure"); + + appender.ActivateOptions(); + appender.Close(); + + Assert.That(errorHandler.Messages, Has.Some.Contains("Unable to connect to remote syslog")); } /// diff --git a/src/log4net/Appender/RemoteSyslogAppender.cs b/src/log4net/Appender/RemoteSyslogAppender.cs index 3d30c526..6e476c4e 100644 --- a/src/log4net/Appender/RemoteSyslogAppender.cs +++ b/src/log4net/Appender/RemoteSyslogAppender.cs @@ -645,12 +645,36 @@ protected override void OnClose() base.OnClose(); } + /// + /// + /// Deliberately empty: this appender sends through the connection its pump owns, so the + /// inherited client would be a second socket that nothing ever uses. + /// + protected override void InitializeClientConnection() + { + } + private async Task ProcessQueueAsync(CancellationToken token) { // We create our own UdpClient here, so that client lifetime is tied to this task - using IUdpConnection udpClient = CreateUdpConnection(); - udpClient.Connect(LocalPort, RemoteAddress.EnsureNotNull(), RemotePort); + IUdpConnection udpClient; + try + { + udpClient = CreateUdpConnection(); + udpClient.Connect(LocalPort, RemoteAddress.EnsureNotNull(), RemotePort); + } + catch (Exception e) when (!e.IsFatal()) + { + // Outside the loop below, so this would otherwise fault the pump unobserved and leave + // every later event queued behind a sender that is no longer running. + ErrorHandler.Error( + $"Unable to connect to remote syslog {RemoteAddress} on port {RemotePort} from local port {LocalPort}. " + + "No logging event will be sent.", + e, ErrorCode.GenericFailure); + return; + } + using IUdpConnection connection = udpClient; try { while (!token.IsCancellationRequested) From 2b396ffdfceff5389a05a4e7df7cb8769c987a24 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 22:33:23 +0200 Subject: [PATCH 09/12] send syslog datagrams through BackgroundSender #314 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. --- .../314-remote-syslog-background-sender.xml | 14 ++ .../Appender/RemoteSyslogAppenderTest.cs | 34 +++- src/log4net/Appender/RemoteSyslogAppender.cs | 165 +++++++++++------- .../appenders/remotesyslogappender.adoc | 7 + 4 files changed, 145 insertions(+), 75 deletions(-) create mode 100644 src/changelog/3.5.0/314-remote-syslog-background-sender.xml diff --git a/src/changelog/3.5.0/314-remote-syslog-background-sender.xml b/src/changelog/3.5.0/314-remote-syslog-background-sender.xml new file mode 100644 index 00000000..9ea954df --- /dev/null +++ b/src/changelog/3.5.0/314-remote-syslog-background-sender.xml @@ -0,0 +1,14 @@ + + + + + bound the queue `RemoteSyslogAppender` sends from. It was unbounded, so a syslog server that + stopped accepting datagrams grew it until the process ran out of memory, and 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 reported, and `Flush` honours its timeout (implemented by @FreeAndNil) + + diff --git a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs index dc56907a..5b187822 100644 --- a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs +++ b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs @@ -21,7 +21,6 @@ using System.Collections.Generic; using System.Linq; using System.Text; -using System.Threading; using log4net.Appender; using log4net.Appender.Internal; using log4net.Core; @@ -68,6 +67,31 @@ private sealed class RecordingErrorHandler : IErrorHandler public void Error(string message) => Messages.Add(message); } + private const int FlushTimeoutMillis = 30_000; + + /// Bounded, so an unreachable server cannot grow the queue without limit. + [Test] + public void SendQueueSizeDefaultsTo500() + => Assert.That(new RemoteSyslogAppender().SendQueueSize, Is.EqualTo(500)); + + /// The longest a logging call waits when the queue is full. + [Test] + public void EnqueueTimeoutMillisDefaultsTo5000() + => Assert.That(new RemoteSyslogAppender().EnqueueTimeoutMillis, Is.EqualTo(5_000)); + + /// A queue with no room for anything cannot work. + [TestCase(0)] + [TestCase(-1)] + public void SendQueueSizeRejectsValuesThatAreNotPositive(int value) + => Assert.That(() => new RemoteSyslogAppender().SendQueueSize = value, + Throws.TypeOf()); + + /// 0 is allowed and never waits, a negative wait is meaningless. + [Test] + public void EnqueueTimeoutMillisRejectsANegativeValue() + => Assert.That(() => new RemoteSyslogAppender().EnqueueTimeoutMillis = -1, + Throws.TypeOf()); + /// /// This appender sends through the connection its pump owns, so the inherited one would be a /// second socket, holding a second binding of LocalPort, that nothing ever uses. @@ -262,13 +286,7 @@ private static List ExecuteAppend(string message, Domain = "TestDomain", }); appender.DoAppend(loggingEvent); - for (int i = 0; i < 20; i++) - { - if (appender.Mock.Sent.Count == 0) - { - Thread.Sleep(10); - } - } + Assert.That(appender.Flush(FlushTimeoutMillis), Is.True); appender.Close(); Assert.That(appender.Mock.ConnectedTo, Is.EqualTo((0, ipAddress, 514))); Assert.That(appender.Mock.WasDisposed, Is.True); diff --git a/src/log4net/Appender/RemoteSyslogAppender.cs b/src/log4net/Appender/RemoteSyslogAppender.cs index 6e476c4e..e2d6cd30 100644 --- a/src/log4net/Appender/RemoteSyslogAppender.cs +++ b/src/log4net/Appender/RemoteSyslogAppender.cs @@ -18,10 +18,8 @@ #endregion using System; -using System.Collections.Concurrent; using System.Text; using System.Threading; -using System.Threading.Tasks; using log4net.Appender.Internal; using log4net.Core; using log4net.Layout; @@ -279,9 +277,11 @@ public enum SyslogNewLineHandling Keep } - private readonly BlockingCollection _sendQueue = new(); - private CancellationTokenSource? _cancellationTokenSource; - private Task? _pumpTask; + private const int CloseTimeoutMillis = 5_000; + private IUdpConnection? _connection; + private BackgroundSender? _sender; + private int _sendQueueSize = 500; + private int _enqueueTimeoutMillis = 5_000; /// /// Initializes a new instance of the class. @@ -389,7 +389,8 @@ protected override void Append(LoggingEvent loggingEvent) // Grab as a byte array byte[] buffer = Encoding.GetBytes(builder.ToString()); - _sendQueue.Add(buffer); + // A full queue is reported by the sender itself. + _sender?.TryEnqueue(buffer, EnqueueTimeoutMillis); } } catch (Exception e) when (!e.IsFatal()) @@ -524,10 +525,89 @@ public override void ActivateOptions() $"The NewLineHandling is not {SyslogNewLineHandling.Escape} or {SyslogNewLineHandling.Keep} or {SyslogNewLineHandling.Split}."); } _levelMapping.ActivateOptions(); - // Start the background pump - _cancellationTokenSource = new(); - _pumpTask = Task.Factory.StartNew(() => ProcessQueueAsync(_cancellationTokenSource.Token), CancellationToken.None, - TaskCreationOptions.LongRunning, TaskScheduler.Default); + StopSending(); + + IUdpConnection connection = CreateUdpConnection(); + try + { + connection.Connect(LocalPort, RemoteAddress.EnsureNotNull(), RemotePort); + } + catch (Exception e) when (!e.IsFatal()) + { + ErrorHandler.Error( + $"Unable to connect to remote syslog {RemoteAddress} on port {RemotePort} from local port {LocalPort}. " + + "No logging event will be sent.", + e, ErrorCode.GenericFailure); + connection.Dispose(); + return; + } + + _connection = connection; + _sender = new(nameof(RemoteSyslogAppender), SendQueueSize, Send, Report); + } + + /// + /// How many datagrams may wait to be sent. Defaults to 500. + /// + /// The value specified is not positive. + public int SendQueueSize + { + get => _sendQueueSize; + set + { + if (value <= 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for SendQueueSize is not positive."); + } + _sendQueueSize = value; + } + } + + /// + /// How long a logging call waits for room in a full queue. Defaults to 5000, 0 never waits. + /// + /// The value specified is negative. + public int EnqueueTimeoutMillis + { + get => _enqueueTimeoutMillis; + set + { + if (value < 0) + { + throw SystemInfo.CreateArgumentOutOfRangeException(nameof(value), value, + "The value specified for EnqueueTimeoutMillis is negative."); + } + _enqueueTimeoutMillis = value; + } + } + + private void Send(byte[] datagram, CancellationToken cancellationToken) + => _connection?.SendAsync(datagram, datagram.Length).GetAwaiter().GetResult(); + + private void Report(string message, Exception? exception) + { + if (exception is null) + { + ErrorHandler.Error(message); + } + else + { + ErrorHandler.Error(message, exception); + } + } + + private void StopSending() + { + if (_sender is BackgroundSender sender) + { + _sender = null; + sender.Close(CloseTimeoutMillis); + sender.Dispose(); + } + + _connection?.Dispose(); + _connection = null; } /// @@ -636,12 +716,17 @@ public class LevelSeverity : LevelMappingEntry public SyslogSeverity Severity { get; set; } } + /// + /// Waits until everything queued so far has been sent. + /// + /// The maximum time to wait. + /// on timeout, or when the sender is no longer running. + public override bool Flush(int millisecondsTimeout) => _sender?.Flush(millisecondsTimeout) ?? true; + /// protected override void OnClose() { - // Signal shutdown and wait for the pump to drain - _cancellationTokenSource?.Cancel(); - _pumpTask?.Wait(TimeSpan.FromSeconds(5)); + StopSending(); base.OnClose(); } @@ -653,58 +738,4 @@ protected override void OnClose() protected override void InitializeClientConnection() { } - - private async Task ProcessQueueAsync(CancellationToken token) - { - // We create our own UdpClient here, so that client lifetime is tied to this task - IUdpConnection udpClient; - try - { - udpClient = CreateUdpConnection(); - udpClient.Connect(LocalPort, RemoteAddress.EnsureNotNull(), RemotePort); - } - catch (Exception e) when (!e.IsFatal()) - { - // Outside the loop below, so this would otherwise fault the pump unobserved and leave - // every later event queued behind a sender that is no longer running. - ErrorHandler.Error( - $"Unable to connect to remote syslog {RemoteAddress} on port {RemotePort} from local port {LocalPort}. " - + "No logging event will be sent.", - e, ErrorCode.GenericFailure); - return; - } - - using IUdpConnection connection = udpClient; - try - { - while (!token.IsCancellationRequested) - { - // Take next message or throw when canceled - byte[] datagram = _sendQueue.Take(token); - try - { - await udpClient.SendAsync(datagram, datagram.Length).ConfigureAwait(false); - } - catch (Exception ex) when (!ex.IsFatal()) - { - ErrorHandler.Error("RemoteSyslogAppender: send failed", ex, ErrorCode.WriteFailure); - } - } - } - catch (OperationCanceledException) - { - // Clean shutdown: drain remaining items if desired - while (_sendQueue.TryTake(out byte[]? leftover)) - { - try - { - await udpClient.SendAsync(leftover, leftover.Length).ConfigureAwait(false); - } - catch (Exception ex) when (!ex.IsFatal()) - { - ErrorHandler.Error("RemoteSyslogAppender: send failed during shutdown", ex, ErrorCode.FlushFailure); - } - } - } - } } \ No newline at end of file diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/remotesyslogappender.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/remotesyslogappender.adoc index ee03fa78..54e712f9 100644 --- a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/remotesyslogappender.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/remotesyslogappender.adoc @@ -42,6 +42,13 @@ You can also specify: * Facility (default: user) * Identity (default: application name) +* SendQueueSize (default: 500), how many datagrams may wait to be sent +* EnqueueTimeoutMillis (default: 5000), how long a logging call waits for room in a full queue + +Datagrams are handed to a background thread, so a slow or unreachable syslog server does not hold +up logging. Once the queue is full, a logging call waits `EnqueueTimeoutMillis` for room and the +datagram is then discarded and counted, rather than growing the queue without limit. `Flush` waits +for the queue to drain. [source,xml] ---- From 14c9e26a8b0f7f6bedab8dec045071c7d2245adc Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 22:47:26 +0200 Subject: [PATCH 10/12] cap the per-event retry in AdoNetAppender #314 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. --- src/changelog/3.5.0/314-adonet-retry-cap.xml | 14 ++ .../Appender/AdoNet/Log4NetCommand.cs | 6 + .../Appender/AdoNetAppenderTest.cs | 126 ++++++++++++++++++ src/log4net/Appender/AdoNetAppender.cs | 27 ++++ 4 files changed, 173 insertions(+) create mode 100644 src/changelog/3.5.0/314-adonet-retry-cap.xml diff --git a/src/changelog/3.5.0/314-adonet-retry-cap.xml b/src/changelog/3.5.0/314-adonet-retry-cap.xml new file mode 100644 index 00000000..4a32b49b --- /dev/null +++ b/src/changelog/3.5.0/314-adonet-retry-cap.xml @@ -0,0 +1,14 @@ + + + + + stop `AdoNetAppender` from retrying a whole batch one event at a time when none of them can be + written. Retrying after a rolled back transaction was added in 3.4.0 to save the events around + the one the database rejected, but a batch that fails outright, such as a missing table or a + missing permission, then cost one round trip per event: 513 instead of 1 for a full buffer. It + now gives up after five consecutive failures (implemented by @FreeAndNil) + + diff --git a/src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs b/src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs index 7a44dea2..280f484f 100644 --- a/src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs +++ b/src/log4net.Tests/Appender/AdoNet/Log4NetCommand.cs @@ -60,6 +60,7 @@ public int ExecuteNonQuery() } payload ??= CommandText; + AttemptCount++; if (ExceptionTrigger is not null && payload?.IndexOf(ExceptionTrigger, StringComparison.Ordinal) >= 0) { @@ -79,6 +80,11 @@ public int ExecuteNonQuery() /// public int ExecuteNonQueryCount { get; private set; } + /// + /// Every attempt across all instances, failed ones included. + /// + internal static int AttemptCount { get; set; } + /// /// When set, throws for every command whose payload /// contains this string, simulating a database that rejects specific content. diff --git a/src/log4net.Tests/Appender/AdoNetAppenderTest.cs b/src/log4net.Tests/Appender/AdoNetAppenderTest.cs index af339681..c03f99b4 100644 --- a/src/log4net.Tests/Appender/AdoNetAppenderTest.cs +++ b/src/log4net.Tests/Appender/AdoNetAppenderTest.cs @@ -501,4 +501,130 @@ public void NullPropertyProgrammaticConfig() Assert.That(param.Value, Is.Not.EqualTo(SystemInfo.NullText)); Assert.That(param.Value, Is.EqualTo(DBNull.Value)); } + + /// + /// Retrying one by one exists to save the events around the one the database rejected. When + /// every one of them fails, the batch is not the problem and each further round trip only + /// learns that again. + /// + [Test] + public void RetryingPerEventGivesUpAfterRepeatedFailures() + { + const int bufferSize = 19; + // One inside the transaction, then five one by one before it gives up. + const int expectedAttempts = 6; + + Log4NetCommand.AttemptCount = 0; + Log4NetCommand.ExceptionTrigger = "Message"; + try + { + XmlDocument log4NetConfig = new(); + log4NetConfig.LoadXml( + """ + + + + + + + + + + + + + + + + + + + + + + """); + + ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); + XmlConfigurator.Configure(rep, log4NetConfig["log4net"]!); + ILog log = LogManager.GetLogger(rep.Name, nameof(RetryingPerEventGivesUpAfterRepeatedFailures)); + + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + // The event after the buffer is full flushes all twenty. + for (int i = 0; i <= bufferSize; i++) + { + log.Debug("Message"); + } + }); + + Assert.That(Log4NetCommand.AttemptCount, Is.EqualTo(expectedAttempts)); + } + finally + { + Log4NetCommand.ExceptionTrigger = null; + Log4NetCommand.ExecutedPayloads.Clear(); + } + } + + /// + /// Giving up must not cost the events around a rejected one, which is the whole point of + /// retrying: five failures spread out are not five in a row. + /// + [Test] + public void RetryingPerEventKeepsGoingWhileFailuresAreSpreadOut() + { + const int bufferSize = 9; + const int expectedWrites = 5; + + Log4NetCommand.AttemptCount = 0; + Log4NetCommand.ExceptionTrigger = "POISON"; + try + { + XmlDocument log4NetConfig = new(); + log4NetConfig.LoadXml( + """ + + + + + + + + + + + + + + + + + + + + + + """); + + ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); + XmlConfigurator.Configure(rep, log4NetConfig["log4net"]!); + ILog log = LogManager.GetLogger(rep.Name, nameof(RetryingPerEventKeepsGoingWhileFailuresAreSpreadOut)); + + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + for (int i = 0; i <= bufferSize; i++) + { + log.Debug(i % 2 == 0 ? "POISON" : $"good {i}"); + } + }); + + Assert.That(Log4NetCommand.ExecutedPayloads, Has.Count.EqualTo(expectedWrites)); + Assert.That(Log4NetCommand.ExecutedPayloads, Has.Member("good 9")); + } + finally + { + Log4NetCommand.ExceptionTrigger = null; + Log4NetCommand.ExecutedPayloads.Clear(); + } + } } diff --git a/src/log4net/Appender/AdoNetAppender.cs b/src/log4net/Appender/AdoNetAppender.cs index c3fd833a..08b69726 100644 --- a/src/log4net/Appender/AdoNetAppender.cs +++ b/src/log4net/Appender/AdoNetAppender.cs @@ -549,6 +549,7 @@ protected virtual void SendBuffer(IDbTransaction? dbTran, LoggingEvent[] events) // rejects must not stop the remaining events from being written. In transaction // mode the exception has to propagate - the transaction is in a failed state - // and SendBuffer retries the events individually after the rollback. + _eventFailed = true; ErrorHandler.Error("Exception while writing a logging event to the database. Continuing with the remaining events.", ex); } } @@ -577,6 +578,7 @@ protected virtual void SendBuffer(IDbTransaction? dbTran, LoggingEvent[] events) catch (Exception ex) when (dbTran is null && !ex.IsFatal()) { // See the parameterized path above: contain per-event failures outside transactions. + _eventFailed = true; ErrorHandler.Error("Exception while writing a logging event to the database. Continuing with the remaining events.", ex); } } @@ -604,6 +606,7 @@ protected virtual void SendBuffer(IDbTransaction? dbTran, LoggingEvent[] events) /// private void SendBufferPerEvent(LoggingEvent[] events) { + int failuresInARow = 0; foreach (LoggingEvent e in events) { if (Connection is not { State: ConnectionState.Open }) @@ -612,17 +615,41 @@ private void SendBufferPerEvent(LoggingEvent[] events) return; } + _eventFailed = false; try { SendBuffer(null, [e]); } catch (Exception ex) when (!ex.IsFatal()) { + _eventFailed = true; ErrorHandler.Error("Exception while writing a logging event to the database. The event has been dropped.", ex); } + + if (!_eventFailed) + { + failuresInARow = 0; + } + else if (++failuresInARow >= MaxFailuresInARow) + { + // Retrying one by one is meant to save the events around the one the database rejected. + // This many in a row means the batch is not the problem, and the remaining events would + // cost one round trip each to learn the same thing. + ErrorHandler.Error( + $"Giving up on the remaining logging events after {failuresInARow} consecutive failures."); + return; + } } } + /// + /// Set by the contained per-event failure path in , + /// which reports rather than throws, so can count failures. + /// + private bool _eventFailed; + + private const int MaxFailuresInARow = 5; + /// /// Prepare entire database command object to be executed. /// From 629a9e06b5f5704bc2fbbe73319b014c38f9f91c Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 22:56:22 +0200 Subject: [PATCH 11/12] cite the right audit finding for the PowerShell version gate #314 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. da18b6fd-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. --- src/changelog/3.5.0/313-require-powershell-74.xml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/changelog/3.5.0/313-require-powershell-74.xml b/src/changelog/3.5.0/313-require-powershell-74.xml index 9b3636ee..3222a5e4 100644 --- a/src/changelog/3.5.0/313-require-powershell-74.xml +++ b/src/changelog/3.5.0/313-require-powershell-74.xml @@ -9,6 +9,6 @@ `$PSNativeCommandUseErrorActionPreference`, which exists only from 7.4, so under Windows PowerShell 5.1 a failing `gpg --verify` was ignored and `verify-release.ps1` reported success and exited 0. The scripts now refuse to start on an older host, and the review instructions install PowerShell 7 and - run the script with `pwsh` (audit da18b6fd-f004) + run the script with `pwsh` (audit 1231d72-f009) From 46affe17af63cdafb33e9468a3ab1953e1a1aa4f Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 23:30:37 +0200 Subject: [PATCH 12/12] wait for the background sender in the buffered mail test #314 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. --- src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs b/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs index 21fc6599..24da27ee 100644 --- a/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs +++ b/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs @@ -574,7 +574,7 @@ public void BufferedEventsAreSentInASingleMail() appender.DoAppend(CreateEvent("three")); Assert.That(_transport.SentMails, Is.Empty, "the buffer is not full yet"); - appender.Flush(true); + Assert.That(appender.Flush(FlushTimeoutMillis), Is.True); Assert.That(_transport.SentMails, Has.Count.EqualTo(1)); string body = _transport.SentMails[0].Body; @@ -599,6 +599,7 @@ public void RequiresALayout() appender.ActivateOptions(); appender.DoAppend(CreateEvent("no layout")); + appender.Flush(FlushTimeoutMillis); Assert.That(_transport.SentMails, Is.Empty); Assert.That(_errorHandler.Message, Is.Not.Empty);