From a6d28365ffd7d7e91f4bed0d2183365bad568f96 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 21:06:49 +0200 Subject: [PATCH 01/23] 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/23] 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/23] 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/23] 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/23] 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/23] 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/23] 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/23] 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/23] 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/23] 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/23] 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/23] 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); From 4058cff47c294ddaf242e07ea90dce1d0d15cab5 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 23:24:52 +0200 Subject: [PATCH 13/23] move SyslogNewLineHandling out of RemoteSyslogAppender #315 LocalSyslogAppender needs the same option, so nesting it in one of the two appenders no longer fits. Breaking for code naming RemoteSyslogAppender.SyslogNewLineHandling. Configuration binds the value by name and is unaffected. --- .../315-syslog-newline-handling-type.xml | 13 +++++ .../Appender/RemoteSyslogAppenderTest.cs | 12 ++--- src/log4net/Appender/RemoteSyslogAppender.cs | 21 -------- src/log4net/Appender/SyslogNewLineHandling.cs | 48 +++++++++++++++++++ 4 files changed, 67 insertions(+), 27 deletions(-) create mode 100644 src/changelog/3.5.0/315-syslog-newline-handling-type.xml create mode 100644 src/log4net/Appender/SyslogNewLineHandling.cs diff --git a/src/changelog/3.5.0/315-syslog-newline-handling-type.xml b/src/changelog/3.5.0/315-syslog-newline-handling-type.xml new file mode 100644 index 00000000..39ac9502 --- /dev/null +++ b/src/changelog/3.5.0/315-syslog-newline-handling-type.xml @@ -0,0 +1,13 @@ + + + + + move `SyslogNewLineHandling` out of `RemoteSyslogAppender` to `log4net.Appender`, now that + `LocalSyslogAppender` uses it too. Configuration files are unaffected, they bind the value by + name, but code naming `RemoteSyslogAppender.SyslogNewLineHandling` has to drop the prefix + (implemented by @FreeAndNil) + + diff --git a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs index 5b187822..acf1cbe7 100644 --- a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs +++ b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs @@ -154,7 +154,7 @@ public void RemoteSyslogTest() /// /// Test for the - /// with + /// with /// /// /// https://github.com/apache/logging-log4net/issues/274 @@ -171,7 +171,7 @@ public void RemoteSyslogNewLineHandlingEscapeTest() /// /// Test for the - /// with + /// with /// /// /// https://github.com/apache/logging-log4net/issues/274 @@ -180,7 +180,7 @@ public void RemoteSyslogNewLineHandlingEscapeTest() public void RemoteSyslogNewLineHandlingKeepTest() { List sentBytes = ExecuteAppend("Test\r\nmessage", - RemoteSyslogAppender.SyslogNewLineHandling.Keep); + SyslogNewLineHandling.Keep); // ReSharper disable once StringLiteralTypo const string expectedData = "<14>TestDomain: INFO - Test\r\nmessage"; Assert.That(sentBytes, Has.Count.EqualTo(1)); @@ -189,7 +189,7 @@ public void RemoteSyslogNewLineHandlingKeepTest() /// /// Test for the - /// with + /// with /// /// /// https://github.com/apache/logging-log4net/issues/274 @@ -198,7 +198,7 @@ public void RemoteSyslogNewLineHandlingKeepTest() public void RemoteSyslogNewLineHandlingSplitTest() { List sentBytes = ExecuteAppend("Test\r\nmessage", - RemoteSyslogAppender.SyslogNewLineHandling.Split); + SyslogNewLineHandling.Split); // ReSharper disable once StringLiteralTypo Assert.That(sentBytes, Has.Count.EqualTo(2)); const string expectedData0 = "<14>TestDomain: INFO - Test"; @@ -266,7 +266,7 @@ public void IdentityWithoutControlCharactersIsUnchangedAndNotReported() } private static List ExecuteAppend(string message, - RemoteSyslogAppender.SyslogNewLineHandling newLineHandling = default, + SyslogNewLineHandling newLineHandling = default, string? identity = null) { System.Net.IPAddress ipAddress = new([127, 0, 0, 1]); diff --git a/src/log4net/Appender/RemoteSyslogAppender.cs b/src/log4net/Appender/RemoteSyslogAppender.cs index e2d6cd30..ec9ea4a1 100644 --- a/src/log4net/Appender/RemoteSyslogAppender.cs +++ b/src/log4net/Appender/RemoteSyslogAppender.cs @@ -256,27 +256,6 @@ public enum SyslogFacility Local7 = 23 } - /// - /// Options for handling newlines (\r or \n) in - /// - public enum SyslogNewLineHandling - { - /// - /// escape the newlines (\\r for \r and \\n for \n) - /// - Escape, - - /// - /// split the message at new lines - /// - Split, - - /// - /// keep newlines as is (many syslog servers can handle newlines in the message part) - /// - Keep - } - private const int CloseTimeoutMillis = 5_000; private IUdpConnection? _connection; private BackgroundSender? _sender; diff --git a/src/log4net/Appender/SyslogNewLineHandling.cs b/src/log4net/Appender/SyslogNewLineHandling.cs new file mode 100644 index 00000000..975af25a --- /dev/null +++ b/src/log4net/Appender/SyslogNewLineHandling.cs @@ -0,0 +1,48 @@ +#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 + +namespace log4net.Appender; + +/// +/// Options for handling the newlines (\r or \n) in logged content, used by +/// and . +/// +/// +/// +/// A newline ends the record for a syslog daemon that writes the message through to a line +/// oriented log, so content could otherwise forge a second, authentic looking entry. +/// +/// +public enum SyslogNewLineHandling +{ + /// + /// escape the newlines (\\r for \r and \\n for \n) + /// + Escape, + + /// + /// split the message at new lines + /// + Split, + + /// + /// keep newlines as is (many syslog servers can handle newlines in the message part) + /// + Keep +} From 470e710a06bc49aa1b95e71c77ecb88d2ffb57f6 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 23:25:43 +0200 Subject: [PATCH 14/23] escape newlines in LocalSyslogAppender content #315 A newline in logged content ends the record for a syslog daemon that writes the message through to a line oriented log, so content could forge a second entry that looks authentic. The code claimed syslog(3) escapes control characters itself. It does not: glibc formats the buffer and hands it over, and the escaping seen on a mainstream Linux is the daemon's. Measured with LOG_PERROR, an embedded newline comes out as two lines. NewLineHandling mirrors the option RemoteSyslogAppender has had all along, which already escaped by default. Keep restores the previous behaviour. The remote appender's habit of dropping non-ASCII is deliberately not copied. --- .../3.5.0/315-local-syslog-newlines.xml | 15 ++++++ .../Appender/LocalSyslogAppenderTest.cs | 45 +++++++++++++++- src/log4net/Appender/LocalSyslogAppender.cs | 53 +++++++++++++++++-- .../appenders/localsyslogappender.adoc | 7 +++ 4 files changed, 114 insertions(+), 6 deletions(-) create mode 100644 src/changelog/3.5.0/315-local-syslog-newlines.xml diff --git a/src/changelog/3.5.0/315-local-syslog-newlines.xml b/src/changelog/3.5.0/315-local-syslog-newlines.xml new file mode 100644 index 00000000..4c7a6a47 --- /dev/null +++ b/src/changelog/3.5.0/315-local-syslog-newlines.xml @@ -0,0 +1,15 @@ + + + + + escape the newlines in logged content in `LocalSyslogAppender`, which passed them to + `syslog(3)` unchanged. A daemon that writes the message through to a line oriented log then + records everything after the newline as its own entry, so content could forge an authentic + looking record (CWE-117). `NewLineHandling` mirrors the option of the same name on + `RemoteSyslogAppender`, which already escaped by default; set it to `Keep` for the previous + behaviour (audit da18b6fd-f008) + + diff --git a/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs b/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs index be09b7f9..1a3627d2 100644 --- a/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs +++ b/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs @@ -55,8 +55,7 @@ public void EveryNulCharacterIsEscaped() => Assert.That(EscapeNulCharacters("a\0b\0c"), Is.EqualTo("a\\0b\\0c")); /// - /// A message without a NUL character has to come through untouched, including the newlines an - /// exception layout produces: syslog(3) deals with those itself. + /// This escape is only about NUL. Newlines are . /// [Test] public void MessagesWithoutNulCharactersAreUnchanged() @@ -114,6 +113,48 @@ private static IntPtr CurrentIdentityHandle() .GetField("_handleToIdentity", BindingFlags.Static | BindingFlags.NonPublic)! .GetValue(null)!; + /// + /// A newline ends the record for a daemon that writes the message through to a line oriented + /// log, so content could otherwise forge a second entry. glibc does not escape it. + /// + [Test] + public void NewLinesAreEscaped() + => Assert.That(EscapeNewLines("value\r\nJan 1 00:00:00 host sshd[1]: forged"), + Is.EqualTo("value\\r\\nJan 1 00:00:00 host sshd[1]: forged")); + + /// Both characters count, on their own as well as paired. + [TestCase("a\rb", "a\\rb")] + [TestCase("a\nb", "a\\nb")] + [TestCase("a\n\nb", "a\\n\\nb")] + public void EveryNewLineIsEscaped(string message, string expected) + => Assert.That(EscapeNewLines(message), Is.EqualTo(expected)); + + /// A message without newlines takes the fast path and comes through untouched. + [Test] + public void MessagesWithoutNewLinesAreUnchanged() + => Assert.That(EscapeNewLines("field=1\tfield=2"), Is.EqualTo("field=1\tfield=2")); + + /// Escaping is the default, because a daemon that splits the record is the common case. + [Test] + public void NewLineHandlingDefaultsToEscape() + => Assert.That(new LocalSyslogAppender().NewLineHandling, + Is.EqualTo(SyslogNewLineHandling.Escape)); + + /// One record per line, and a blank line is no record at all. + [Test] + public void SplittingDropsTheEmptyLines() + => Assert.That(SplitLines("first\r\nsecond\n\nthird\r"), Is.EqualTo(new[] { "first", "second", "third" })); + + private static string EscapeNewLines(string message) + => (string)typeof(LocalSyslogAppender) + .GetMethod("EscapeNewLines", BindingFlags.Static | BindingFlags.NonPublic)! + .Invoke(null, [message])!; + + private static string[] SplitLines(string message) + => (string[])typeof(LocalSyslogAppender) + .GetMethod("SplitLines", BindingFlags.Static | BindingFlags.NonPublic)! + .Invoke(null, [message])!; + private static string EscapeNulCharacters(string message) => (string)typeof(LocalSyslogAppender) .GetMethod("EscapeNulCharacters", BindingFlags.Static | BindingFlags.NonPublic)! diff --git a/src/log4net/Appender/LocalSyslogAppender.cs b/src/log4net/Appender/LocalSyslogAppender.cs index 6c946a1b..1711485f 100644 --- a/src/log4net/Appender/LocalSyslogAppender.cs +++ b/src/log4net/Appender/LocalSyslogAppender.cs @@ -355,11 +355,56 @@ protected override void Append(LoggingEvent loggingEvent) int priority = GeneratePriority(Facility, GetSeverity(loggingEvent.EnsureNotNull().Level)); string message = EscapeNulCharacters(RenderLoggingEvent(loggingEvent)); - // Call the local libc syslog method - // The second argument is a printf style format string + // The second argument is a printf style format string. + if (NewLineHandling == SyslogNewLineHandling.Split) + { + foreach (string line in SplitLines(message)) + { + NativeMethods.syslog(priority, "%s", line); + } + + return; + } + + if (NewLineHandling == SyslogNewLineHandling.Escape) + { + message = EscapeNewLines(message); + } + NativeMethods.syslog(priority, "%s", message); } + /// + /// What to do with the newlines in logged content. Defaults to + /// . + /// + /// + /// A newline in content ends the record for daemons that write the message through to a line + /// oriented log, letting content forge a second, authentic looking entry. + /// + public SyslogNewLineHandling NewLineHandling { get; set; } + = SyslogNewLineHandling.Escape; + + /// + /// Replaces the newlines with a visible \r or \n escape. + /// + /// The rendered message. + /// The message with every newline escaped. + private static string EscapeNewLines(string message) + => message.IndexOf('\r') < 0 && message.IndexOf('\n') < 0 + ? message + : message.Replace("\r", "\\r").Replace("\n", "\\n"); + + /// + /// Splits the message into the lines to send as separate records, dropping the empty ones. + /// + /// The rendered message. + /// One entry per non-empty line. + private static string[] SplitLines(string message) + => message.Split(_newLines, StringSplitOptions.RemoveEmptyEntries); + + private static readonly string[] _newLines = ["\r\n", "\n", "\r"]; + /// /// Replaces NUL characters with a visible \0 escape. /// @@ -373,8 +418,8 @@ protected override void Append(LoggingEvent loggingEvent) /// contain a NUL, so the character is escaped rather than passed through. /// /// - /// Other control characters are left alone: syslog(3) encodes them itself, and newlines - /// are needed for the multi-line output an exception layout produces. + /// Newlines are handled separately, see . Other control characters + /// are passed through. /// /// private static string EscapeNulCharacters(string message) diff --git a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/localsyslogappender.adoc b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/localsyslogappender.adoc index 07459e96..5c5e9eea 100644 --- a/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/localsyslogappender.adoc +++ b/src/site/antora/modules/ROOT/pages/manual/configuration/appenders/localsyslogappender.adoc @@ -38,6 +38,13 @@ You can also specify: * Facility (default: user) * Identity (default: application name) +* NewLineHandling (default: Escape), one of `Escape`, `Split` or `Keep` + +A newline in logged content ends the record for a syslog daemon that writes the message through to +a line oriented log, so content can otherwise forge a second, authentic looking entry. `Escape` +writes them as `\r` and `\n`, `Split` sends one record per line, and `Keep` passes them through +for a daemon that handles multiline messages itself. Note that `syslog(3)` does no escaping of its +own: whatever escaping you see on a mainstream Linux comes from the daemon, not from libc. [source,xml] ---- From 74e938093acb1ca017b897babc8dcbf38939d588 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 23:52:07 +0200 Subject: [PATCH 15/23] escape NUL characters in OutputDebugStringAppender content #315 OutputDebugStringW takes a null terminated string, so a NUL in logged content ended the record there and dropped whatever the layout rendered after it. The escape LocalSyslogAppender already had is now shared by both, since EventLogAppender is the same shape and will want it too. Its tests moved onto the shared helper with it. The appender level test only runs on Windows: Append refuses to run elsewhere. --- .../3.5.0/315-outputdebugstring-nul.xml | 13 ++++++ .../Appender/LocalSyslogAppenderTest.cs | 3 +- .../Appender/OutputDebugAppenderTest.cs | 23 +++++++++++ .../Appender/Internal/NativeStringEscape.cs | 41 +++++++++++++++++++ src/log4net/Appender/LocalSyslogAppender.cs | 23 +---------- .../Appender/OutputDebugStringAppender.cs | 3 +- 6 files changed, 83 insertions(+), 23 deletions(-) create mode 100644 src/changelog/3.5.0/315-outputdebugstring-nul.xml create mode 100644 src/log4net/Appender/Internal/NativeStringEscape.cs diff --git a/src/changelog/3.5.0/315-outputdebugstring-nul.xml b/src/changelog/3.5.0/315-outputdebugstring-nul.xml new file mode 100644 index 00000000..b2adef68 --- /dev/null +++ b/src/changelog/3.5.0/315-outputdebugstring-nul.xml @@ -0,0 +1,13 @@ + + + + + escape NUL characters in `OutputDebugStringAppender` content. `OutputDebugStringW` takes a null + terminated string, so a NUL in logged content ended the record there and silently dropped whatever + the layout rendered after it, exception text and trailing fields included (CWE-158). The escape + `LocalSyslogAppender` already applied is now shared between the two (audit da18b6fd-f009) + + diff --git a/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs b/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs index 1a3627d2..bf9aee71 100644 --- a/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs +++ b/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs @@ -156,7 +156,8 @@ private static string[] SplitLines(string message) .Invoke(null, [message])!; private static string EscapeNulCharacters(string message) - => (string)typeof(LocalSyslogAppender) + => (string)typeof(LocalSyslogAppender).Assembly + .GetType("log4net.Appender.Internal.NativeStringEscape")! .GetMethod("EscapeNulCharacters", BindingFlags.Static | BindingFlags.NonPublic)! .Invoke(null, [message])!; } diff --git a/src/log4net.Tests/Appender/OutputDebugAppenderTest.cs b/src/log4net.Tests/Appender/OutputDebugAppenderTest.cs index 882b1d53..19b84a8a 100644 --- a/src/log4net.Tests/Appender/OutputDebugAppenderTest.cs +++ b/src/log4net.Tests/Appender/OutputDebugAppenderTest.cs @@ -58,6 +58,29 @@ public void AppendShouldNotCauseAnyErrors() log.Debug(DebugMessage); Assert.That(lastDebugString, Is.Not.Null.And.Contains(DebugMessage)); } + + /// + /// OutputDebugStringW takes a null terminated string, so a NUL in content would end the record + /// there and drop whatever the layout rendered after it. + /// + [Test] + public void NulCharactersAreEscapedBeforeTheNativeCall() + { + ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); + string? lastDebugString = null; + OutputAppender appender = new(value => lastDebugString = value) + { + Layout = new SimpleLayout(), + ErrorHandler = new FailOnError() + }; + appender.ActivateOptions(); + BasicConfigurator.Configure(rep, appender); + + LogManager.GetLogger(rep.Name, GetType()).Debug("before\0after"); + + Assert.That(lastDebugString, Does.Contain("before\\0after")); + Assert.That(lastDebugString, Does.Not.Contain("\0")); + } } file sealed class OutputAppender(Action outputDebugString) diff --git a/src/log4net/Appender/Internal/NativeStringEscape.cs b/src/log4net/Appender/Internal/NativeStringEscape.cs new file mode 100644 index 00000000..a4ac1a62 --- /dev/null +++ b/src/log4net/Appender/Internal/NativeStringEscape.cs @@ -0,0 +1,41 @@ +#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 + +namespace log4net.Appender.Internal; + +/// +/// Prepares rendered content for a sink that takes a null terminated string. +/// +internal static class NativeStringEscape +{ + /// + /// Replaces NUL characters with a visible \0 escape. + /// + /// The rendered message. + /// The message with every NUL character escaped. + /// + /// + /// A NUL ends the string for the native sink, dropping everything the layout rendered after it, + /// trailing fields and exception text included. Logged content is not trusted and may well + /// contain a NUL, so the character is escaped rather than passed through. + /// + /// + internal static string EscapeNulCharacters(string message) + => message.IndexOf('\0') < 0 ? message : message.Replace("\0", "\\0"); +} diff --git a/src/log4net/Appender/LocalSyslogAppender.cs b/src/log4net/Appender/LocalSyslogAppender.cs index 1711485f..0e6f7fa9 100644 --- a/src/log4net/Appender/LocalSyslogAppender.cs +++ b/src/log4net/Appender/LocalSyslogAppender.cs @@ -20,6 +20,7 @@ using System; using System.Runtime.InteropServices; +using log4net.Appender.Internal; using log4net.Core; using log4net.Util; @@ -353,7 +354,7 @@ public override void ActivateOptions() protected override void Append(LoggingEvent loggingEvent) { int priority = GeneratePriority(Facility, GetSeverity(loggingEvent.EnsureNotNull().Level)); - string message = EscapeNulCharacters(RenderLoggingEvent(loggingEvent)); + string message = NativeStringEscape.EscapeNulCharacters(RenderLoggingEvent(loggingEvent)); // The second argument is a printf style format string. if (NewLineHandling == SyslogNewLineHandling.Split) @@ -405,26 +406,6 @@ private static string[] SplitLines(string message) private static readonly string[] _newLines = ["\r\n", "\n", "\r"]; - /// - /// Replaces NUL characters with a visible \0 escape. - /// - /// The rendered message. - /// The message with every NUL character escaped. - /// - /// - /// The message is marshaled to libc as a null-terminated string, so a NUL character anywhere in - /// it would end the record there and silently drop everything the layout rendered after it, - /// including trailing fields and exception text. Logged content is not trusted and may well - /// contain a NUL, so the character is escaped rather than passed through. - /// - /// - /// Newlines are handled separately, see . Other control characters - /// are passed through. - /// - /// - private static string EscapeNulCharacters(string message) - => message.IndexOf('\0') < 0 ? message : message.Replace("\0", "\\0"); - /// /// Close the syslog when the appender is closed /// diff --git a/src/log4net/Appender/OutputDebugStringAppender.cs b/src/log4net/Appender/OutputDebugStringAppender.cs index 44442e9d..9c5b01b9 100644 --- a/src/log4net/Appender/OutputDebugStringAppender.cs +++ b/src/log4net/Appender/OutputDebugStringAppender.cs @@ -18,6 +18,7 @@ #endregion using System; +using log4net.Appender.Internal; using log4net.Core; using log4net.Util; @@ -59,7 +60,7 @@ protected override void Append(LoggingEvent loggingEvent) } #endif - _outputDebugString(RenderLoggingEvent(loggingEvent)); + _outputDebugString(NativeStringEscape.EscapeNulCharacters(RenderLoggingEvent(loggingEvent))); } /// From 4e0e3ba37bcf00e889060f4d21d8f5ba744f3984 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Tue, 1 Sep 2026 23:57:40 +0200 Subject: [PATCH 16/23] escape NUL characters in EventLogAppender content #315 ReportEventW takes a null terminated string, so a NUL in logged content ended the stored record there and dropped whatever the layout rendered after it. WriteEntry raises nothing, so the record simply stored short and no ErrorHandler call fired. Measured on Windows 11 build 26200: a 45 character message with a NUL at 23 stored as its 23 character prefix. Escaping happens before the size limit is applied, since it doubles each NUL, and PrepareEventText exists so that ordering can be tested without an event log. --- src/changelog/3.5.0/315-eventlog-nul.xml | 15 ++++++++ .../Appender/EventLogAppenderTest.cs | 37 ++++++++++++++++++- src/log4net/Appender/EventLogAppender.cs | 28 ++++++++++---- 3 files changed, 72 insertions(+), 8 deletions(-) create mode 100644 src/changelog/3.5.0/315-eventlog-nul.xml diff --git a/src/changelog/3.5.0/315-eventlog-nul.xml b/src/changelog/3.5.0/315-eventlog-nul.xml new file mode 100644 index 00000000..2ac7a56f --- /dev/null +++ b/src/changelog/3.5.0/315-eventlog-nul.xml @@ -0,0 +1,15 @@ + + + + + escape NUL characters in `EventLogAppender` content. `ReportEventW` takes a null terminated + string, so a NUL in logged content ended the stored record there and silently dropped whatever + the layout rendered after it, exception text and trailing fields included (CWE-158). `WriteEntry` + raises nothing, so the record simply stored short. Measured on Windows 11 build 26200: of a 45 + character message with a NUL at 23, the 23 character prefix was stored and the rest was gone + (audit da18b6fd-f007) + + diff --git a/src/log4net.Tests/Appender/EventLogAppenderTest.cs b/src/log4net.Tests/Appender/EventLogAppenderTest.cs index ad0cd705..07873db5 100644 --- a/src/log4net.Tests/Appender/EventLogAppenderTest.cs +++ b/src/log4net.Tests/Appender/EventLogAppenderTest.cs @@ -21,6 +21,7 @@ #if NET462_OR_GREATER using System.Diagnostics; +using System.Reflection; using log4net.Appender; using log4net.Core; @@ -81,6 +82,40 @@ public void ActivateOptionsDisablesAppenderIfSourceDoesntExist() eventAppender.ActivateOptions(); Assert.That(eventAppender.Threshold, Is.EqualTo(Level.Off)); } + + /// + /// ReportEventW takes a null terminated string, so a NUL in content ends the stored record + /// there and silently drops whatever the layout rendered after it. Measured on Windows 11 + /// 26200: WriteEntry does not throw, and only the prefix is stored. + /// + [Test] + public void NulCharactersAreEscaped() + => Assert.That(PrepareEventText("before\0after", 100), Is.EqualTo("before\\0after")); + + /// + /// The escape doubles each NUL, so it has to happen before the limit is applied. Escaping + /// afterwards would push a message near the limit back over it. + /// + [Test] + public void EscapingHappensBeforeTheLimitIsApplied() + { + const int maxSize = 4; + + string prepared = PrepareEventText("\0\0\0", maxSize); + + Assert.That(prepared, Has.Length.EqualTo(maxSize)); + Assert.That(prepared, Does.Not.Contain("\0")); + } + + /// A message within the limit and without a NUL comes through untouched. + [Test] + public void MessagesWithinTheLimitAreUnchanged() + => Assert.That(PrepareEventText("field=1\tfield=2", 100), Is.EqualTo("field=1\tfield=2")); + + private static string PrepareEventText(string rendered, int maxSize) + => (string)typeof(EventLogAppender) + .GetMethod("PrepareEventText", BindingFlags.Static | BindingFlags.NonPublic)! + .Invoke(null, [rendered, maxSize])!; } -#endif // NET462_OR_GREATER \ No newline at end of file +#endif // NET462_OR_GREATER diff --git a/src/log4net/Appender/EventLogAppender.cs b/src/log4net/Appender/EventLogAppender.cs index 48844cd3..ea5f8894 100644 --- a/src/log4net/Appender/EventLogAppender.cs +++ b/src/log4net/Appender/EventLogAppender.cs @@ -23,6 +23,7 @@ using System.Diagnostics; using log4net.Util; +using log4net.Appender.Internal; using log4net.Core; namespace log4net.Appender; @@ -377,13 +378,7 @@ protected override void Append(LoggingEvent loggingEvent) // Write to the event log try { - string eventTxt = RenderLoggingEvent(loggingEvent); - - // There is a limit of about 32K characters for an event log message - if (eventTxt.Length > _maxEventlogMessageSize) - { - eventTxt = eventTxt.Substring(0, _maxEventlogMessageSize); - } + string eventTxt = PrepareEventText(RenderLoggingEvent(loggingEvent), _maxEventlogMessageSize); EventLogEntryType entryType = GetEntryType(loggingEvent.Level); @@ -398,6 +393,25 @@ protected override void Append(LoggingEvent loggingEvent) } } + /// + /// Escapes the NUL characters and then applies the message size limit. + /// + /// The rendered event. + /// The largest message the event log accepts. + /// The text to write. + /// + /// + /// The order matters. ReportEventW takes a null terminated string, so a NUL in content + /// ends the stored record there, and escaping doubles each NUL, so escaping after the limit was + /// applied could push the message back over it. + /// + /// + private static string PrepareEventText(string rendered, int maxSize) + { + string escaped = NativeStringEscape.EscapeNulCharacters(rendered); + return escaped.Length > maxSize ? escaped.Substring(0, maxSize) : escaped; + } + /// /// This appender requires a to be set. /// From 890238a0725c567fe6c1d730506faebd82ef975a Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Wed, 2 Sep 2026 00:05:52 +0200 Subject: [PATCH 17/23] escape what RemoteSyslogAppender cannot send instead of deleting it #315 RFC 3164 allows only visible ASCII and space in the message, and everything else fell through the loop unwritten. "Schoenwetter " reached the collector as "Schnwetter ", and a tab vanished from between its neighbours, with no marker and no error. Such characters are now written as a \uXXXX escape, which stays inside the allowed range. Encoding still cannot make the message body non-ASCII, which the appender page now says. --- src/changelog/3.5.0/315-syslog-non-ascii.xml | 14 +++++++++++ .../Appender/RemoteSyslogAppenderTest.cs | 24 +++++++++++++++++++ src/log4net/Appender/RemoteSyslogAppender.cs | 7 ++++++ .../appenders/remotesyslogappender.adoc | 4 ++++ 4 files changed, 49 insertions(+) create mode 100644 src/changelog/3.5.0/315-syslog-non-ascii.xml diff --git a/src/changelog/3.5.0/315-syslog-non-ascii.xml b/src/changelog/3.5.0/315-syslog-non-ascii.xml new file mode 100644 index 00000000..e8020168 --- /dev/null +++ b/src/changelog/3.5.0/315-syslog-non-ascii.xml @@ -0,0 +1,14 @@ + + + + + escape the characters `RemoteSyslogAppender` cannot send instead of deleting them. RFC 3164 + allows only the visible ASCII characters and space, and everything else was dropped silently, so + `Schönwetter 你好` reached the collector as `Schnwetter ` and a tab disappeared + from between its neighbours. Such characters are now written as a `\uXXXX` escape, which keeps + the record inside the allowed range and readable (audit da18b6fd-f035) + + diff --git a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs index acf1cbe7..149d191b 100644 --- a/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs +++ b/src/log4net.Tests/Appender/RemoteSyslogAppenderTest.cs @@ -69,6 +69,30 @@ private sealed class RecordingErrorHandler : IErrorHandler private const int FlushTimeoutMillis = 30_000; + /// + /// Content outside the RFC 3164 range used to be deleted with no marker, so a message written + /// in a non-Latin script reached the audit trail empty. + /// + [Test] + public void NonAsciiContentIsEscapedAndNotDeleted() + { + List sentBytes = ExecuteAppend("Sch\u00f6nwetter \u4f60\u597d"); + + Assert.That(sentBytes, Has.Count.EqualTo(1)); + Assert.That(Encoding.ASCII.GetString(sentBytes[0]), + Is.EqualTo(@"<14>TestDomain: INFO - Sch\u00f6nwetter \u4f60\u597d")); + } + + /// A control character other than CR or LF was dropped as well. + [Test] + public void OtherControlCharactersAreEscaped() + { + List sentBytes = ExecuteAppend("a\tb"); + + Assert.That(sentBytes, Has.Count.EqualTo(1)); + Assert.That(Encoding.ASCII.GetString(sentBytes[0]), Is.EqualTo(@"<14>TestDomain: INFO - a\u0009b")); + } + /// Bounded, so an unreachable server cannot grow the queue without limit. [Test] public void SendQueueSizeDefaultsTo500() diff --git a/src/log4net/Appender/RemoteSyslogAppender.cs b/src/log4net/Appender/RemoteSyslogAppender.cs index ec9ea4a1..00a55dab 100644 --- a/src/log4net/Appender/RemoteSyslogAppender.cs +++ b/src/log4net/Appender/RemoteSyslogAppender.cs @@ -18,6 +18,7 @@ #endregion using System; +using System.Globalization; using System.Text; using System.Threading; using log4net.Appender.Internal; @@ -484,6 +485,12 @@ protected virtual void AppendMessage(string message, ref int characterIndex, Str break; } } + else + { + // Escaped, not dropped: content is masked visibly rather than deleted. RFC 3164 allows + // only 0x20 to 0x7E here, so the escape itself stays inside that range. + builder.Append("\\u").Append(((int)c).ToString("x4", CultureInfo.InvariantCulture)); + } } } 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 54e712f9..9fef8942 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 @@ -45,6 +45,10 @@ You can also specify: * 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 +RFC 3164 allows only the visible ASCII characters and space in the message, so anything else is +written as a `\uXXXX` escape rather than dropped: a message in a non-Latin script reaches the +collector readable instead of empty. `Encoding` therefore does not make the message body non-ASCII. + 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 From 65430217aada33e22598eeb5400d9a50f5e983db Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Wed, 2 Sep 2026 06:23:27 +0200 Subject: [PATCH 18/23] compare ordinally when asserting no NUL survives #315 Does.Not.Contain is culture sensitive, and a culture sensitive comparison treats NUL as ignorable: it reports a match in a string that contains none. Both new escape tests therefore failed on Windows against correctly escaped output. ContainsConstraint has no comparison knob at all, so these use Contains.Substring(x).Using(StringComparison.Ordinal), negated with the ! operator Constraint defines. The EventLog test asserts the whole value instead, which is ordinal and pins the length too. This is the shape f018 reports in StringMatchFilter, which is still open. --- src/log4net.Tests/Appender/EventLogAppenderTest.cs | 5 +++-- src/log4net.Tests/Appender/OutputDebugAppenderTest.cs | 6 ++++-- 2 files changed, 7 insertions(+), 4 deletions(-) diff --git a/src/log4net.Tests/Appender/EventLogAppenderTest.cs b/src/log4net.Tests/Appender/EventLogAppenderTest.cs index 07873db5..e5dfc293 100644 --- a/src/log4net.Tests/Appender/EventLogAppenderTest.cs +++ b/src/log4net.Tests/Appender/EventLogAppenderTest.cs @@ -103,8 +103,9 @@ public void EscapingHappensBeforeTheLimitIsApplied() string prepared = PrepareEventText("\0\0\0", maxSize); - Assert.That(prepared, Has.Length.EqualTo(maxSize)); - Assert.That(prepared, Does.Not.Contain("\0")); + // Equality is ordinal, and pins the length and the absence of a NUL in one go. Escaping the + // three NULs gives six characters, so the limit has to cut it back to four. + Assert.That(prepared, Is.EqualTo(@"\0\0")); } /// A message within the limit and without a NUL comes through untouched. diff --git a/src/log4net.Tests/Appender/OutputDebugAppenderTest.cs b/src/log4net.Tests/Appender/OutputDebugAppenderTest.cs index 19b84a8a..5d03f02e 100644 --- a/src/log4net.Tests/Appender/OutputDebugAppenderTest.cs +++ b/src/log4net.Tests/Appender/OutputDebugAppenderTest.cs @@ -78,8 +78,10 @@ public void NulCharactersAreEscapedBeforeTheNativeCall() LogManager.GetLogger(rep.Name, GetType()).Debug("before\0after"); - Assert.That(lastDebugString, Does.Contain("before\\0after")); - Assert.That(lastDebugString, Does.Not.Contain("\0")); + // Ordinal throughout: a culture sensitive comparison treats NUL as ignorable, so it reports a + // match in a string that has none. + Assert.That(lastDebugString, Contains.Substring("before\\0after").Using(StringComparison.Ordinal)); + Assert.That(lastDebugString, !Contains.Substring("\0").Using(StringComparison.Ordinal)); } } From fc122b10fb2397dca84a2ecda1a54ce2bef285d2 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Wed, 2 Sep 2026 22:41:04 +0200 Subject: [PATCH 19/23] compute the EventLog size limit instead of guessing it #315 The limit is a whole record budget, and the log name, the source and the machine name are spent from it one character for one. The fixed 31837 sat above the real ceiling, so log4net truncated to a size the service then discarded: the event was lost whole rather than shortened, with no exception and no record. Measured on Windows 11 build 26200 over five source name lengths and two log names with no residual: stored while message + logName + applicationName stays within 31736. One character more and nothing is stored. ApplicationName defaults to the app domain name, so the consumer's assembly name came out of the budget invisibly. A 1024 margin is held back because crossing the line is not one lost message: the write still consumes log space, and a log given about thirty of them was later found reporting a negative record count. Truncation is now reported through the error handler. There is no channel where the service records a dropped write, so that is the only signal available. --- .../3.5.0/315-eventlog-size-budget.xml | 17 +++++++ .../Appender/EventLogAppenderTest.cs | 38 ++++++++++++++++ src/log4net/Appender/EventLogAppender.cs | 45 ++++++++++++++++--- 3 files changed, 94 insertions(+), 6 deletions(-) create mode 100644 src/changelog/3.5.0/315-eventlog-size-budget.xml diff --git a/src/changelog/3.5.0/315-eventlog-size-budget.xml b/src/changelog/3.5.0/315-eventlog-size-budget.xml new file mode 100644 index 00000000..faa41f34 --- /dev/null +++ b/src/changelog/3.5.0/315-eventlog-size-budget.xml @@ -0,0 +1,17 @@ + + + + + stop `EventLogAppender` truncating to a size the event log then discards. The limit is a whole + record budget that the log name, the source and the machine name are spent from, so the fixed + 31837 was above the real ceiling: measured on Windows 11 build 26200, a record is stored while + `message + logName + applicationName` stays within 31736 characters, and one character beyond + that the service stores nothing and reports nothing. The whole event was lost rather than + shortened, and `applicationName` defaults to the app domain name, so a consumer with a long + assembly name lost more. The limit is now computed, and a truncation is reported through the + error handler, which is the only signal available (audit da18b6fd-f030) + + diff --git a/src/log4net.Tests/Appender/EventLogAppenderTest.cs b/src/log4net.Tests/Appender/EventLogAppenderTest.cs index e5dfc293..9abfc4b7 100644 --- a/src/log4net.Tests/Appender/EventLogAppenderTest.cs +++ b/src/log4net.Tests/Appender/EventLogAppenderTest.cs @@ -117,6 +117,44 @@ private static string PrepareEventText(string rendered, int maxSize) => (string)typeof(EventLogAppender) .GetMethod("PrepareEventText", BindingFlags.Static | BindingFlags.NonPublic)! .Invoke(null, [rendered, maxSize])!; + + /// + /// The limit is a whole record budget: the source is spent from it one character for one, so a + /// longer ApplicationName has to leave less room for the message. + /// + [Test] + public void TheSourceNameIsSpentFromTheMessageBudget() + { + const int difference = 44; + int shortSource = GetMaxMessageSize(new() { LogName = "Application", ApplicationName = "abc" }); + int longSource = GetMaxMessageSize(new() { LogName = "Application", ApplicationName = new('a', 3 + difference) }); + + Assert.That(shortSource - longSource, Is.EqualTo(difference)); + } + + /// + /// And so is the log name, which is the half of the budget that was not expected. + /// + [Test] + public void TheLogNameIsSpentFromTheMessageBudgetToo() + { + const int difference = 7; + int shortLog = GetMaxMessageSize(new() { LogName = "Application", ApplicationName = "abc" }); + int longLog = GetMaxMessageSize(new() { LogName = new('L', 11 + difference), ApplicationName = "abc" }); + + Assert.That(shortLog - longLog, Is.EqualTo(difference)); + } + + /// Names long enough to exhaust the budget must not produce a negative length. + [Test] + public void TheLimitNeverGoesBelowZero() + => Assert.That(GetMaxMessageSize(new() { LogName = new('L', 40000), ApplicationName = "abc" }), + Is.EqualTo(0)); + + private static int GetMaxMessageSize(EventLogAppender appender) + => (int)typeof(EventLogAppender) + .GetMethod("GetMaxMessageSize", BindingFlags.Instance | BindingFlags.NonPublic)! + .Invoke(appender, [])!; } #endif // NET462_OR_GREATER diff --git a/src/log4net/Appender/EventLogAppender.cs b/src/log4net/Appender/EventLogAppender.cs index ea5f8894..ed54c855 100644 --- a/src/log4net/Appender/EventLogAppender.cs +++ b/src/log4net/Appender/EventLogAppender.cs @@ -378,7 +378,16 @@ protected override void Append(LoggingEvent loggingEvent) // Write to the event log try { - string eventTxt = PrepareEventText(RenderLoggingEvent(loggingEvent), _maxEventlogMessageSize); + string escaped = NativeStringEscape.EscapeNulCharacters(RenderLoggingEvent(loggingEvent)); + int maxSize = GetMaxMessageSize(); + string eventTxt = PrepareEventText(escaped, maxSize); + if (eventTxt.Length < escaped.Length) + { + // The only signal there is: the service reports neither a truncated nor a dropped record. + ErrorHandler.Error( + $"Truncated a logging event from {escaped.Length} to {maxSize} characters for log [{LogName}] " + + $"using source [{ApplicationName}]. What the layout rendered after that is not in the record."); + } EventLogEntryType entryType = GetEntryType(loggingEvent.Level); @@ -412,6 +421,26 @@ private static string PrepareEventText(string rendered, int maxSize) return escaped.Length > maxSize ? escaped.Substring(0, maxSize) : escaped; } + /// + /// The largest message this appender may hand to the event log. + /// + /// What is left of the record budget once the names are spent from it. + /// + /// Computed, not a constant: defaults to the app domain name, so + /// the consumer's assembly name comes out of the budget. The machine name is subtracted on the + /// assumption that it counts, which cannot be tested without renaming a machine. + /// + private int GetMaxMessageSize() + { + string machineName = MachineName == "." ? Environment.MachineName : MachineName; + int budget = _maxEventlogMessageSize + - LogName.Length + - ApplicationName.Length + - machineName.Length + - MaxEventlogMessageSizeMargin; + return Math.Max(budget, 0); + } + /// /// This appender requires a to be set. /// @@ -527,12 +556,16 @@ public class Level2EventLogEntryType : LevelMappingEntry /// Going over this size may succeed a few times but the buffer will overrun and /// eventually corrupt the log (based on testing). /// - /// The maxEventMsgSize size is based on the max buffer size of the lpStrings parameter of the ReportEvent API. - /// The documented max size for EventLog.WriteEntry for Windows Vista and higher is 31839, but I'm leaving room for a - /// terminator of #0#0, as we cannot see the source of ReportEvent (though we could use an API monitor to examine the - /// buffer, given enough time). + /// Measured on Windows 11 build 26200: a record is stored while message plus log name plus + /// source stays within 31736 characters, and one character more stores nothing at all. /// - private const int MaxEventlogMessageSizeVistaOrNewer = 31839 - 2; + private const int MaxEventlogMessageSizeVistaOrNewer = 31736; + + /// + /// Held back from the computed limit. Crossing it discards the record silently, consumes the + /// log's space anyway, and has been seen to leave the log unreadable. + /// + private const int MaxEventlogMessageSizeMargin = 1024; /// /// The maximum size that the operating system supports for From 3588007ae178f15b1948ec8753ffb83322d87e30 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Thu, 3 Sep 2026 00:11:12 +0200 Subject: [PATCH 20/23] share the content escapes in ContentEscape #315 The helper held only the NUL escape. It now also escapes unpaired surrogates, which f013 needs and f011 will, so the name no longer fitted. --- .../Appender/ContentEscapeTest.cs | 73 +++++++++++++ .../Appender/LocalSyslogAppenderTest.cs | 2 +- src/log4net/Appender/EventLogAppender.cs | 4 +- .../Appender/Internal/ContentEscape.cs | 103 ++++++++++++++++++ .../Appender/Internal/NativeStringEscape.cs | 41 ------- src/log4net/Appender/LocalSyslogAppender.cs | 2 +- .../Appender/OutputDebugStringAppender.cs | 2 +- 7 files changed, 181 insertions(+), 46 deletions(-) create mode 100644 src/log4net.Tests/Appender/ContentEscapeTest.cs create mode 100644 src/log4net/Appender/Internal/ContentEscape.cs delete mode 100644 src/log4net/Appender/Internal/NativeStringEscape.cs diff --git a/src/log4net.Tests/Appender/ContentEscapeTest.cs b/src/log4net.Tests/Appender/ContentEscapeTest.cs new file mode 100644 index 00000000..1935dfc5 --- /dev/null +++ b/src/log4net.Tests/Appender/ContentEscapeTest.cs @@ -0,0 +1,73 @@ +#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.Reflection; + +using log4net.Appender; + +using NUnit.Framework; + +namespace log4net.Tests.Appender; + +/// +/// Tests for the internal ContentEscape helper. +/// +[TestFixture] +public class ContentEscapeTest +{ + /// + /// An unpaired surrogate cannot be encoded, and an encoder that throws costs the event. The + /// input is built here rather than in the attribute: an attribute argument lives in metadata as + /// UTF-8, so the compiler would replace the surrogate with U+FFFD before the test ran. + /// + [TestCase(0xd800)] + [TestCase(0xdbff)] + [TestCase(0xdc00)] + [TestCase(0xdfff)] + public void UnpairedSurrogatesAreEscaped(int surrogate) + { + string input = "before" + (char)surrogate + "after"; + + Assert.That(EscapeUnpairedSurrogates(input), Is.EqualTo($@"before\u{surrogate:x4}after")); + } + + /// Every one of them, not just the first. + [Test] + public void EveryUnpairedSurrogateIsEscaped() + => Assert.That(EscapeUnpairedSurrogates("a" + (char)0xd800 + "b" + (char)0xdc00 + "c"), + Is.EqualTo(@"a\ud800b\udc00c")); + + /// A valid pair is one character and must survive untouched. + [Test] + public void ValidSurrogatePairsAreLeftAlone() + => Assert.That(EscapeUnpairedSurrogates("emoji \U0001F600 here"), Is.EqualTo("emoji \U0001F600 here")); + + /// The common case takes a fast path that must not alter anything. + [TestCase("")] + [TestCase("plain ascii")] + [TestCase("Schönwetter 你好")] + public void MessagesWithoutSurrogatesAreUnchanged(string message) + => Assert.That(EscapeUnpairedSurrogates(message), Is.EqualTo(message)); + + private static string EscapeUnpairedSurrogates(string message) + => (string)typeof(TelnetAppender).Assembly + .GetType("log4net.Appender.Internal.ContentEscape")! + .GetMethod("EscapeUnpairedSurrogates", BindingFlags.Static | BindingFlags.NonPublic)! + .Invoke(null, [message])!; +} diff --git a/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs b/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs index bf9aee71..cd921030 100644 --- a/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs +++ b/src/log4net.Tests/Appender/LocalSyslogAppenderTest.cs @@ -157,7 +157,7 @@ private static string[] SplitLines(string message) private static string EscapeNulCharacters(string message) => (string)typeof(LocalSyslogAppender).Assembly - .GetType("log4net.Appender.Internal.NativeStringEscape")! + .GetType("log4net.Appender.Internal.ContentEscape")! .GetMethod("EscapeNulCharacters", BindingFlags.Static | BindingFlags.NonPublic)! .Invoke(null, [message])!; } diff --git a/src/log4net/Appender/EventLogAppender.cs b/src/log4net/Appender/EventLogAppender.cs index ed54c855..fa0a23d5 100644 --- a/src/log4net/Appender/EventLogAppender.cs +++ b/src/log4net/Appender/EventLogAppender.cs @@ -378,7 +378,7 @@ protected override void Append(LoggingEvent loggingEvent) // Write to the event log try { - string escaped = NativeStringEscape.EscapeNulCharacters(RenderLoggingEvent(loggingEvent)); + string escaped = ContentEscape.EscapeNulCharacters(RenderLoggingEvent(loggingEvent)); int maxSize = GetMaxMessageSize(); string eventTxt = PrepareEventText(escaped, maxSize); if (eventTxt.Length < escaped.Length) @@ -417,7 +417,7 @@ protected override void Append(LoggingEvent loggingEvent) /// private static string PrepareEventText(string rendered, int maxSize) { - string escaped = NativeStringEscape.EscapeNulCharacters(rendered); + string escaped = ContentEscape.EscapeNulCharacters(rendered); return escaped.Length > maxSize ? escaped.Substring(0, maxSize) : escaped; } diff --git a/src/log4net/Appender/Internal/ContentEscape.cs b/src/log4net/Appender/Internal/ContentEscape.cs new file mode 100644 index 00000000..05021f8d --- /dev/null +++ b/src/log4net/Appender/Internal/ContentEscape.cs @@ -0,0 +1,103 @@ +#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.Globalization; +using System.Text; + +namespace log4net.Appender.Internal; + +/// +/// Makes rendered content safe for a sink, without discarding any of it. +/// +internal static class ContentEscape +{ + /// + /// Replaces NUL characters with a visible \0 escape. + /// + /// The rendered message. + /// The message with every NUL character escaped. + /// + /// + /// A NUL ends the string for the native sink, dropping everything the layout rendered after it, + /// trailing fields and exception text included. Logged content is not trusted and may well + /// contain a NUL, so the character is escaped rather than passed through. + /// + /// + internal static string EscapeNulCharacters(string message) + => message.IndexOf('\0') < 0 ? message : message.Replace("\0", "\\0"); + + /// + /// Replaces the surrogates that are not part of a pair with a visible \uXXXX escape. + /// + /// The rendered message. + /// The message with every unpaired surrogate escaped. + /// + /// An unpaired surrogate is a legal but cannot be encoded, and an encoder + /// that throws costs the whole event, so it is escaped rather than left to fail. + /// + internal static string EscapeUnpairedSurrogates(string message) + { + if (!ContainsUnpairedSurrogate(message)) + { + return message; + } + + StringBuilder builder = new(message.Length); + for (int i = 0; i < message.Length; i++) + { + char c = message[i]; + if (char.IsHighSurrogate(c) && i + 1 < message.Length && char.IsLowSurrogate(message[i + 1])) + { + builder.Append(c).Append(message[i + 1]); + i++; + } + else if (char.IsSurrogate(c)) + { + builder.Append("\\u").Append(((int)c).ToString("x4", CultureInfo.InvariantCulture)); + } + else + { + builder.Append(c); + } + } + + return builder.ToString(); + } + + private static bool ContainsUnpairedSurrogate(string message) + { + for (int i = 0; i < message.Length; i++) + { + if (!char.IsSurrogate(message[i])) + { + continue; + } + + if (char.IsHighSurrogate(message[i]) && i + 1 < message.Length && char.IsLowSurrogate(message[i + 1])) + { + i++; + continue; + } + + return true; + } + + return false; + } +} diff --git a/src/log4net/Appender/Internal/NativeStringEscape.cs b/src/log4net/Appender/Internal/NativeStringEscape.cs deleted file mode 100644 index a4ac1a62..00000000 --- a/src/log4net/Appender/Internal/NativeStringEscape.cs +++ /dev/null @@ -1,41 +0,0 @@ -#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 - -namespace log4net.Appender.Internal; - -/// -/// Prepares rendered content for a sink that takes a null terminated string. -/// -internal static class NativeStringEscape -{ - /// - /// Replaces NUL characters with a visible \0 escape. - /// - /// The rendered message. - /// The message with every NUL character escaped. - /// - /// - /// A NUL ends the string for the native sink, dropping everything the layout rendered after it, - /// trailing fields and exception text included. Logged content is not trusted and may well - /// contain a NUL, so the character is escaped rather than passed through. - /// - /// - internal static string EscapeNulCharacters(string message) - => message.IndexOf('\0') < 0 ? message : message.Replace("\0", "\\0"); -} diff --git a/src/log4net/Appender/LocalSyslogAppender.cs b/src/log4net/Appender/LocalSyslogAppender.cs index 0e6f7fa9..dae7f505 100644 --- a/src/log4net/Appender/LocalSyslogAppender.cs +++ b/src/log4net/Appender/LocalSyslogAppender.cs @@ -354,7 +354,7 @@ public override void ActivateOptions() protected override void Append(LoggingEvent loggingEvent) { int priority = GeneratePriority(Facility, GetSeverity(loggingEvent.EnsureNotNull().Level)); - string message = NativeStringEscape.EscapeNulCharacters(RenderLoggingEvent(loggingEvent)); + string message = ContentEscape.EscapeNulCharacters(RenderLoggingEvent(loggingEvent)); // The second argument is a printf style format string. if (NewLineHandling == SyslogNewLineHandling.Split) diff --git a/src/log4net/Appender/OutputDebugStringAppender.cs b/src/log4net/Appender/OutputDebugStringAppender.cs index 9c5b01b9..7a6b0617 100644 --- a/src/log4net/Appender/OutputDebugStringAppender.cs +++ b/src/log4net/Appender/OutputDebugStringAppender.cs @@ -60,7 +60,7 @@ protected override void Append(LoggingEvent loggingEvent) } #endif - _outputDebugString(NativeStringEscape.EscapeNulCharacters(RenderLoggingEvent(loggingEvent))); + _outputDebugString(ContentEscape.EscapeNulCharacters(RenderLoggingEvent(loggingEvent))); } /// From dccaafba2498414abaff4a766f3fc6c5de0561b5 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Thu, 3 Sep 2026 00:11:23 +0200 Subject: [PATCH 21/23] escape what the Telnet writer cannot encode #315 The default writer encoding threw on an unpaired surrogate, and Send reads a throw as a client that hung up, so one event reached nobody and disconnected everybody. Escaped as \uXXXX now; the non-throwing encoding stays as belt and braces. --- .../3.5.0/315-telnet-unencodable-content.xml | 13 +++ .../Appender/TelnetAppenderTest.cs | 81 +++++++++++++++++++ src/log4net/Appender/TelnetAppender.cs | 8 +- 3 files changed, 100 insertions(+), 2 deletions(-) create mode 100644 src/changelog/3.5.0/315-telnet-unencodable-content.xml diff --git a/src/changelog/3.5.0/315-telnet-unencodable-content.xml b/src/changelog/3.5.0/315-telnet-unencodable-content.xml new file mode 100644 index 00000000..ad96651f --- /dev/null +++ b/src/changelog/3.5.0/315-telnet-unencodable-content.xml @@ -0,0 +1,13 @@ + + + + + stop one logging event disconnecting every `TelnetAppender` client. The default writer encoding + throws on content it cannot encode, such as an unpaired surrogate, and `Send` reads any failure as + a client that hung up. Unpaired surrogates are now written as a `\uXXXX` escape, as elsewhere + (audit da18b6fd-f013) + + diff --git a/src/log4net.Tests/Appender/TelnetAppenderTest.cs b/src/log4net.Tests/Appender/TelnetAppenderTest.cs index 5d8f37cd..c0df92b4 100644 --- a/src/log4net.Tests/Appender/TelnetAppenderTest.cs +++ b/src/log4net.Tests/Appender/TelnetAppenderTest.cs @@ -47,6 +47,87 @@ public sealed class TelnetAppenderTest /// https://github.com/apache/logging-log4net/issues/194 /// https://stackoverflow.com/questions/79053363/log4net-telnetappender-doesnt-work-after-migrate-to-log4net-3 /// + /// + /// An unpaired surrogate used to throw while encoding, and Send reads any throw as a client + /// that hung up, so one such event reached nobody and disconnected everybody. + /// + [Test] + public void ContentThatCannotBeEncodedDoesNotDisconnectTheClient() + { + StringBuilder received = new(); + object receivedSyncRoot = new(); + + int port = FindFreeTcpPort(); + XmlDocument log4NetConfig = new(); + log4NetConfig.LoadXml( + $""" + + + + + + + + + + + + + """); + string marker = Guid.NewGuid().ToString(); + ILoggerRepository repository = LogManager.CreateRepository(marker); + XmlConfigurator.Configure(repository, log4NetConfig["log4net"]!); + try + { + using (SimpleTelnetClient telnetClient = new(Received, port)) + { + telnetClient.Run(TestContext.Out.WriteLine); + WaitFor("welcome message", WelcomeMessage); + + ILogger logger = repository.GetLogger("Telnet"); + logger.Log(typeof(TelnetAppenderTest), Level.Info, "poison\ud800event", null); + // The event after it only arrives if the client survived the one before. + logger.Log(typeof(TelnetAppenderTest), Level.Info, marker, null); + WaitFor("the event after the unencodable one", marker); + } + } + finally + { + repository.Shutdown(); + } + + Assert.That(ReceivedText(), Does.Contain(@"poison\ud800event")); + + void Received(string message) + { + lock (receivedSyncRoot) + { + received.Append(message); + } + } + + string ReceivedText() + { + lock (receivedSyncRoot) + { + return received.ToString(); + } + } + + void WaitFor(string what, string expected) + { + Stopwatch stopwatch = Stopwatch.StartNew(); + while (ReceivedText().IndexOf(expected, StringComparison.Ordinal) < 0) + { + if (stopwatch.Elapsed > _receiveTimeout) + { + Assert.Fail($"Timeout waiting for {what} - received so far: '{ReceivedText()}'"); + } + Thread.Sleep(20); + } + } + } + /// /// Maximum time to wait for a message to arrive at the client. /// diff --git a/src/log4net/Appender/TelnetAppender.cs b/src/log4net/Appender/TelnetAppender.cs index a0b04e13..903cd0d5 100644 --- a/src/log4net/Appender/TelnetAppender.cs +++ b/src/log4net/Appender/TelnetAppender.cs @@ -21,8 +21,10 @@ using System.Collections.Generic; using System.Net; using System.Net.Sockets; +using System.Text; using System.IO; using System.Linq; +using log4net.Appender.Internal; using log4net.Core; using log4net.Util; @@ -245,7 +247,9 @@ public SocketClient(Socket socket) _socket = socket; try { - _writer = new(new NetworkStream(socket)); + // Belt and braces. Send escapes what cannot be encoded; this keeps a future gap costing + // one character rather than every client, since Send reads a throw as a hung up client. + _writer = new(new NetworkStream(socket), new UTF8Encoding(false)); } catch (Exception e) when (!e.IsFatal()) { @@ -260,7 +264,7 @@ public SocketClient(Socket socket) /// string to send public void Send(string message) { - _writer.Write(message); + _writer.Write(ContentEscape.EscapeUnpairedSurrogates(message.EnsureNotNull())); _writer.Flush(); } From b3b8bb2fcc18cb6ef78a7a6a385bb25319b1ef1d Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Thu, 3 Sep 2026 00:11:23 +0200 Subject: [PATCH 22/23] record the escaping rule in CLAUDE.md Four appenders have needed the same two escapes. New ones belong in ContentEscape, and escaping comes before any length limit, not after. --- CLAUDE.md | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/CLAUDE.md b/CLAUDE.md index 09b3b901..bba164a2 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -229,9 +229,15 @@ What that leaves for this file is where the answers live in the code: at the site with a link to the model rather than changing the code. `XmlConfigurator` and `XmlHierarchyConfigurator` carry these for the configuration-is-trusted paths, and `SystemStringFormat` for the format string. -- `LocalSyslogAppender.EscapeNulCharacters` and `RemoteSyslogAppender.ValidateIdentity` are the two +- `log4net.Appender.Internal.ContentEscape` and `RemoteSyslogAppender.ValidateIdentity` are the two sides of the content and structural-identifier rule: content is escaped and never rejected, a malformed identifier is reported rather than quietly repaired. +- **A sink that cannot carry a character escapes it visibly, and never drops the character, the + rest of the record, or the event.** The escapes already in use are `\0` for NUL, `\r` and `\n` + for newlines, and `\uXXXX` for anything else, in `ContentEscape` and in + `RemoteSyslogAppender.AppendMessage`. Put new ones in `ContentEscape` rather than in the + appender: four appenders have needed the same two so far. Escaping before a length limit, not + after, since an escape is longer than what it replaces. - Deliberate secure-default choices belong in the changelog with their opt-out named, so that an upgrade surprise is searchable. See the entries for `SendTimeoutMillis`, `MatchTimeoutMillis` and `LockTimeoutMillis`. From ef97324fe0ef593781c94f61ef5cfb6c3ff5b80f Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Thu, 3 Sep 2026 00:19:58 +0200 Subject: [PATCH 23/23] escape what the pickup mail writer cannot encode #315 File.CreateText throws on an unpaired surrogate, which abandoned the whole buffered batch and left a truncated mail for the pickup service to send. Reverting the fix leaves the test with a file that exists and is empty. Writing under the final name stays as it was, with a note why. --- .../315-pickup-dir-unencodable-content.xml | 13 ++++++++++ .../Appender/SmtpPickupDirAppenderTest.cs | 23 +++++++++++++++++ src/log4net/Appender/SmtpPickupDirAppender.cs | 25 ++++++++++++------- 3 files changed, 52 insertions(+), 9 deletions(-) create mode 100644 src/changelog/3.5.0/315-pickup-dir-unencodable-content.xml diff --git a/src/changelog/3.5.0/315-pickup-dir-unencodable-content.xml b/src/changelog/3.5.0/315-pickup-dir-unencodable-content.xml new file mode 100644 index 00000000..8f952bf1 --- /dev/null +++ b/src/changelog/3.5.0/315-pickup-dir-unencodable-content.xml @@ -0,0 +1,13 @@ + + + + + stop one logging event destroying a whole `SmtpPickupDirAppender` batch. `File.CreateText` + throws on content it cannot encode, such as an unpaired surrogate, which abandoned every buffered + event and left a truncated mail in the pickup directory for the service to send. Such content is + now written as a `\uXXXX` escape (audit da18b6fd-f011) + + diff --git a/src/log4net.Tests/Appender/SmtpPickupDirAppenderTest.cs b/src/log4net.Tests/Appender/SmtpPickupDirAppenderTest.cs index 509b42a9..5ba88f03 100644 --- a/src/log4net.Tests/Appender/SmtpPickupDirAppenderTest.cs +++ b/src/log4net.Tests/Appender/SmtpPickupDirAppenderTest.cs @@ -153,6 +153,29 @@ private static void DestroyLogger() LoggerManager.RepositorySelector = new DefaultRepositorySelector(typeof(log4net.Repository.Hierarchy.Hierarchy)); } + /// + /// An unpaired surrogate used to abort the write, losing every buffered event with it and + /// leaving a truncated mail behind for the pickup service to send. + /// + [Test] + public void ContentThatCannotBeEncodedDoesNotDestroyTheBatch() + { + SilentErrorHandler sh = new(); + SmtpPickupDirAppender appender = CreateSmtpPickupDirAppender(sh); + ILogger log = CreateLogger(appender); + + log.Log(GetType(), Level.Info, "poison" + (char)0xd800 + "event", null); + log.Log(GetType(), Level.Info, "the event after it", null); + DestroyLogger(); + + Assert.That(Directory.GetFiles(_testPickupDir), Has.Length.EqualTo(1)); + string content = File.ReadAllText(Directory.GetFiles(_testPickupDir)[0]); + + Assert.That(content, Does.Contain(@"poison\ud800event")); + Assert.That(content, Does.Contain("the event after it")); + Assert.That(sh.Message, Is.EqualTo(string.Empty), "Unexpected error message"); + } + /// /// Tests if the sent message contained the date header. /// diff --git a/src/log4net/Appender/SmtpPickupDirAppender.cs b/src/log4net/Appender/SmtpPickupDirAppender.cs index 6cb88c80..86c17c79 100644 --- a/src/log4net/Appender/SmtpPickupDirAppender.cs +++ b/src/log4net/Appender/SmtpPickupDirAppender.cs @@ -20,6 +20,9 @@ using System; using System.IO; +using System.Globalization; +using System.Text; +using log4net.Appender.Internal; using log4net.Core; using log4net.Util; @@ -128,10 +131,15 @@ protected override void SendBuffer(LoggingEvent[] events) StreamWriter writer; // Impersonate to open the file + // Written under its final name, so a failure mid write leaves a partial mail for the pickup + // service. Accepted: no temporary name is safe for every service, and FileExtension is the + // operator's to choose. string filePath = Path.Combine(PickupDir.EnsureNotNull(), Guid.NewGuid().ToString("N") + _fileExtension); using (SecurityContext?.Impersonate(this)) { - writer = File.CreateText(filePath); + // Not File.CreateText: its encoding throws on content it cannot encode, which would + // abandon the whole batch and leave a truncated mail for the pickup service to send. + writer = new StreamWriter(filePath, false, new UTF8Encoding(false)); } using (writer) @@ -142,22 +150,21 @@ protected override void SendBuffer(LoggingEvent[] events) writer.WriteLine("Date: " + DateTime.UtcNow.ToString("r")); writer.WriteLine(); - string? t = Layout?.Header; - if (t is not null) + if (Layout?.Header is string header) { - writer.Write(t); + writer.Write(header); } for (int i = 0; i < events.Length; i++) { - // Render the event and append the text to the buffer - RenderLoggingEvent(writer, events[i]); + using StringWriter rendered = new(CultureInfo.InvariantCulture); + RenderLoggingEvent(rendered, events[i]); + writer.Write(ContentEscape.EscapeUnpairedSurrogates(rendered.ToString())); } - t = Layout?.Footer; - if (t is not null) + if (Layout?.Footer is string footer) { - writer.Write(t); + writer.Write(footer); } writer.WriteLine();