From 73b9a17e110bcb6a04c3257d68e6aec9a4710165 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Sat, 12 Sep 2026 00:55:18 +0200 Subject: [PATCH 01/14] keep the log when a roll cannot rename it #319 - A failed rename was reported, then the file reopened without appending, which destroyed it. A backup agent holding a read handle is enough. It appends now, and only that rename is retried, once per MaxFileSize of growth, so the backups are never rotated twice and a retry that succeeds keeps the generation it recovers. - The footer, close and open paths released the file lock even when acquiring it had failed. Only what was taken is released now. audit da18b6fd-f036, da18b6fd-f032 --- CLAUDE.md | 12 + .../3.5.0/319-lock-level-underflow.xml | 13 + .../3.5.0/319-rollover-keeps-events.xml | 15 + .../Appender/LockingStreamTest.cs | 143 +++++++ .../RollingFileAppenderRollFailureTest.cs | 349 ++++++++++++++++++ src/log4net/Appender/FileAppender.cs | 86 +++-- src/log4net/Appender/RollingFileAppender.cs | 144 +++++++- 7 files changed, 715 insertions(+), 47 deletions(-) create mode 100644 src/changelog/3.5.0/319-lock-level-underflow.xml create mode 100644 src/changelog/3.5.0/319-rollover-keeps-events.xml create mode 100644 src/log4net.Tests/Appender/LockingStreamTest.cs create mode 100644 src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs diff --git a/CLAUDE.md b/CLAUDE.md index 0e7bcaa23..3c3ecc5ea 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -26,6 +26,8 @@ almost always be doing. Omit the type wherever the target is known, including `return new(…);` and `=> new(…);`, where the enclosing member's return type supplies it. It cannot be omitted when the target type is an interface or abstract class, as in `Func f = () => new MailKitSmtpTransport();`. +- `x?.Method() ?? false` rather than `x is not null && x.Method()`, and merge nested guards + into one condition. - Expression-bodied members whenever the body fits on one line, including constructors (`resharper_constructor_or_destructor_body = expression_body`). - Braces on `if`/`else` bodies even for a single statement. @@ -149,6 +151,13 @@ almost always be doing. the assertion is about control characters, use `Contains.Substring(x).Using(StringComparison.Ordinal)`, negated with the `!` operator that `Constraint` defines, or assert the whole value with `Is.EqualTo`, which is ordinal. +- **Order `[TestCase]` attributes shortest to longest by source line**, not by argument length. +- **If no black-box test can reach a defect, extract the sequence into a small private helper + and drive that by reflection.** Do not delete the test and call the defect untestable. The + extraction is usually an improvement anyway: `FileAppender.RunWithBestEffortLock` replaced two + copies of an acquire/release pair, one of which released a lock it had failed to take. +- **A test that passes before the fix is worthless.** Revert the production change and watch + it fail; if it does not, the test is wrong or the defect is not where you think it is. - **Give a `[TestCase]` an explicit `TestName` when an argument holds a control character.** Otherwise the whole fixture can become invisible to `dotnet test --filter`, silently: it is listed by `--list-tests` and runs in a full pass, but every filter reports "No test matches". @@ -206,6 +215,9 @@ Every user-visible change gets an entry in `src/changelog//` `missing attribute: link` otherwise, which is only caught by the Maven site build. - Put anything that has no issue number, such as an external finding identifier, in the description text rather than inventing an `` for it. +- **The description is whitespace-collapsed before the AsciiDoc transform, so block syntax does + not survive.** No bullets, no code blocks: `*` ends up mid-sentence as a literal asterisk. + Write prose. Bullets are fine in commit messages. - Close the description with an attribution in parentheses, crediting both sides: who raised it and who did the work, as in `(reported by @viktorgobbi, fixed by @FreeAndNil)`. `implemented by` reads better than `fixed by` for an `added` or `changed` entry, and once a pull request exists the house diff --git a/src/changelog/3.5.0/319-lock-level-underflow.xml b/src/changelog/3.5.0/319-lock-level-underflow.xml new file mode 100644 index 000000000..82cf7dcd4 --- /dev/null +++ b/src/changelog/3.5.0/319-lock-level-underflow.xml @@ -0,0 +1,13 @@ + + + + Stop the file lock counter going negative. Writing the footer, + closing the writer and opening the file released the lock even when acquiring it had failed, and a + negative count made every later acquisition fail. The footer and close paths share one helper now, + which releases only what it took; opening keeps its own acquire, because wrapping an unlocked + stream throws. Nothing was lost by this, because the appender reopens the file on the next + event (audit da18b6fd-f032, fixed by @FreeAndNil) + diff --git a/src/changelog/3.5.0/319-rollover-keeps-events.xml b/src/changelog/3.5.0/319-rollover-keeps-events.xml new file mode 100644 index 000000000..9ccb7fdb0 --- /dev/null +++ b/src/changelog/3.5.0/319-rollover-keeps-events.xml @@ -0,0 +1,15 @@ + + + + Keep the log file when a rollover cannot rename it. The failed rename + was reported and the file then reopened without appending, which destroyed everything it held; a + reader holding the file without `FILE_SHARE_DELETE`, such as a backup or antivirus agent, is enough + to cause it. The file is appended to now. Only the rename that failed is retried, once per + `MaxFileSize` of growth, which is the cadence a working rollover would have had, because a full + retry would shift the numbered backups again and lose the oldest one every time; the file + therefore grows past `MaxFileSize` for as long as the rename keeps failing (audit da18b6fd-f036, + fixed by @FreeAndNil) + diff --git a/src/log4net.Tests/Appender/LockingStreamTest.cs b/src/log4net.Tests/Appender/LockingStreamTest.cs new file mode 100644 index 000000000..abe9d49c6 --- /dev/null +++ b/src/log4net.Tests/Appender/LockingStreamTest.cs @@ -0,0 +1,143 @@ +#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.IO; +using System.Reflection; +using System.Text; + +using log4net.Appender; + +using NUnit.Framework; + +namespace log4net.Tests.Appender; + +/// The recursion counter inside the private FileAppender.LockingStream. +[TestFixture] +public sealed class LockingStreamTest +{ + /// Hands out a stream only when told to, so a failed acquisition can be staged. + private sealed class SwitchableLock : FileAppender.LockingModelBase + { + internal bool CanAcquire { get; set; } + + internal int ReleaseCount { get; private set; } + + public override Stream? AcquireLock() => CanAcquire ? Stream.Null : null; + + public override void ReleaseLock() => ReleaseCount++; + + public override void OpenFile(string filename, bool append, Encoding encoding) + { } + + public override void CloseFile() + { } + + public override void ActivateOptions() + { } + + public override void OnClose() + { } + } + + /// + /// An unmatched release drove the counter below zero, after which every later acquisition failed + /// and the model lock was never released. + /// + [Test] + public void AnUnmatchedReleaseDoesNotBreakTheNextAcquisition() + { + SwitchableLock model = new() { CanAcquire = false }; + object stream = NewLockingStream(model); + + // What the footer, close and open paths used to do. + Assert.That(Invoke(stream, "AcquireLock"), Is.False, "the model was set up to refuse"); + Invoke(stream, "ReleaseLock"); + + model.CanAcquire = true; + + Assert.That(Invoke(stream, "AcquireLock"), Is.True, + "the counter went negative, so the stream could never be locked again"); + Invoke(stream, "ReleaseLock"); + Assert.That(model.ReleaseCount, Is.EqualTo(1), "the model lock must be released exactly once"); + } + + /// Nesting still locks and releases the model once. + [Test] + public void NestedAcquisitionsReleaseTheModelOnce() + { + SwitchableLock model = new() { CanAcquire = true }; + object stream = NewLockingStream(model); + + Assert.That(Invoke(stream, "AcquireLock"), Is.True); + Assert.That(Invoke(stream, "AcquireLock"), Is.True); + Invoke(stream, "ReleaseLock"); + Assert.That(model.ReleaseCount, Is.EqualTo(0), "still held by the outer acquisition"); + + Invoke(stream, "ReleaseLock"); + Assert.That(model.ReleaseCount, Is.EqualTo(1)); + } + + /// + /// The footer, close and open paths run through one helper. The work has to happen either way, + /// because closing is what releases the OS handle, but only a lock that was taken may be released. + /// + [Test] + public void RunWithBestEffortLockRunsTheWorkButReleasesOnlyWhatItTook() + { + SwitchableLock model = new() { CanAcquire = false }; + FileAppender appender = new(); + SetStream(appender, NewLockingStream(model)); + + bool ran = false; + RunWithBestEffortLock(appender, () => ran = true); + Assert.That(ran, Is.True, "the work must run even without the lock, or the file is never closed"); + Assert.That(model.ReleaseCount, Is.EqualTo(0), "released a lock it never took"); + + model.CanAcquire = true; + ran = false; + + RunWithBestEffortLock(appender, () => ran = true); + Assert.That(ran, Is.True); + Assert.That(model.ReleaseCount, Is.EqualTo(1), "the counter went negative, so nothing locked again"); + } + + + private static void SetStream(FileAppender appender, object stream) + => typeof(FileAppender).GetField("_stream", BindingFlags.Instance | BindingFlags.NonPublic)! + .SetValue(appender, stream); + + private static void RunWithBestEffortLock(FileAppender appender, Action action) + => typeof(FileAppender).GetMethod("RunWithBestEffortLock", BindingFlags.Instance | BindingFlags.NonPublic)! + .Invoke(appender, [action]); + + private static object NewLockingStream(FileAppender.LockingModelBase model) + { + Type type = typeof(FileAppender).GetNestedType("LockingStream", BindingFlags.NonPublic) + ?? throw new InvalidOperationException("FileAppender.LockingStream is gone"); + return Activator.CreateInstance(type, BindingFlags.Instance | BindingFlags.NonPublic | BindingFlags.Public, + null, [model], null) + ?? throw new InvalidOperationException("could not construct a LockingStream"); + } + + private static void Invoke(object target, string method) => Invoke(target, method); + + private static T Invoke(object target, string method) + => (T)target.GetType().GetMethod(method)!.Invoke(target, null)!; +} diff --git a/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs b/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs new file mode 100644 index 000000000..13d926106 --- /dev/null +++ b/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.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.IO; +using log4net.Appender; +using log4net.Core; +using log4net.Layout; +using log4net.Tests.Integration; +using log4net.Util; + +using NUnit.Framework; + +namespace log4net.Tests.Appender; + +/// +/// What does when a roll cannot complete. Every test here blocks +/// the base rename with , which leaves the archive shift working, so the +/// state under test is the reported one: a reader holding the log file and nothing else. +/// +[TestFixture] +public sealed class RollingFileAppenderRollFailureTest +{ + private const string Marker = "must survive the failed roll"; + + private string _directory = string.Empty; + private readonly Internal.RecordingErrorHandler _errors = new(); + + [SetUp] + public void SetUp() + { + _directory = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString("N")); + Directory.CreateDirectory(_directory); + _errors.Messages.Clear(); + } + + [TearDown] + public void TearDown() + { + if (Directory.Exists(_directory)) + { + Directory.Delete(_directory, true); + } + } + + /// + /// A failed rename leaves the file in place, and reopening it without appending destroyed it. + /// The archive it shifted on the way must not be shifted a second time. + /// + [Test] + [NonParallelizable] + public void AFailedRollKeepsTheEventsItCouldNotMove() + { + string file = Path.Combine(_directory, "roll-failure.log"); + RollingFileAppender appender = new() + { + File = file, + Layout = new PatternLayout("%message%newline"), + RollingStyle = RollingFileAppender.RollingMode.Size, + MaxSizeRollBackups = 3, + MaximumFileSize = "200", + AppendToFile = true, + LockingModel = new FileAppender.MinimalLock(), + ErrorHandler = _errors + }; + appender.ActivateOptions(); + + try + { + // Two ordinary rolls, so there is an archive to rotate. + appender.DoAppend(CreateEvent(new string('a', 200))); + appender.DoAppend(CreateEvent(new string('a', 200))); + appender.DoAppend(CreateEvent(new string('a', 200))); + + BlockRename(file + ".1"); + + // The file is already over the limit, so this event rolls first and the roll is the one that + // fails. What it writes afterwards is the content the failed roll used to destroy. + LogLog.ExecuteWithoutEmittingInternalMessages(() => appender.DoAppend(CreateEvent(Marker))); + Assert.That(_errors.Messages, Is.Not.Empty, "the roll never failed, so nothing was exercised"); + + // That first attempt shifts the archive before failing on the base file, which is + // unavoidable. What must not happen is a second shift. + string[] afterFirstFailure = Backups(file); + Assert.That(afterFirstFailure, Is.Not.Empty, "the fixture needs an archive for the roll to shift"); + string[] contentAfterFirstFailure = Array.ConvertAll(afterFirstFailure, File.ReadAllText); + + // Events well under MaxFileSize, so a retry per MaxFileSize of growth is measurably rarer + // than a retry per event. At 200 bytes each the two cadences would be the same thing. + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + for (int i = 0; i < 20; i++) + { + appender.DoAppend(CreateEvent(new string('b', 50))); + } + }); + + Assert.That(Backups(file), Is.EqualTo(afterFirstFailure), + "the archive was rotated again while the rename kept failing"); + Assert.That(Array.ConvertAll(afterFirstFailure, File.ReadAllText), Is.EqualTo(contentAfterFirstFailure), + "the backup contents were rewritten while the rename kept failing"); + // Only the base rename is retried, and only once the file has grown another MaxFileSize, + // so the attempts are far fewer than the 20 events above. + Assert.That(BaseRenameAttempts(file), Is.LessThan(20), + "the rename was retried per event instead of per MaxFileSize of growth"); + } + finally + { + LogLog.ExecuteWithoutEmittingInternalMessages(appender.Close); + } + + Assert.That(File.ReadAllText(file), Does.Contain(Marker), + "the roll could not rename the file, so reopening it must not have truncated it"); + } + + /// + /// The same failure with a dated name, where the file being rolled is not the configured one. + /// Testing the base file's existence instead of the one the rename could not move passes here + /// and truncates anyway. + /// + [Test] + [NonParallelizable] + public void AFailedRollKeepsTheEventsWhenTheFileNameIsDated() + { + string file = Path.Combine(_directory, "roll-failure.log"); + RollingFileAppender appender = new() + { + File = file, + Layout = new PatternLayout("%message%newline"), + RollingStyle = RollingFileAppender.RollingMode.Composite, + DatePattern = "'.'yyyy-MM-dd", + StaticLogFileName = false, + MaxSizeRollBackups = 3, + MaximumFileSize = "200", + AppendToFile = true, + LockingModel = new FileAppender.MinimalLock(), + ErrorHandler = _errors + }; + appender.ActivateOptions(); + + // The file that is written and rolled, which is not the configured name. + string dated = appender.File!; + Assert.That(dated, Is.Not.EqualTo(file), "the fixture needs a name the configured one does not match"); + + try + { + appender.DoAppend(CreateEvent(new string('a', 200))); + + BlockRename(dated + ".1"); + + // Rolls first, fails on the dated name, and keeps what the rename could not move. + LogLog.ExecuteWithoutEmittingInternalMessages( + () => appender.DoAppend(CreateEvent(new string('b', 200)))); + Assert.That(_errors.Messages, Is.Not.Empty, "the roll never failed, so nothing was exercised"); + + // Written into the file the failed rename left behind, so a truncating reopen destroys it. + appender.DoAppend(CreateEvent(Marker)); + + // Grow past the retry threshold, so the base rename is attempted and fails again. + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + for (int i = 0; i < 20; i++) + { + appender.DoAppend(CreateEvent(new string('b', 200))); + } + }); + } + finally + { + LogLog.ExecuteWithoutEmittingInternalMessages(appender.Close); + } + + Assert.That(File.ReadAllText(dated), Does.Contain(Marker), + "the roll could not rename the dated file, so reopening it must not have truncated it"); + } + + /// + /// A retry that succeeds moves the kept file into the archive, and the next roll has to shift + /// that generation rather than overwrite it. + /// + [Test] + [NonParallelizable] + public void ASuccessfulRetryKeepsTheBackupItRecovered() + { + string file = Path.Combine(_directory, "roll-failure.log"); + RollingFileAppender appender = new() + { + File = file, + Layout = new PatternLayout("%message%newline"), + RollingStyle = RollingFileAppender.RollingMode.Size, + // Far more than the run needs, so nothing may be discarded as too old. + MaxSizeRollBackups = 10, + MaximumFileSize = "200", + AppendToFile = true, + LockingModel = new FileAppender.MinimalLock(), + ErrorHandler = _errors + }; + appender.ActivateOptions(); + + try + { + appender.DoAppend(CreateEvent(new string('a', 200))); + + BlockRename(file + ".1"); + + // Rolls first, fails, and is then written into the file the rename could not move. + LogLog.ExecuteWithoutEmittingInternalMessages(() => appender.DoAppend(CreateEvent(Marker))); + Assert.That(_errors.Messages, Is.Not.Empty, "the roll never failed, so nothing was exercised"); + + // The obstruction is gone, so the next retry succeeds. + UnblockRename(file + ".1"); + + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + for (int i = 0; i < 20 && !ArchiveHolds(file, Marker); i++) + { + appender.DoAppend(CreateEvent(new string('b', 200))); + } + }); + Assert.That(ArchiveHolds(file, Marker), Is.True, + "the retry never moved the kept file into the archive, so nothing was recovered"); + + // One ordinary roll on top of the recovered generation. + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + for (int i = 0; i < 2; i++) + { + appender.DoAppend(CreateEvent(new string('c', 200))); + } + }); + } + finally + { + LogLog.ExecuteWithoutEmittingInternalMessages(appender.Close); + } + + Assert.That(ArchiveHolds(file, Marker), Is.True, + "the roll after the retry overwrote the backup the retry had just recovered"); + } + + /// + /// A failed base rename leaves the numbered files one slot higher than the backup count says, + /// and the time roll has to take that top one with it. + /// + [Test] + [NonParallelizable] + public void ATimeRollAfterAFailedRenameTakesEveryBackupWithIt() + { + string file = Path.Combine(_directory, "roll-failure.log"); + MockDateTime clock = new(new DateTime(2026, 1, 1, 12, 0, 0, DateTimeKind.Local)); + RollingFileAppender appender = new() + { + File = file, + Layout = new PatternLayout("%message%newline"), + RollingStyle = RollingFileAppender.RollingMode.Composite, + DatePattern = "'.'yyyy-MM-dd", + StaticLogFileName = true, + MaxSizeRollBackups = 5, + MaximumFileSize = "200", + AppendToFile = true, + LockingModel = new FileAppender.MinimalLock(), + DateTimeStrategy = clock, + ErrorHandler = _errors + }; + appender.ActivateOptions(); + + try + { + // Two ordinary rolls, so the marker ends up in the second backup. + appender.DoAppend(CreateEvent(Marker + new string('a', 200))); + appender.DoAppend(CreateEvent(new string('a', 200))); + appender.DoAppend(CreateEvent(new string('a', 200))); + + BlockRename(file + ".1"); + + LogLog.ExecuteWithoutEmittingInternalMessages( + () => appender.DoAppend(CreateEvent(new string('b', 200)))); + Assert.That(_errors.Messages, Is.Not.Empty, "the base rename never failed, so nothing was exercised"); + Assert.That(File.ReadAllText(file + ".3"), Does.Contain(Marker), + "the fixture needs the archive shifted a slot beyond the backup count"); + + // A day later, so the time roll moves the whole group under the dated name. + clock.Now = clock.Now.AddDays(1); + LogLog.ExecuteWithoutEmittingInternalMessages(() => appender.DoAppend(CreateEvent("after midnight"))); + } + finally + { + LogLog.ExecuteWithoutEmittingInternalMessages(appender.Close); + } + + Assert.That(File.Exists(file + ".3"), Is.False, + "the backup stayed under the old base name instead of moving with the group"); + } + + /// + /// Blocks one rename by occupying its target with a directory. + /// throws when the destination exists, and the appender's own delete of the target skips it, + /// because is false for a directory. Only that rename fails, so the + /// archive shift still goes through, which is the reported shape: a reader holding the log file + /// without FILE_SHARE_DELETE. + /// + private static void BlockRename(string target) + { + if (File.Exists(target)) + { + File.Delete(target); + } + + Directory.CreateDirectory(target); + } + + private static void UnblockRename(string target) => Directory.Delete(target, true); + + /// The numbered backups, excluding the log file itself: a `.*` pattern matches it too. + private string[] Backups(string file) + => Array.FindAll(Directory.GetFiles(_directory, "roll-failure.log.*"), + f => !string.Equals(f, file, StringComparison.Ordinal)); + + /// + /// How often the base rename itself was attempted. A failed attempt can report twice, once for + /// the delete of the target and once for the move, so counting messages counts the wrong thing. + /// + private int BaseRenameAttempts(string file) + => _errors.Messages.FindAll(m => m.IndexOf($"[{file}] ->", StringComparison.Ordinal) >= 0).Count; + + /// Whether any numbered backup holds . + private bool ArchiveHolds(string file, string content) + => Array.Exists(Backups(file), + f => File.ReadAllText(f).IndexOf(content, StringComparison.Ordinal) >= 0); + + private static LoggingEvent CreateEvent(string message) + => new(new LoggingEventData { Level = Level.Info, Message = message, LoggerName = "RollFailure" }); +} diff --git a/src/log4net/Appender/FileAppender.cs b/src/log4net/Appender/FileAppender.cs index 5887fbfe7..28f74a170 100644 --- a/src/log4net/Appender/FileAppender.cs +++ b/src/log4net/Appender/FileAppender.cs @@ -194,6 +194,12 @@ public void ReleaseLock() { lock (_syncRoot) { + if (_lockLevel == 0) + { + // Unmatched release: going negative would strand the model lock. + return; + } + _lockLevel--; if (_lockLevel == 0) { @@ -1094,7 +1100,7 @@ protected override void PrepareWriter() /// protected override void Append(LoggingEvent loggingEvent) { - if (_stream is not null && _stream.AcquireLock()) + if (_stream?.AcquireLock() ?? false) { try { @@ -1120,7 +1126,7 @@ protected override void Append(LoggingEvent loggingEvent) /// protected override void Append(LoggingEvent[] loggingEvents) { - if (_stream is not null && _stream.AcquireLock()) + if (_stream?.AcquireLock() ?? false) { try { @@ -1143,19 +1149,8 @@ protected override void Append(LoggingEvent[] loggingEvents) /// protected override void WriteFooter() { - if (_stream is not null) - { - //WriteFooter can be called even before a file is opened - _stream.AcquireLock(); - try - { - base.WriteFooter(); - } - finally - { - _stream.ReleaseLock(); - } - } + //WriteFooter can be called even before a file is opened + RunWithBestEffortLock(base.WriteFooter); } /// @@ -1168,18 +1163,15 @@ protected override void WriteFooter() /// protected override void WriteHeader() { - if (_stream is not null) + if (_stream?.AcquireLock() ?? false) { - if (_stream.AcquireLock()) + try { - try - { - base.WriteHeader(); - } - finally - { - _stream.ReleaseLock(); - } + base.WriteHeader(); + } + finally + { + _stream.ReleaseLock(); } } } @@ -1194,18 +1186,8 @@ protected override void WriteHeader() /// protected override void CloseWriter() { - if (_stream is not null) - { - _stream.AcquireLock(); - try - { - base.CloseWriter(); - } - finally - { - _stream.ReleaseLock(); - } - } + // An already closed writer cannot take the lock. + RunWithBestEffortLock(base.CloseWriter); } /// @@ -1242,6 +1224,28 @@ protected virtual void SafeOpenFile(string fileName, bool append) } } + /// + /// Runs under the file lock if it can be taken, releasing only what it + /// took. It runs unlocked too, because closing has to happen: that is what frees the handle. + /// and deliberately skip their work + /// instead when the lock is refused, so they keep their own acquire. + /// + private void RunWithBestEffortLock(Action action) + { + bool locked = _stream?.AcquireLock() ?? false; + try + { + action(); + } + finally + { + if (locked) + { + _stream!.ReleaseLock(); + } + } + } + /// /// Sets and opens the file where the log output will go. The specified file must be writable. /// @@ -1289,9 +1293,9 @@ protected virtual void OpenFile(string fileName, bool append) LockingModel.OpenFile(fileName, append, Encoding); _stream = new LockingStream(LockingModel); - if (_stream is not null) + // Wrapping an unlocked stream throws, so say why instead of trying. + if (_stream.AcquireLock()) { - _stream.AcquireLock(); try { SetQWForFiles(_stream); @@ -1301,6 +1305,10 @@ protected virtual void OpenFile(string fileName, bool append) _stream.ReleaseLock(); } } + else + { + ErrorHandler.Error($"Could not acquire the lock on {fileName} to open it."); + } WriteHeader(); } diff --git a/src/log4net/Appender/RollingFileAppender.cs b/src/log4net/Appender/RollingFileAppender.cs index a15e8f979..1339bb619 100644 --- a/src/log4net/Appender/RollingFileAppender.cs +++ b/src/log4net/Appender/RollingFileAppender.cs @@ -128,6 +128,16 @@ namespace log4net.Appender; // ReSharper disable GrammarMistakeInComment public partial class RollingFileAppender : FileAppender { + /// A base rename that failed, kept whole so its parts cannot drift apart. + /// The file that could not be moved. + /// Where it was heading. + /// + /// Whether the caller undid a increment, which a successful + /// retry has to put back. The time roll does not touch the counter, the size roll does. + /// + /// The size the file must reach before the rename is attempted again. + private sealed record PendingRename(string From, string To, bool WasBackupCountReverted, long RetryAtCount = 0); + /// /// Style of rolling to use /// @@ -556,9 +566,17 @@ protected virtual void AdjustFileBeforeAppend() } } - if (_rollSize && (File is not null) && ((CountingQuietTextWriter)QuietWriter!).Count >= MaxFileSize) + if (_rollSize && (File is not null) + && ((CountingQuietTextWriter)QuietWriter!).Count >= MaxFileSize) { - RollOverSize(); + if (_pendingRename is null) + { + RollOverSize(); + } + else if (((CountingQuietTextWriter)QuietWriter).Count >= _pendingRename.RetryAtCount) + { + RetryFailedRoll(); + } } } finally @@ -623,7 +641,10 @@ protected override void OpenFile(string fileName, bool append) base.OpenFile(fileName, append); // Set the file size onto the counting writer - ((CountingQuietTextWriter)QuietWriter!).Count = currentCount; + if (QuietWriter is CountingQuietTextWriter countingWriter) + { + countingWriter.Count = currentCount; + } } } @@ -1001,6 +1022,8 @@ public static RollPoint ComputeCheckPeriod(string datePattern) /// public override void ActivateOptions() { + _pendingRename = null; + if (_rollDate && DatePattern is not null) { _now = DateTimeStrategy.Now; @@ -1081,6 +1104,15 @@ private string CombinePath(string path1, string path2) /// protected void RollOverTime(bool fileIsOpen) { + if (_pendingRename is { WasBackupCountReverted: true }) + { + // The failed size rename left the numbered files a slot higher than the count says, and the + // group move below walks the count. Without this the top backup stays behind. + CurrentSizeRollBackups++; + } + + // A time roll that renames successfully proves the obstruction is gone. + _pendingRename = null; if (StaticLogFileName) { // Compute filename, but only if datePattern is specified @@ -1114,7 +1146,10 @@ protected void RollOverTime(bool fileIsOpen) RollFile(from, to); } - RollFile(File!, _scheduledFilename!); + if (!TryRollFile(File!, _scheduledFilename!)) + { + RecordFailedBaseRename(File!, _scheduledFilename!, wasBackupCountReverted: false); + } } //We've cleared out the old date and are ready for the new @@ -1126,7 +1161,15 @@ protected void RollOverTime(bool fileIsOpen) if (fileIsOpen) { // This will also close the file. This is OK since multiple close operations are safe. - SafeOpenFile(_baseFileName!, false); + // A failed rename leaves the file in place; appending keeps what it holds. + SafeOpenFile(_baseFileName!, ShouldAppendAfterFailedRoll()); + // Its own threshold, or the one from a size failure would fire a retry immediately. + ScheduleRollRetry(); + } + else + { + // The startup roll, with no file open to grow, so nothing can trigger a retry. As before. + _pendingRename = null; } } @@ -1159,6 +1202,7 @@ protected void RollFile(string fromFile, string toFile) } catch (Exception e) when (!e.IsFatal()) { + _rollFailures++; ErrorHandler.Error($"Exception while rolling file [{fromFile}] -> [{toFile}]", e, ErrorCode.GenericFailure); } } @@ -1287,6 +1331,7 @@ protected void RollOverSize() LogLog.Debug(_declaringType, $"curSizeRollBackups [{CurrentSizeRollBackups}]"); LogLog.Debug(_declaringType, $"countDirection [{CountDirection}]"); + _pendingRename = null; if (File is not null) { RollOverRenameFiles(File); @@ -1298,7 +1343,72 @@ protected void RollOverSize() } // This will also close the file. This is OK since multiple close operations are safe. - SafeOpenFile(_baseFileName!, false); + // A failed rename leaves the file in place; appending keeps what it holds. + SafeOpenFile(_baseFileName!, ShouldAppendAfterFailedRoll()); + + if (_pendingRename is not null) + { + ScheduleRollRetry(); + // The failing rename already reported, and OnlyOnceErrorHandler silences the handler after + // the first report, so this one goes through LogLog to survive. + LogLog.Error(_declaringType, + $"Rolling {_pendingRename.From} failed, so it is kept and appended to. Only that rename is " + + "retried, once per MaxFileSize of growth, so the backups are left alone."); + } + } + + /// Remembers the base rename to retry, without touching the archive again. + private void RecordFailedBaseRename(string fromFile, string toFile, bool wasBackupCountReverted) + => _pendingRename = new(fromFile, toFile, wasBackupCountReverted); + + /// + /// Schedules the next attempt at the failed base rename, one of growth + /// away: the cadence a working roll would have had. + /// + private void ScheduleRollRetry() + { + // A refused lock leaves no writer, and then the threshold simply stays where it was. + if (_pendingRename is not null && QuietWriter is CountingQuietTextWriter countingWriter) + { + _pendingRename = _pendingRename with { RetryAtCount = countingWriter.Count + MaxFileSize }; + } + } + + /// + /// Retries only the base rename, never the archive shift, so the backups are not rotated twice. + /// When the shift succeeded the target slot is still free. When it failed too, the target may be + /// occupied and deletes it, which is what that call has always done. + /// + private void RetryFailedRoll() + { + CloseFile(); + PendingRename pending = _pendingRename!; + if (TryRollFile(pending.From, pending.To)) + { + if (pending.WasBackupCountReverted) + { + // The slot the failed rename left empty is filled now, so the backup it gave up is real + // again. Without this the next roll shifts nothing and overwrites what was just recovered. + CurrentSizeRollBackups++; + } + + _pendingRename = null; + } + + SafeOpenFile(_baseFileName!, ShouldAppendAfterFailedRoll()); + ScheduleRollRetry(); + } + + /// Whether a rename failed and left the file, so it must be appended to. + private bool ShouldAppendAfterFailedRoll() + => _pendingRename is not null && FileExists(_pendingRename.From); + + /// Renames as does, reporting whether it worked. + private bool TryRollFile(string fromFile, string toFile) + { + int failuresBefore = _rollFailures; + RollFile(fromFile, toFile); + return _rollFailures == failuresBefore; } /// @@ -1353,7 +1463,11 @@ protected virtual void RollOverRenameFiles(string baseFileName) CurrentSizeRollBackups++; // Rename fileName to fileName.1 - RollFile(baseFileName, CombinePath(baseFileName, ".1")); + if (!TryRollFile(baseFileName, CombinePath(baseFileName, ".1"))) + { + CurrentSizeRollBackups--; + RecordFailedBaseRename(baseFileName, CombinePath(baseFileName, ".1"), wasBackupCountReverted: true); + } } else { @@ -1402,7 +1516,12 @@ protected virtual void RollOverRenameFiles(string baseFileName) if (StaticLogFileName) { CurrentSizeRollBackups++; - RollFile(baseFileName, CombinePath(baseFileName, "." + CurrentSizeRollBackups)); + if (!TryRollFile(baseFileName, CombinePath(baseFileName, "." + CurrentSizeRollBackups))) + { + CurrentSizeRollBackups--; + RecordFailedBaseRename(baseFileName, CombinePath(baseFileName, "." + (CurrentSizeRollBackups + 1)), + wasBackupCountReverted: true); + } } } } @@ -1526,6 +1645,15 @@ protected static DateTime NextCheckDate(DateTime currentDateTime, RollPoint roll /// private bool _rollDate = true; + /// + /// The base rename waiting to be retried, or null when none is. A + /// override that renames itself bypasses it. + /// + private PendingRename? _pendingRename; + + /// How many renames have failed, so one call can be told apart. + private int _rollFailures; + /// /// Cache flag set if we are rolling by size. /// From 18bc141dc498d3e33bb620db012c9e250fec1866 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Mon, 14 Sep 2026 22:10:32 +0200 Subject: [PATCH 02/14] name the file lock mutex after the resolved path #319 - InterProcessLock named its mutex before the path was resolved, so a relative and an absolute spelling of one file took two mutexes and excluded nothing. - A name over 255 characters throws on Unix, out of ActivateOptions, so a deep log path took the appender down. Those are hashed now. Windows has no limit, measured, so its names are left alone and keep excluding older versions. - Both mutexes take their name from one helper, which carries why there is no ACL, no Global\ prefix and no user component. audit da18b6fd-f031, da18b6fd-f010 --- src/changelog/3.5.0/319-mutex-name-length.xml | 14 ++ .../3.5.0/319-mutex-resolved-path.xml | 15 ++ .../Appender/FileAppenderMutexNameTest.cs | 222 ++++++++++++++++++ src/log4net/Appender/FileAppender.cs | 54 ++++- src/log4net/Appender/RollingFileAppender.cs | 6 +- src/log4net/Util/SystemInfo.cs | 6 + 6 files changed, 303 insertions(+), 14 deletions(-) create mode 100644 src/changelog/3.5.0/319-mutex-name-length.xml create mode 100644 src/changelog/3.5.0/319-mutex-resolved-path.xml create mode 100644 src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs diff --git a/src/changelog/3.5.0/319-mutex-name-length.xml b/src/changelog/3.5.0/319-mutex-name-length.xml new file mode 100644 index 000000000..c9ac89d8f --- /dev/null +++ b/src/changelog/3.5.0/319-mutex-name-length.xml @@ -0,0 +1,14 @@ + + + + Keep logging to a deep path on Unix. Both the rolling lock and the + inter-process file lock name their mutex after the log file, and Unix rejects a name longer than + 255 characters, throwing out of `ActivateOptions` and taking the appender with it before anything + was written. Such a name is replaced by a hash of the path now. Windows enforces no + length limit at all, and names are left alone there, so the only ones that change are the ones + that used to throw and exclusion against an older version is nowhere affected (audit + da18b6fd-f010, da18b6fd-f031, fixed by @FreeAndNil) + diff --git a/src/changelog/3.5.0/319-mutex-resolved-path.xml b/src/changelog/3.5.0/319-mutex-resolved-path.xml new file mode 100644 index 000000000..a4d6d87d2 --- /dev/null +++ b/src/changelog/3.5.0/319-mutex-resolved-path.xml @@ -0,0 +1,15 @@ + + + + Let two processes that spell the log path differently share one + inter-process file lock. `InterProcessLock` named its mutex after the configured path before that + path was resolved, so a relative and an absolute spelling of one file took two different mutexes + and excluded nothing. The name comes from the resolved path now. That resolves a relative path and + nothing else: symbolic links, hard links, 8.3 short names, letter case and UNC versus mapped-drive + spellings still produce different names. The name is also unprefixed, which on Windows makes it + per-session, so a service and an interactive process have never coordinated through it (audit + da18b6fd-f031, fixed by @FreeAndNil) + diff --git a/src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs b/src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs new file mode 100644 index 000000000..6eb3baa05 --- /dev/null +++ b/src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs @@ -0,0 +1,222 @@ +#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.IO; +using System.Reflection; +using System.Text; +using System.Threading; + +using log4net.Appender; +using log4net.Core; +using log4net.Layout; +using log4net.Util; + +using NUnit.Framework; + +namespace log4net.Tests.Appender; + +/// The mutex name the file lock and the rolling lock derive from the log file path. +[TestFixture] +public sealed class FileAppenderMutexNameTest +{ + /// Records what the appender had resolved by the time the locking model was activated. + private sealed class RecordingLock : FileAppender.LockingModelBase + { + internal string? FileAtActivation { get; private set; } + + public override void ActivateOptions() => FileAtActivation = CurrentAppender?.File; + + public override Stream? AcquireLock() => Stream.Null; + + public override void ReleaseLock() + { } + + public override void OpenFile(string filename, bool append, Encoding encoding) + { } + + public override void CloseFile() + { } + + public override void OnClose() + { } + } + + private string _directory = string.Empty; + + [SetUp] + public void SetUp() + { + _directory = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString("N")); + Directory.CreateDirectory(_directory); + } + + [TearDown] + public void TearDown() + { + if (Directory.Exists(_directory)) + { + Directory.Delete(_directory, true); + } + } + + /// + /// The model was activated before the path was resolved, so a relative and an absolute spelling + /// of one file never shared a mutex. + /// + [Test] + [NonParallelizable] + public void TheLockingModelIsActivatedAfterThePathIsResolved() + { + RecordingLock model = new(); + FileAppender appender = new() + { + File = "mutex-name-test.log", + Layout = new PatternLayout("%message%newline"), + LockingModel = model, + ErrorHandler = new Internal.RecordingErrorHandler() + }; + + try + { + LogLog.ExecuteWithoutEmittingInternalMessages(appender.ActivateOptions); + + Assert.That(model.FileAtActivation, Is.Not.Null, "the locking model was never activated"); + Assert.That(Path.IsPathRooted(model.FileAtActivation!), Is.True, + "the locking model named its mutex after an unresolved path"); + Assert.That(model.FileAtActivation, Does.EndWith("mutex-name-test.log")); + } + finally + { + LogLog.ExecuteWithoutEmittingInternalMessages(appender.Close); + string written = appender.File!; + if (File.Exists(written)) + { + File.Delete(written); + } + } + } + + /// A name past the Unix limit took the appender down before anything was logged. + [Test] + [NonParallelizable] + public void ADeepPathStillActivates() + { + // Over the 255 character mutex name limit once "_rolling" is added, under the 260 Windows + // still enforces on net462. + string leaf = new('d', 250 - _directory.Length - "roll.log".Length - 2); + string directory = Path.Combine(_directory, leaf); + Directory.CreateDirectory(directory); + string file = Path.Combine(directory, "roll.log"); + Assert.That(file, Has.Length.EqualTo(250), "the fixture must exceed the mutex name limit"); + + RollingFileAppender appender = new() + { + File = file, + Layout = new PatternLayout("%message%newline"), + RollingStyle = RollingFileAppender.RollingMode.Size, + MaximumFileSize = "10KB", + LockingModel = new FileAppender.MinimalLock(), + ErrorHandler = new Internal.RecordingErrorHandler() + }; + + try + { + appender.ActivateOptions(); + appender.DoAppend(new LoggingEvent(new LoggingEventData + { + Level = Level.Info, + Message = "deep", + LoggerName = "MutexName" + })); + } + finally + { + LogLog.ExecuteWithoutEmittingInternalMessages(appender.Close); + } + + Assert.That(File.ReadAllText(file), Does.Contain("deep")); + } + + /// A name that fits is left alone, so no existing deployment's mutex changes. + [Test] + public void AShortPathKeepsTheNameEarlierVersionsComputed() + => Assert.That(MutexNameForPath("/var/log/app.log", "_rolling"), Is.EqualTo("_var_log_app.log_rolling")); + + /// Under a limit, a long name is hashed below it and stays distinct. + [Test] + public void ALongPathIsHashedWhereThePlatformHasALimit() + { + string deep = "/" + new string('d', 4000) + "/app.log"; + string name = MutexNameForPath(deep, "_rolling", 255); + + Assert.That(name, Has.Length.LessThanOrEqualTo(255)); + Assert.That(name, Does.EndWith("_rolling")); + Assert.That(MutexNameForPath(deep + "x", "_rolling", 255), Is.Not.EqualTo(name), + "two different paths collapsed onto one mutex"); + + // The defect itself: this threw before the cap existed. + using Mutex mutex = new(false, name); + Assert.That(mutex.WaitOne(0), Is.True); + mutex.ReleaseMutex(); + } + + /// With no limit, which is Windows, the name is left as earlier versions computed it. + [Test] + public void ALongPathIsLeftAloneWhereThePlatformHasNoLimit() + { + string deep = "/" + new string('d', 4000) + "/app.log"; + + Assert.That(MutexNameForPath(deep, "_rolling", null), + Is.EqualTo("_" + new string('d', 4000) + "_app.log_rolling")); + } + + /// + /// Which limit the platform gets, expected from this fixture's own check rather than the one + /// under test. On Windows nothing else would notice a wrong gate. + /// + [Test] + public void ThePlatformDecidesWhetherALongNameIsHashed() + { + string deep = "/" + new string('d', 4000) + "/app.log"; + string name = MutexNameForPath(deep, "_rolling"); + + if (Environment.OSVersion.Platform is PlatformID.Unix or PlatformID.MacOSX) + { + Assert.That(name, Has.Length.LessThanOrEqualTo(255), "Unix rejects a longer name"); + } + else + { + Assert.That(name, Has.Length.EqualTo(deep.Length + "_rolling".Length), + "Windows has no limit, so the name must be left as earlier versions computed it"); + } + } + + private static string MutexNameForPath(string path, string suffix) + => (string)typeof(FileAppender) + .GetMethod("MutexNameForPath", BindingFlags.NonPublic | BindingFlags.Static, + null, [typeof(string), typeof(string)], null)! + .Invoke(null, [path, suffix])!; + + private static string MutexNameForPath(string path, string suffix, int? maxLength) + => (string)typeof(FileAppender) + .GetMethod("MutexNameForPath", BindingFlags.NonPublic | BindingFlags.Static, + null, [typeof(string), typeof(string), typeof(int?)], null)! + .Invoke(null, [path, suffix, maxLength])!; +} diff --git a/src/log4net/Appender/FileAppender.cs b/src/log4net/Appender/FileAppender.cs index 28f74a170..70228545c 100644 --- a/src/log4net/Appender/FileAppender.cs +++ b/src/log4net/Appender/FileAppender.cs @@ -22,6 +22,7 @@ using System.Diagnostics.CodeAnalysis; using System.IO; using System.Runtime.Serialization; +using System.Security.Cryptography; using System.Text; using System.Threading; using log4net.Util; @@ -759,12 +760,9 @@ public override void ActivateOptions() { if (CurrentAppender.File is not null) { - string mutexFriendlyFilename = CurrentAppender.File - .Replace("\\", "_") - .Replace(":", "_") - .Replace("/", "_"); - - _mutex = new Mutex(false, mutexFriendlyFilename); + // No ACL, Global\ prefix or user name here: without a shared ACL a global mutex + // throws for whichever process starts second, and a user name splits one session. + _mutex = new Mutex(false, MutexNameForPath(CurrentAppender.File, string.Empty)); } else { @@ -1025,16 +1023,20 @@ public override void ActivateOptions() SecurityContext ??= SecurityContextProvider.DefaultProvider.CreateSecurityContext(this); - LockingModel.CurrentAppender = this; - LockingModel.ActivateOptions(); - if (_fileName is not null) { using (SecurityContext.Impersonate(this)) { + // Before the locking model activates, which names its mutex after this path. _fileName = ConvertToFullPath(_fileName.Trim()); } + } + + LockingModel.CurrentAppender = this; + LockingModel.ActivateOptions(); + if (_fileName is not null) + { SafeOpenFile(_fileName, AppendToFile); } else @@ -1366,6 +1368,40 @@ protected virtual void SetQWForFiles(TextWriter writer) /// protected static string ConvertToFullPath(string path) => SystemInfo.ConvertToFullPath(path); + /// + /// Names the mutex that serialises between processes, with + /// telling one mutex over the same file from another. + /// + /// + /// The flattened path, as earlier versions computed it. Only a name the platform rejects is + /// hashed: Unix stops at , Windows has no limit. Unprefixed, so + /// on Windows it coordinates one session. + /// + internal static string MutexNameForPath(string path, string suffix) + => MutexNameForPath(path, suffix, SystemInfo.IsWindows ? null : MaxMutexNameLength); + + /// Takes the limit rather than deciding it, so both branches are testable anywhere. + private static string MutexNameForPath(string path, string suffix, int? maxLength) + { + string name = path.EnsureNotNull() + .Replace("\\", "_") + .Replace(":", "_") + .Replace("/", "_") + suffix; + + if (maxLength is null || name.Length <= maxLength) + { + return name; + } + + // TODO use SHA256.HashData and Convert.ToHexString on .net10 + using SHA256 sha256 = SHA256.Create(); + byte[] hash = sha256.ComputeHash(Encoding.UTF8.GetBytes(path)); + return "log4net_" + BitConverter.ToString(hash).Replace("-", "") + suffix; + } + + /// The longest mutex name Unix accepts. Windows has no limit. Both measured. + private const int MaxMutexNameLength = 255; + /// /// The name of the log file. /// diff --git a/src/log4net/Appender/RollingFileAppender.cs b/src/log4net/Appender/RollingFileAppender.cs index 1339bb619..0b31c6163 100644 --- a/src/log4net/Appender/RollingFileAppender.cs +++ b/src/log4net/Appender/RollingFileAppender.cs @@ -1059,11 +1059,7 @@ public override void ActivateOptions() } // initialize the mutex that is used to lock rolling - _mutexForRolling = new Mutex(false, _baseFileName - .Replace("\\", "_") - .Replace(":", "_") - .Replace("/", "_") + "_rolling" - ); + _mutexForRolling = new Mutex(false, MutexNameForPath(_baseFileName, "_rolling")); if (_rollDate && File is not null && _scheduledFilename is null) { diff --git a/src/log4net/Util/SystemInfo.cs b/src/log4net/Util/SystemInfo.cs index f71876d7b..5da9adb77 100644 --- a/src/log4net/Util/SystemInfo.cs +++ b/src/log4net/Util/SystemInfo.cs @@ -47,6 +47,12 @@ public static class SystemInfo /// Is the mono runtime used /// internal static bool IsMono { get; } = Type.GetType("Mono.Runtime") is not null; + + /// + /// Is the runtime on Windows + /// + /// Not RuntimeInformation.IsOSPlatform, which throws below net471. + internal static bool IsWindows { get; } = Environment.OSVersion.Platform == PlatformID.Win32NT; /// /// Initialize default values for private static fields. From 2f3d444e2ff87dbc255db8688086161e9c880f12 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Mon, 14 Sep 2026 22:10:46 +0200 Subject: [PATCH 03/14] drop the pre-Vista event log size branch Windows 7 SP1 is the floor for the net462 build this file compiles into, so the version test could not fail and the 32766 constant behind it was dead. The surviving constant keeps its measured value and loses the superseded lore. --- src/log4net/Appender/EventLogAppender.cs | 67 ++---------------------- 1 file changed, 5 insertions(+), 62 deletions(-) diff --git a/src/log4net/Appender/EventLogAppender.cs b/src/log4net/Appender/EventLogAppender.cs index fa0a23d5c..524dcf9c6 100644 --- a/src/log4net/Appender/EventLogAppender.cs +++ b/src/log4net/Appender/EventLogAppender.cs @@ -433,7 +433,7 @@ private static string PrepareEventText(string rendered, int maxSize) private int GetMaxMessageSize() { string machineName = MachineName == "." ? Environment.MachineName : MachineName; - int budget = _maxEventlogMessageSize + int budget = MaxEventlogMessageSize - LogName.Length - ApplicationName.Length - machineName.Length @@ -519,47 +519,14 @@ public class Level2EventLogEntryType : LevelMappingEntry private static readonly Type _declaringType = typeof(EventLogAppender); /// - /// The maximum size supported by default. + /// The maximum size the operating system supports for an event log message. /// /// - /// http://msdn.microsoft.com/en-us/library/xzwc042w(v=vs.100).aspx - /// The 32766 documented max size is two bytes shy of 32K (I'm assuming 32766 - /// may leave space for a two byte null terminator of #0#0). The 32766 max - /// length is what the .NET 4.0 source code checks for, but this is WRONG! - /// Strings with a length > 31839 on Windows Vista or higher can CORRUPT - /// the event log! See: System.Diagnostics.EventLogInternal.InternalWriteEvent() - /// for the use of the 32766 max size. - /// - private const int MaxEventlogMessageSizeDefault = 32766; - - /// - /// The maximum size supported by a windows operating system that is vista - /// or newer. - /// - /// - /// See ReportEvent API: - /// http://msdn.microsoft.com/en-us/library/aa363679(VS.85).aspx - /// ReportEvent's lpStrings parameter: - /// "A pointer to a buffer containing an array of - /// null-terminated strings that are merged into the message before Event Viewer - /// displays the string to the user. This parameter must be a valid pointer - /// (or NULL), even if wNumStrings is zero. Each string is limited to 31,839 characters." - /// - /// Going beyond the size of 31839 will (at some point) corrupt the event log on Windows - /// Vista or higher! It may succeed for a while...but you will eventually run into the - /// error: "System.ComponentModel.Win32Exception : A device attached to the system is - /// not functioning", and the event log will then be corrupt (I was able to corrupt - /// an event log using a length of 31877 on Windows 7). - /// - /// The max size for Windows Vista or higher is documented here: - /// http://msdn.microsoft.com/en-us/library/xzwc042w(v=vs.100).aspx. - /// Going over this size may succeed a few times but the buffer will overrun and - /// eventually corrupt the log (based on testing). - /// /// 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. + /// source stays within this, and one character more stores nothing. The 32766 that .NET itself + /// checks for is wrong and corrupts the log. /// - private const int MaxEventlogMessageSizeVistaOrNewer = 31736; + private const int MaxEventlogMessageSize = 31736; /// /// Held back from the computed limit. Crossing it discards the record silently, consumes the @@ -567,29 +534,5 @@ public class Level2EventLogEntryType : LevelMappingEntry /// private const int MaxEventlogMessageSizeMargin = 1024; - /// - /// The maximum size that the operating system supports for - /// a event log message. - /// - /// - /// Used to determine the maximum string length that can be written - /// to the operating system event log and eventually truncate a string - /// that exceeds the limits. - /// - private static readonly int _maxEventlogMessageSize = GetMaxEventLogMessageSize(); - - /// - /// This method determines the maximum event log message size allowed for - /// the current environment. - /// - /// - private static int GetMaxEventLogMessageSize() - { - if (Environment.OSVersion.Platform == PlatformID.Win32NT && Environment.OSVersion.Version.Major >= 6) - { - return MaxEventlogMessageSizeVistaOrNewer; - } - return MaxEventlogMessageSizeDefault; - } } #endif // NET462_OR_GREATER \ No newline at end of file From a9525256b0c52a22b7b7656e763cd7995db61a78 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Thu, 17 Sep 2026 22:19:22 +0200 Subject: [PATCH 04/14] answer the review on the file locking work #319 - Release the file lock with _stream?.ReleaseLock() wherever the acquire was already null-conditional. - One CountingWriter property instead of five QuietWriter casts, through EnsureIs<> so a wrong writer names itself. The two sites after a reopen keep their null check: a refused lock leaves no writer there. - The new fixtures keep no state between tests: AutoTempFolder from PeanutButter.Utils and a per-test error handler. Its namespace collides with our test helper Utils, which is internal TestUtils now. --- src/Directory.Build.props | 1 + .../Appender/FileAppenderMutexNameTest.cs | 26 ++----- .../RollingFileAppenderRollFailureTest.cs | 67 ++++++++----------- .../Context/LogicalThreadContextTest.cs | 50 +++++++------- .../Context/ThreadContextTest.cs | 28 ++++---- src/log4net.Tests/Layout/PatternLayoutTest.cs | 14 ++-- src/log4net.Tests/{Utils.cs => TestUtils.cs} | 2 +- src/log4net.Tests/log4net.Tests.csproj | 1 + src/log4net/Appender/FileAppender.cs | 8 +-- src/log4net/Appender/RollingFileAppender.cs | 15 +++-- 10 files changed, 99 insertions(+), 113 deletions(-) rename src/log4net.Tests/{Utils.cs => TestUtils.cs} (97%) diff --git a/src/Directory.Build.props b/src/Directory.Build.props index 5b60be696..a14971b18 100644 --- a/src/Directory.Build.props +++ b/src/Directory.Build.props @@ -34,6 +34,7 @@ 4.3.0 4.2.2 4.6.0 + 2.0.63 1.0.25 diff --git a/src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs b/src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs index 6eb3baa05..83b77c48e 100644 --- a/src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs +++ b/src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs @@ -30,6 +30,8 @@ using NUnit.Framework; +using PeanutButter.Utils; + namespace log4net.Tests.Appender; /// The mutex name the file lock and the rolling lock derive from the log file path. @@ -58,24 +60,6 @@ public override void OnClose() { } } - private string _directory = string.Empty; - - [SetUp] - public void SetUp() - { - _directory = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString("N")); - Directory.CreateDirectory(_directory); - } - - [TearDown] - public void TearDown() - { - if (Directory.Exists(_directory)) - { - Directory.Delete(_directory, true); - } - } - /// /// The model was activated before the path was resolved, so a relative and an absolute spelling /// of one file never shared a mutex. @@ -118,10 +102,12 @@ public void TheLockingModelIsActivatedAfterThePathIsResolved() [NonParallelizable] public void ADeepPathStillActivates() { + using AutoTempFolder folder = new(); + // Over the 255 character mutex name limit once "_rolling" is added, under the 260 Windows // still enforces on net462. - string leaf = new('d', 250 - _directory.Length - "roll.log".Length - 2); - string directory = Path.Combine(_directory, leaf); + string leaf = new('d', 250 - folder.Path.Length - "roll.log".Length - 2); + string directory = Path.Combine(folder.Path, leaf); Directory.CreateDirectory(directory); string file = Path.Combine(directory, "roll.log"); Assert.That(file, Has.Length.EqualTo(250), "the fixture must exceed the mutex name limit"); diff --git a/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs b/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs index 13d926106..c896b3c0f 100644 --- a/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs +++ b/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs @@ -27,6 +27,8 @@ using NUnit.Framework; +using PeanutButter.Utils; + namespace log4net.Tests.Appender; /// @@ -39,26 +41,6 @@ public sealed class RollingFileAppenderRollFailureTest { private const string Marker = "must survive the failed roll"; - private string _directory = string.Empty; - private readonly Internal.RecordingErrorHandler _errors = new(); - - [SetUp] - public void SetUp() - { - _directory = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString("N")); - Directory.CreateDirectory(_directory); - _errors.Messages.Clear(); - } - - [TearDown] - public void TearDown() - { - if (Directory.Exists(_directory)) - { - Directory.Delete(_directory, true); - } - } - /// /// A failed rename leaves the file in place, and reopening it without appending destroyed it. /// The archive it shifted on the way must not be shifted a second time. @@ -67,7 +49,9 @@ public void TearDown() [NonParallelizable] public void AFailedRollKeepsTheEventsItCouldNotMove() { - string file = Path.Combine(_directory, "roll-failure.log"); + using AutoTempFolder folder = new(); + Internal.RecordingErrorHandler errors = new(); + string file = Path.Combine(folder.Path, "roll-failure.log"); RollingFileAppender appender = new() { File = file, @@ -77,7 +61,7 @@ public void AFailedRollKeepsTheEventsItCouldNotMove() MaximumFileSize = "200", AppendToFile = true, LockingModel = new FileAppender.MinimalLock(), - ErrorHandler = _errors + ErrorHandler = errors }; appender.ActivateOptions(); @@ -93,7 +77,7 @@ public void AFailedRollKeepsTheEventsItCouldNotMove() // The file is already over the limit, so this event rolls first and the roll is the one that // fails. What it writes afterwards is the content the failed roll used to destroy. LogLog.ExecuteWithoutEmittingInternalMessages(() => appender.DoAppend(CreateEvent(Marker))); - Assert.That(_errors.Messages, Is.Not.Empty, "the roll never failed, so nothing was exercised"); + Assert.That(errors.Messages, Is.Not.Empty, "the roll never failed, so nothing was exercised"); // That first attempt shifts the archive before failing on the base file, which is // unavoidable. What must not happen is a second shift. @@ -117,7 +101,7 @@ public void AFailedRollKeepsTheEventsItCouldNotMove() "the backup contents were rewritten while the rename kept failing"); // Only the base rename is retried, and only once the file has grown another MaxFileSize, // so the attempts are far fewer than the 20 events above. - Assert.That(BaseRenameAttempts(file), Is.LessThan(20), + Assert.That(BaseRenameAttempts(errors, file), Is.LessThan(20), "the rename was retried per event instead of per MaxFileSize of growth"); } finally @@ -138,7 +122,9 @@ public void AFailedRollKeepsTheEventsItCouldNotMove() [NonParallelizable] public void AFailedRollKeepsTheEventsWhenTheFileNameIsDated() { - string file = Path.Combine(_directory, "roll-failure.log"); + using AutoTempFolder folder = new(); + Internal.RecordingErrorHandler errors = new(); + string file = Path.Combine(folder.Path, "roll-failure.log"); RollingFileAppender appender = new() { File = file, @@ -150,7 +136,7 @@ public void AFailedRollKeepsTheEventsWhenTheFileNameIsDated() MaximumFileSize = "200", AppendToFile = true, LockingModel = new FileAppender.MinimalLock(), - ErrorHandler = _errors + ErrorHandler = errors }; appender.ActivateOptions(); @@ -167,7 +153,7 @@ public void AFailedRollKeepsTheEventsWhenTheFileNameIsDated() // Rolls first, fails on the dated name, and keeps what the rename could not move. LogLog.ExecuteWithoutEmittingInternalMessages( () => appender.DoAppend(CreateEvent(new string('b', 200)))); - Assert.That(_errors.Messages, Is.Not.Empty, "the roll never failed, so nothing was exercised"); + Assert.That(errors.Messages, Is.Not.Empty, "the roll never failed, so nothing was exercised"); // Written into the file the failed rename left behind, so a truncating reopen destroys it. appender.DoAppend(CreateEvent(Marker)); @@ -198,7 +184,9 @@ public void AFailedRollKeepsTheEventsWhenTheFileNameIsDated() [NonParallelizable] public void ASuccessfulRetryKeepsTheBackupItRecovered() { - string file = Path.Combine(_directory, "roll-failure.log"); + using AutoTempFolder folder = new(); + Internal.RecordingErrorHandler errors = new(); + string file = Path.Combine(folder.Path, "roll-failure.log"); RollingFileAppender appender = new() { File = file, @@ -209,7 +197,7 @@ public void ASuccessfulRetryKeepsTheBackupItRecovered() MaximumFileSize = "200", AppendToFile = true, LockingModel = new FileAppender.MinimalLock(), - ErrorHandler = _errors + ErrorHandler = errors }; appender.ActivateOptions(); @@ -221,7 +209,7 @@ public void ASuccessfulRetryKeepsTheBackupItRecovered() // Rolls first, fails, and is then written into the file the rename could not move. LogLog.ExecuteWithoutEmittingInternalMessages(() => appender.DoAppend(CreateEvent(Marker))); - Assert.That(_errors.Messages, Is.Not.Empty, "the roll never failed, so nothing was exercised"); + Assert.That(errors.Messages, Is.Not.Empty, "the roll never failed, so nothing was exercised"); // The obstruction is gone, so the next retry succeeds. UnblockRename(file + ".1"); @@ -262,7 +250,9 @@ public void ASuccessfulRetryKeepsTheBackupItRecovered() [NonParallelizable] public void ATimeRollAfterAFailedRenameTakesEveryBackupWithIt() { - string file = Path.Combine(_directory, "roll-failure.log"); + using AutoTempFolder folder = new(); + Internal.RecordingErrorHandler errors = new(); + string file = Path.Combine(folder.Path, "roll-failure.log"); MockDateTime clock = new(new DateTime(2026, 1, 1, 12, 0, 0, DateTimeKind.Local)); RollingFileAppender appender = new() { @@ -276,7 +266,7 @@ public void ATimeRollAfterAFailedRenameTakesEveryBackupWithIt() AppendToFile = true, LockingModel = new FileAppender.MinimalLock(), DateTimeStrategy = clock, - ErrorHandler = _errors + ErrorHandler = errors }; appender.ActivateOptions(); @@ -291,7 +281,7 @@ public void ATimeRollAfterAFailedRenameTakesEveryBackupWithIt() LogLog.ExecuteWithoutEmittingInternalMessages( () => appender.DoAppend(CreateEvent(new string('b', 200)))); - Assert.That(_errors.Messages, Is.Not.Empty, "the base rename never failed, so nothing was exercised"); + Assert.That(errors.Messages, Is.Not.Empty, "the base rename never failed, so nothing was exercised"); Assert.That(File.ReadAllText(file + ".3"), Does.Contain(Marker), "the fixture needs the archive shifted a slot beyond the backup count"); @@ -328,19 +318,20 @@ private static void BlockRename(string target) private static void UnblockRename(string target) => Directory.Delete(target, true); /// The numbered backups, excluding the log file itself: a `.*` pattern matches it too. - private string[] Backups(string file) - => Array.FindAll(Directory.GetFiles(_directory, "roll-failure.log.*"), + private static string[] Backups(string file) + => Array.FindAll( + Directory.GetFiles(Path.GetDirectoryName(file)!, Path.GetFileName(file) + ".*"), f => !string.Equals(f, file, StringComparison.Ordinal)); /// /// How often the base rename itself was attempted. A failed attempt can report twice, once for /// the delete of the target and once for the move, so counting messages counts the wrong thing. /// - private int BaseRenameAttempts(string file) - => _errors.Messages.FindAll(m => m.IndexOf($"[{file}] ->", StringComparison.Ordinal) >= 0).Count; + private static int BaseRenameAttempts(Internal.RecordingErrorHandler errors, string file) + => errors.Messages.FindAll(m => m.IndexOf($"[{file}] ->", StringComparison.Ordinal) >= 0).Count; /// Whether any numbered backup holds . - private bool ArchiveHolds(string file, string content) + private static bool ArchiveHolds(string file, string content) => Array.Exists(Backups(file), f => File.ReadAllText(f).IndexOf(content, StringComparison.Ordinal) >= 0); diff --git a/src/log4net.Tests/Context/LogicalThreadContextTest.cs b/src/log4net.Tests/Context/LogicalThreadContextTest.cs index 17a4941ab..5bed274f8 100644 --- a/src/log4net.Tests/Context/LogicalThreadContextTest.cs +++ b/src/log4net.Tests/Context/LogicalThreadContextTest.cs @@ -41,14 +41,14 @@ namespace log4net.Tests.Context; public class LogicalThreadContextTest { [TearDown] - public void TearDown() => Utils.RemovePropertyFromAllContexts(); + public void TearDown() => TestUtils.RemovePropertyFromAllContexts(); [Test] public void TestLogicalThreadPropertiesPatternBasicGetSet() { StringAppender stringAppender = new() { - Layout = new PatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = new PatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -60,13 +60,13 @@ public void TestLogicalThreadPropertiesPatternBasicGetSet() Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test no logical thread properties value set"); stringAppender.Reset(); - LogicalThreadContext.Properties[Utils.PropertyKey] = "val1"; + LogicalThreadContext.Properties[TestUtils.PropertyKey] = "val1"; log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo("val1"), "Test logical thread properties value set"); stringAppender.Reset(); - LogicalThreadContext.Properties.Remove(Utils.PropertyKey); + LogicalThreadContext.Properties.Remove(TestUtils.PropertyKey); log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test logical thread properties value removed"); @@ -78,7 +78,7 @@ public async Task TestLogicalThreadPropertiesPatternAsyncAwait() { StringAppender stringAppender = new() { - Layout = new PatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = new PatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -91,7 +91,7 @@ public async Task TestLogicalThreadPropertiesPatternAsyncAwait() stringAppender.Reset(); string testValueForCurrentContext = "Outer"; - LogicalThreadContext.Properties[Utils.PropertyKey] = testValueForCurrentContext; + LogicalThreadContext.Properties[TestUtils.PropertyKey] = testValueForCurrentContext; log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo(testValueForCurrentContext), "Test logical thread properties value set"); @@ -109,7 +109,7 @@ public async Task TestLogicalThreadPropertiesPatternAsyncAwait() Assert.That(stringAppender.GetString(), Is.EqualTo(testValueForCurrentContext), "Test logical thread properties value set"); stringAppender.Reset(); - LogicalThreadContext.Properties.Remove(Utils.PropertyKey); + LogicalThreadContext.Properties.Remove(TestUtils.PropertyKey); log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test logical thread properties value removed"); @@ -121,7 +121,7 @@ public void TestLogicalThreadStackPattern() { StringAppender stringAppender = new() { - Layout = new PatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = new PatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -133,7 +133,7 @@ public void TestLogicalThreadStackPattern() Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test no logical thread stack value set"); stringAppender.Reset(); - using (LogicalThreadContext.Stacks[Utils.PropertyKey].Push("val1")) + using (LogicalThreadContext.Stacks[TestUtils.PropertyKey].Push("val1")) { log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo("val1"), "Test logical thread stack value set"); @@ -150,7 +150,7 @@ public void TestLogicalThreadStackPattern2() { StringAppender stringAppender = new() { - Layout = new PatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = new PatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -162,13 +162,13 @@ public void TestLogicalThreadStackPattern2() Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test no logical thread stack value set"); stringAppender.Reset(); - using (LogicalThreadContext.Stacks[Utils.PropertyKey].Push("val1")) + using (LogicalThreadContext.Stacks[TestUtils.PropertyKey].Push("val1")) { log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo("val1"), "Test logical thread stack value set"); stringAppender.Reset(); - using (LogicalThreadContext.Stacks[Utils.PropertyKey].Push("val2")) + using (LogicalThreadContext.Stacks[TestUtils.PropertyKey].Push("val2")) { log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo("val1 val2"), "Test logical thread stack value pushed 2nd val"); @@ -186,7 +186,7 @@ public void TestLogicalThreadStackPatternNullVal() { StringAppender stringAppender = new() { - Layout = new PatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = new PatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -198,7 +198,7 @@ public void TestLogicalThreadStackPatternNullVal() Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test no logical thread stack value set"); stringAppender.Reset(); - using (LogicalThreadContext.Stacks[Utils.PropertyKey].Push(null)) + using (LogicalThreadContext.Stacks[TestUtils.PropertyKey].Push(null)) { log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test logical thread stack value set"); @@ -215,7 +215,7 @@ public void TestLogicalThreadStackPatternNullVal2() { StringAppender stringAppender = new() { - Layout = new PatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = new PatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -227,13 +227,13 @@ public void TestLogicalThreadStackPatternNullVal2() Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test no logical thread stack value set"); stringAppender.Reset(); - using (LogicalThreadContext.Stacks[Utils.PropertyKey].Push("val1")) + using (LogicalThreadContext.Stacks[TestUtils.PropertyKey].Push("val1")) { log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo("val1"), "Test logical thread stack value set"); stringAppender.Reset(); - using (LogicalThreadContext.Stacks[Utils.PropertyKey].Push(null)) + using (LogicalThreadContext.Stacks[TestUtils.PropertyKey].Push(null)) { log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo("val1 "), "Test logical thread stack value pushed null"); @@ -251,7 +251,7 @@ public async Task TestLogicalThreadStackPatternAsyncAwait() { StringAppender stringAppender = new() { - Layout = new PatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = new PatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -265,7 +265,7 @@ public async Task TestLogicalThreadStackPatternAsyncAwait() string testValueForCurrentContext = "Outer"; string[]? strings; - using (LogicalThreadContext.Stacks[Utils.PropertyKey].Push(testValueForCurrentContext)) + using (LogicalThreadContext.Stacks[TestUtils.PropertyKey].Push(testValueForCurrentContext)) { log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo(testValueForCurrentContext), "Test logical thread stack value set"); @@ -289,7 +289,7 @@ static async Task SomeWorkProperties(string propertyName) { StringAppender stringAppender = new() { - Layout = new PatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = new PatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -299,7 +299,7 @@ static async Task SomeWorkProperties(string propertyName) log.Info("TestMessage"); // set a new one - LogicalThreadContext.Properties[Utils.PropertyKey] = propertyName; + LogicalThreadContext.Properties[TestUtils.PropertyKey] = propertyName; log.Info("TestMessage"); await MoreWorkProperties(log, "A").ConfigureAwait(false); @@ -311,7 +311,7 @@ static async Task SomeWorkProperties(string propertyName) static async Task MoreWorkProperties(ILog log, string propertyName) { - LogicalThreadContext.Properties[Utils.PropertyKey] = propertyName; + LogicalThreadContext.Properties[TestUtils.PropertyKey] = propertyName; log.Info("TestMessage"); await Task.Delay(1).ConfigureAwait(false); log.Info("TestMessage"); @@ -321,7 +321,7 @@ private static async Task SomeWorkStack(string stackName) { StringAppender stringAppender = new() { - Layout = new PatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = new PatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -329,7 +329,7 @@ private static async Task SomeWorkStack(string stackName) ILog log = LogManager.GetLogger(rep.Name, "TestLogicalThreadStackPattern"); - using (LogicalThreadContext.Stacks[Utils.PropertyKey].Push(stackName)) + using (LogicalThreadContext.Stacks[TestUtils.PropertyKey].Push(stackName)) { log.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo($"Outer {stackName}"), "Test logical thread stack value set"); @@ -346,7 +346,7 @@ private static async Task SomeWorkStack(string stackName) static async Task MoreWorkStack(ILog log, string stackName) { - using (LogicalThreadContext.Stacks[Utils.PropertyKey].Push(stackName)) + using (LogicalThreadContext.Stacks[TestUtils.PropertyKey].Push(stackName)) { log.Info("TestMessage"); await Task.Delay(1).ConfigureAwait(false); diff --git a/src/log4net.Tests/Context/ThreadContextTest.cs b/src/log4net.Tests/Context/ThreadContextTest.cs index c89b68b0a..31e4de592 100644 --- a/src/log4net.Tests/Context/ThreadContextTest.cs +++ b/src/log4net.Tests/Context/ThreadContextTest.cs @@ -42,7 +42,7 @@ public class ThreadContextTest [TearDown] public void TearDown() { - Utils.RemovePropertyFromAllContexts(); + TestUtils.RemovePropertyFromAllContexts(); } [Test] @@ -50,7 +50,7 @@ public void TestThreadPropertiesPattern() { StringAppender stringAppender = new() { - Layout = new PatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = new PatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -62,13 +62,13 @@ public void TestThreadPropertiesPattern() Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test no thread properties value set"); stringAppender.Reset(); - ThreadContext.Properties[Utils.PropertyKey] = "val1"; + ThreadContext.Properties[TestUtils.PropertyKey] = "val1"; log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo("val1"), "Test thread properties value set"); stringAppender.Reset(); - ThreadContext.Properties.Remove(Utils.PropertyKey); + ThreadContext.Properties.Remove(TestUtils.PropertyKey); log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test thread properties value removed"); @@ -80,7 +80,7 @@ public void TestThreadStackPattern() { StringAppender stringAppender = new() { - Layout = new PatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = new PatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -92,7 +92,7 @@ public void TestThreadStackPattern() Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test no thread stack value set"); stringAppender.Reset(); - using (ThreadContext.Stacks[Utils.PropertyKey].Push("val1")) + using (ThreadContext.Stacks[TestUtils.PropertyKey].Push("val1")) { log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo("val1"), "Test thread stack value set"); @@ -109,7 +109,7 @@ public void TestThreadStackPattern2() { StringAppender stringAppender = new() { - Layout = new PatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = new PatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -121,13 +121,13 @@ public void TestThreadStackPattern2() Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test no thread stack value set"); stringAppender.Reset(); - using (ThreadContext.Stacks[Utils.PropertyKey].Push("val1")) + using (ThreadContext.Stacks[TestUtils.PropertyKey].Push("val1")) { log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo("val1"), "Test thread stack value set"); stringAppender.Reset(); - using (ThreadContext.Stacks[Utils.PropertyKey].Push("val2")) + using (ThreadContext.Stacks[TestUtils.PropertyKey].Push("val2")) { log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo("val1 val2"), "Test thread stack value pushed 2nd val"); @@ -145,7 +145,7 @@ public void TestThreadStackPatternNullVal() { StringAppender stringAppender = new() { - Layout = new PatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = new PatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -157,7 +157,7 @@ public void TestThreadStackPatternNullVal() Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test no thread stack value set"); stringAppender.Reset(); - using (ThreadContext.Stacks[Utils.PropertyKey].Push(null)) + using (ThreadContext.Stacks[TestUtils.PropertyKey].Push(null)) { log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test thread stack value set"); @@ -174,7 +174,7 @@ public void TestThreadStackPatternNullVal2() { StringAppender stringAppender = new() { - Layout = new PatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = new PatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -186,13 +186,13 @@ public void TestThreadStackPatternNullVal2() Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test no thread stack value set"); stringAppender.Reset(); - using (ThreadContext.Stacks[Utils.PropertyKey].Push("val1")) + using (ThreadContext.Stacks[TestUtils.PropertyKey].Push("val1")) { log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo("val1"), "Test thread stack value set"); stringAppender.Reset(); - using (ThreadContext.Stacks[Utils.PropertyKey].Push(null)) + using (ThreadContext.Stacks[TestUtils.PropertyKey].Push(null)) { log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo("val1 "), "Test thread stack value pushed null"); diff --git a/src/log4net.Tests/Layout/PatternLayoutTest.cs b/src/log4net.Tests/Layout/PatternLayoutTest.cs index da7cc6e5e..b32efe4c4 100644 --- a/src/log4net.Tests/Layout/PatternLayoutTest.cs +++ b/src/log4net.Tests/Layout/PatternLayoutTest.cs @@ -64,7 +64,7 @@ public void SetUp() [TearDown] public void TearDown() { - Utils.RemovePropertyFromAllContexts(); + TestUtils.RemovePropertyFromAllContexts(); // restore previous culture Thread.CurrentThread.CurrentCulture = _currentCulture!; Thread.CurrentThread.CurrentUICulture = _currentUiCulture!; @@ -92,7 +92,7 @@ public void TestThreadPropertiesPattern() { StringAppender stringAppender = new() { - Layout = NewPatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = NewPatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -104,13 +104,13 @@ public void TestThreadPropertiesPattern() Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test no thread properties value set"); stringAppender.Reset(); - ThreadContext.Properties[Utils.PropertyKey] = "val1"; + ThreadContext.Properties[TestUtils.PropertyKey] = "val1"; log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo("val1"), "Test thread properties value set"); stringAppender.Reset(); - ThreadContext.Properties.Remove(Utils.PropertyKey); + ThreadContext.Properties.Remove(TestUtils.PropertyKey); log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test thread properties value removed"); @@ -147,7 +147,7 @@ public void TestGlobalPropertiesPattern() { StringAppender stringAppender = new() { - Layout = NewPatternLayout("%property{" + Utils.PropertyKey + "}") + Layout = NewPatternLayout("%property{" + TestUtils.PropertyKey + "}") }; ILoggerRepository rep = LogManager.CreateRepository(Guid.NewGuid().ToString()); @@ -159,13 +159,13 @@ public void TestGlobalPropertiesPattern() Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test no global properties value set"); stringAppender.Reset(); - GlobalContext.Properties[Utils.PropertyKey] = "val1"; + GlobalContext.Properties[TestUtils.PropertyKey] = "val1"; log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo("val1"), "Test global properties value set"); stringAppender.Reset(); - GlobalContext.Properties.Remove(Utils.PropertyKey); + GlobalContext.Properties.Remove(TestUtils.PropertyKey); log1.Info("TestMessage"); Assert.That(stringAppender.GetString(), Is.EqualTo(SystemInfo.NullText), "Test global properties value removed"); diff --git a/src/log4net.Tests/Utils.cs b/src/log4net.Tests/TestUtils.cs similarity index 97% rename from src/log4net.Tests/Utils.cs rename to src/log4net.Tests/TestUtils.cs index 477036973..4e4d04bdd 100644 --- a/src/log4net.Tests/Utils.cs +++ b/src/log4net.Tests/TestUtils.cs @@ -22,7 +22,7 @@ namespace log4net.Tests; /// /// Utilities for testing /// -public static class Utils +internal static class TestUtils { /// /// Sample property key diff --git a/src/log4net.Tests/log4net.Tests.csproj b/src/log4net.Tests/log4net.Tests.csproj index 851af72ee..e503207ad 100644 --- a/src/log4net.Tests/log4net.Tests.csproj +++ b/src/log4net.Tests/log4net.Tests.csproj @@ -33,6 +33,7 @@ + diff --git a/src/log4net/Appender/FileAppender.cs b/src/log4net/Appender/FileAppender.cs index 70228545c..aa3c242f7 100644 --- a/src/log4net/Appender/FileAppender.cs +++ b/src/log4net/Appender/FileAppender.cs @@ -1110,7 +1110,7 @@ protected override void Append(LoggingEvent loggingEvent) } finally { - _stream.ReleaseLock(); + _stream?.ReleaseLock(); } } } @@ -1136,7 +1136,7 @@ protected override void Append(LoggingEvent[] loggingEvents) } finally { - _stream.ReleaseLock(); + _stream?.ReleaseLock(); } } } @@ -1173,7 +1173,7 @@ protected override void WriteHeader() } finally { - _stream.ReleaseLock(); + _stream?.ReleaseLock(); } } } @@ -1243,7 +1243,7 @@ private void RunWithBestEffortLock(Action action) { if (locked) { - _stream!.ReleaseLock(); + _stream?.ReleaseLock(); } } } diff --git a/src/log4net/Appender/RollingFileAppender.cs b/src/log4net/Appender/RollingFileAppender.cs index 0b31c6163..7c65d9064 100644 --- a/src/log4net/Appender/RollingFileAppender.cs +++ b/src/log4net/Appender/RollingFileAppender.cs @@ -481,6 +481,14 @@ public RollingMode RollingStyle protected override void SetQWForFiles(TextWriter writer) => QuietWriter = new CountingQuietTextWriter(writer, ErrorHandler); + /// The writer, which counts what it has written so a size roll can be timed. + /// + /// Only for the paths reached through , where + /// has already refused a null writer. A reopen + /// that could not take the lock leaves none, so the sites that run after one keep their own check. + /// + private CountingQuietTextWriter CountingWriter => QuietWriter.EnsureIs(); + /// /// Write out a logging event. /// @@ -566,14 +574,13 @@ protected virtual void AdjustFileBeforeAppend() } } - if (_rollSize && (File is not null) - && ((CountingQuietTextWriter)QuietWriter!).Count >= MaxFileSize) + if (_rollSize && (File is not null) && CountingWriter.Count >= MaxFileSize) { if (_pendingRename is null) { RollOverSize(); } - else if (((CountingQuietTextWriter)QuietWriter).Count >= _pendingRename.RetryAtCount) + else if (CountingWriter.Count >= _pendingRename.RetryAtCount) { RetryFailedRoll(); } @@ -1322,7 +1329,7 @@ protected void RollOverSize() { CloseFile(); // keep windows happy. - LogLog.Debug(_declaringType, $"rolling over count [{((CountingQuietTextWriter)QuietWriter!).Count}]"); + LogLog.Debug(_declaringType, $"rolling over count [{CountingWriter.Count}]"); LogLog.Debug(_declaringType, $"maxSizeRollBackups [{MaxSizeRollBackups}]"); LogLog.Debug(_declaringType, $"curSizeRollBackups [{CurrentSizeRollBackups}]"); LogLog.Debug(_declaringType, $"countDirection [{CountDirection}]"); From 03af5dcd1026274dea28a0c9d27926db0867d656 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Thu, 17 Sep 2026 22:28:04 +0200 Subject: [PATCH 05/14] give the temp folder tests their own folder #319 - SmtpPickupDirAppenderTest kept its pickup directory in a fixture field, shared by every test, and created it inside the build output. - FileAppenderTest leaked two files per run: Path.GetTempFileName creates them and nothing deleted them. - PatternStringTest tracked its config file by hand to delete it in a finally. All three use AutoTempFolder now, which disposes what it made. --- .../Appender/FileAppenderTest.cs | 8 ++- .../Appender/SmtpPickupDirAppenderTest.cs | 72 +++++++------------ src/log4net.Tests/Util/PatternStringTest.cs | 18 ++--- 3 files changed, 35 insertions(+), 63 deletions(-) diff --git a/src/log4net.Tests/Appender/FileAppenderTest.cs b/src/log4net.Tests/Appender/FileAppenderTest.cs index ddd55f7ea..7f658c1be 100644 --- a/src/log4net.Tests/Appender/FileAppenderTest.cs +++ b/src/log4net.Tests/Appender/FileAppenderTest.cs @@ -23,6 +23,8 @@ using System; using log4net.Appender; using NUnit.Framework; + +using PeanutButter.Utils; using log4net.Repository; using log4net.Config; using log4net.Util; @@ -163,7 +165,8 @@ public void FilenameWithGlobalContextPatternStringTest() [Test] public void InterProcessLock_AcquireLock_ReleasesMutexWhenStreamIsNull() { - string tempFile = Path.GetTempFileName(); + using AutoTempFolder folder = new(); + string tempFile = Path.Combine(folder.Path, "lock-test.log"); FileAppender appender = new() { File = "log4net_ipl_test" }; FileAppender.InterProcessLock lockingModel = new() { CurrentAppender = appender }; lockingModel.ActivateOptions(); @@ -221,7 +224,8 @@ public void LockTimeoutMillisRejectsNegativeValuesExceptInfinite() public void AcquireLockGivesUpWhenTheLockIsHeldTooLong() { const string appenderFile = "log4net_lock_timeout_test"; - string tempFile = Path.GetTempFileName(); + using AutoTempFolder folder = new(); + string tempFile = Path.Combine(folder.Path, "lock-test.log"); FileAppender appender = new() { File = appenderFile }; FileAppender.InterProcessLock lockingModel = new() { diff --git a/src/log4net.Tests/Appender/SmtpPickupDirAppenderTest.cs b/src/log4net.Tests/Appender/SmtpPickupDirAppenderTest.cs index 5ba88f035..cefcee9f3 100644 --- a/src/log4net.Tests/Appender/SmtpPickupDirAppenderTest.cs +++ b/src/log4net.Tests/Appender/SmtpPickupDirAppenderTest.cs @@ -27,6 +27,8 @@ using NUnit.Framework; +using PeanutButter.Utils; + namespace log4net.Tests.Appender; /// @@ -35,7 +37,6 @@ namespace log4net.Tests.Appender; [TestFixture] public class SmtpPickupDirAppenderTest { - private readonly string _testPickupDir; private sealed class SilentErrorHandler : IErrorHandler { @@ -51,13 +52,6 @@ public void Error(string message, Exception? e, ErrorCode errorCode) => _buffer.Append(message + '\n' + e?.Message + '\n'); } - public SmtpPickupDirAppenderTest() - => _testPickupDir = Path.Combine(Directory.GetCurrentDirectory(), "SmtpPickupDirAppenderTest_PickupDir"); - - /// - /// Sets up variables used for the tests - /// - private void InitializePickupDir() => Directory.CreateDirectory(_testPickupDir); /// /// Shuts down any loggers in the hierarchy, along @@ -77,33 +71,13 @@ private static void ResetLogger() /// go here /// [SetUp] - public void SetUp() - { - ResetLogger(); - DeleteTestFiles(); - InitializePickupDir(); - } + public void SetUp() => ResetLogger(); /// /// Any steps that happen after each test go here /// [TearDown] - public void TearDown() - { - ResetLogger(); - DeleteTestFiles(); - } - - /// - /// Removes all test files that exist - /// - private void DeleteTestFiles() - { - if (Directory.Exists(_testPickupDir)) - { - Directory.Delete(_testPickupDir, true); - } - } + public void TearDown() => ResetLogger(); /// /// Creates a logger hierarchy, configures a SMTP pickup dir appender and returns an ILogger @@ -130,17 +104,15 @@ private static ILogger CreateLogger(SmtpPickupDirAppender appender) /// /// Create an appender to use for the logger /// + /// The directory the appender writes its mails to. /// The error handler to use. /// - private SmtpPickupDirAppender CreateSmtpPickupDirAppender(IErrorHandler handler) - { - SmtpPickupDirAppender appender = new() + private static SmtpPickupDirAppender CreateSmtpPickupDirAppender(string pickupDir, IErrorHandler handler) + => new() { - PickupDir = _testPickupDir, + PickupDir = pickupDir, ErrorHandler = handler }; - return appender; - } /// /// Destroys the logger hierarchy created by @@ -160,16 +132,17 @@ private static void DestroyLogger() [Test] public void ContentThatCannotBeEncodedDoesNotDestroyTheBatch() { + using AutoTempFolder pickupDir = new(); SilentErrorHandler sh = new(); - SmtpPickupDirAppender appender = CreateSmtpPickupDirAppender(sh); + SmtpPickupDirAppender appender = CreateSmtpPickupDirAppender(pickupDir.Path, 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(Directory.GetFiles(pickupDir.Path), Has.Length.EqualTo(1)); + string content = File.ReadAllText(Directory.GetFiles(pickupDir.Path)[0]); Assert.That(content, Does.Contain(@"poison\ud800event")); Assert.That(content, Does.Contain("the event after it")); @@ -182,16 +155,17 @@ public void ContentThatCannotBeEncodedDoesNotDestroyTheBatch() [Test] public void TestOutputContainsSentDate() { + using AutoTempFolder pickupDir = new(); SilentErrorHandler sh = new(); - SmtpPickupDirAppender appender = CreateSmtpPickupDirAppender(sh); + SmtpPickupDirAppender appender = CreateSmtpPickupDirAppender(pickupDir.Path, sh); ILogger log = CreateLogger(appender); DateTime beforeLog = DateTime.UtcNow; log.Log(GetType(), Level.Info, "This is a message", null); log.Log(GetType(), Level.Info, "This is a message 2", null); DestroyLogger(); - Assert.That(Directory.GetFiles(_testPickupDir), Has.Length.EqualTo(1)); - string[] fileContent = File.ReadAllLines((Directory.GetFiles(_testPickupDir)[0])); + Assert.That(Directory.GetFiles(pickupDir.Path), Has.Length.EqualTo(1)); + string[] fileContent = File.ReadAllLines((Directory.GetFiles(pickupDir.Path)[0])); bool hasDateHeader = false; const string dateHeaderStart = "Date: "; foreach (string line in fileContent) @@ -220,16 +194,17 @@ public void TestOutputContainsSentDate() public void TestConfigurableFileExtension() { const string fileExtension = "eml"; + using AutoTempFolder pickupDir = new(); SilentErrorHandler sh = new(); - SmtpPickupDirAppender appender = CreateSmtpPickupDirAppender(sh); + SmtpPickupDirAppender appender = CreateSmtpPickupDirAppender(pickupDir.Path, sh); appender.FileExtension = fileExtension; ILogger log = CreateLogger(appender); log.Log(GetType(), Level.Info, "This is a message", null); log.Log(GetType(), Level.Info, "This is a message 2", null); DestroyLogger(); - Assert.That(Directory.GetFiles(_testPickupDir), Has.Length.EqualTo(1)); - FileInfo fileInfo = new(Directory.GetFiles(_testPickupDir)[0]); + Assert.That(Directory.GetFiles(pickupDir.Path), Has.Length.EqualTo(1)); + FileInfo fileInfo = new(Directory.GetFiles(pickupDir.Path)[0]); Assert.That(fileInfo.Extension, Is.EqualTo("." + fileExtension)); Assert.That(Guid.TryParse(fileInfo.Name.Substring(0, fileInfo.Name.Length - fileInfo.Extension.Length), out _)); @@ -242,15 +217,16 @@ public void TestConfigurableFileExtension() [Test] public void TestDefaultFileNameIsAGuid() { + using AutoTempFolder pickupDir = new(); SilentErrorHandler sh = new(); - SmtpPickupDirAppender appender = CreateSmtpPickupDirAppender(sh); + SmtpPickupDirAppender appender = CreateSmtpPickupDirAppender(pickupDir.Path, sh); ILogger log = CreateLogger(appender); log.Log(GetType(), Level.Info, "This is a message", null); log.Log(GetType(), Level.Info, "This is a message 2", null); DestroyLogger(); - Assert.That(Directory.GetFiles(_testPickupDir), Has.Length.EqualTo(1)); - FileInfo fileInfo = new(Directory.GetFiles(_testPickupDir)[0]); + Assert.That(Directory.GetFiles(pickupDir.Path), Has.Length.EqualTo(1)); + FileInfo fileInfo = new(Directory.GetFiles(pickupDir.Path)[0]); Assert.That(fileInfo.Extension, Is.Empty); Assert.That(Guid.TryParse(fileInfo.Name, out _)); diff --git a/src/log4net.Tests/Util/PatternStringTest.cs b/src/log4net.Tests/Util/PatternStringTest.cs index 234b9893d..46acecf29 100644 --- a/src/log4net.Tests/Util/PatternStringTest.cs +++ b/src/log4net.Tests/Util/PatternStringTest.cs @@ -28,6 +28,8 @@ using System.Reflection; using System.Configuration; +using PeanutButter.Utils; + namespace log4net.Tests.Util; [TestFixture] @@ -64,11 +66,12 @@ public void TestAppSettingPathConverter() """; - string? configurationFileName = null; + using AutoTempFolder folder = new(); AppDomain? appDomain = null; try { - configurationFileName = CreateTempConfigFile(configurationFileContent); + string configurationFileName = Path.Combine(folder.Path, "app.config"); + File.WriteAllText(configurationFileName, configurationFileContent); appDomain = CreateConfiguredDomain("AppSettingsTestDomain", configurationFileName); PatternStringTest pst = (PatternStringTest)appDomain.CreateInstanceAndUnwrap(Assembly.GetExecutingAssembly().FullName, this.GetType().FullName); @@ -80,10 +83,6 @@ public void TestAppSettingPathConverter() { AppDomain.Unload(appDomain); } - if (configurationFileName is not null) - { - File.Delete(configurationFileName); - } } } @@ -106,13 +105,6 @@ private void TestAppSettingPathConverterInConfiguredDomain() "Evaluated pattern expected to be \"(null)\" for non-existent appSettings key"); } - private static string CreateTempConfigFile(string configurationFileContent) - { - string fileName = Path.GetTempFileName(); - File.WriteAllText(fileName, configurationFileContent); - return fileName; - } - private static AppDomain CreateConfiguredDomain(string domainName, string configurationFileName) { AppDomainSetup ads = new() From dc354f9cf8dd3a62a98c2e358965afa86dace150 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Sat, 19 Sep 2026 21:20:38 +0200 Subject: [PATCH 06/14] bump PeanutButter.Utils to 3.0.437 --- src/Directory.Build.props | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Directory.Build.props b/src/Directory.Build.props index a14971b18..df004bc91 100644 --- a/src/Directory.Build.props +++ b/src/Directory.Build.props @@ -34,7 +34,7 @@ 4.3.0 4.2.2 4.6.0 - 2.0.63 + 3.0.437 1.0.25 From 0e1e7cffd3fbc4502f5de0288056599d88f02e8f Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Sat, 19 Sep 2026 21:20:39 +0200 Subject: [PATCH 07/14] document the overrides in the two locking fakes --- src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs | 6 ++++++ src/log4net.Tests/Appender/LockingStreamTest.cs | 6 ++++++ 2 files changed, 12 insertions(+) diff --git a/src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs b/src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs index 83b77c48e..dd63f7d7c 100644 --- a/src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs +++ b/src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs @@ -43,19 +43,25 @@ private sealed class RecordingLock : FileAppender.LockingModelBase { internal string? FileAtActivation { get; private set; } + /// public override void ActivateOptions() => FileAtActivation = CurrentAppender?.File; + /// public override Stream? AcquireLock() => Stream.Null; + /// public override void ReleaseLock() { } + /// public override void OpenFile(string filename, bool append, Encoding encoding) { } + /// public override void CloseFile() { } + /// public override void OnClose() { } } diff --git a/src/log4net.Tests/Appender/LockingStreamTest.cs b/src/log4net.Tests/Appender/LockingStreamTest.cs index abe9d49c6..b9247237e 100644 --- a/src/log4net.Tests/Appender/LockingStreamTest.cs +++ b/src/log4net.Tests/Appender/LockingStreamTest.cs @@ -39,19 +39,25 @@ private sealed class SwitchableLock : FileAppender.LockingModelBase internal int ReleaseCount { get; private set; } + /// public override Stream? AcquireLock() => CanAcquire ? Stream.Null : null; + /// public override void ReleaseLock() => ReleaseCount++; + /// public override void OpenFile(string filename, bool append, Encoding encoding) { } + /// public override void CloseFile() { } + /// public override void ActivateOptions() { } + /// public override void OnClose() { } } From 1b7a8ae1917ceaf567ff598203d35031ec95716d Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Sat, 19 Sep 2026 21:20:39 +0200 Subject: [PATCH 08/14] cap the mutex name by UTF-8 bytes, not characters #319 104 characters can be 304 bytes, and Unix rejects by bytes. --- src/changelog/3.5.0/319-mutex-name-length.xml | 4 ++-- .../Appender/FileAppenderMutexNameTest.cs | 19 +++++++++++++++++++ src/log4net/Appender/FileAppender.cs | 13 +++++++------ 3 files changed, 28 insertions(+), 8 deletions(-) diff --git a/src/changelog/3.5.0/319-mutex-name-length.xml b/src/changelog/3.5.0/319-mutex-name-length.xml index c9ac89d8f..3cb6148c8 100644 --- a/src/changelog/3.5.0/319-mutex-name-length.xml +++ b/src/changelog/3.5.0/319-mutex-name-length.xml @@ -6,8 +6,8 @@ Keep logging to a deep path on Unix. Both the rolling lock and the inter-process file lock name their mutex after the log file, and Unix rejects a name longer than - 255 characters, throwing out of `ActivateOptions` and taking the appender with it before anything - was written. Such a name is replaced by a hash of the path now. Windows enforces no + 255 UTF-8 bytes, which a path of 104 characters can already exceed, throwing out of + `ActivateOptions` and taking the appender with it before anything was written. Such a name is replaced by a hash of the path now. Windows enforces no length limit at all, and names are left alone there, so the only ones that change are the ones that used to throw and exclusion against an older version is nowhere affected (audit da18b6fd-f010, da18b6fd-f031, fixed by @FreeAndNil) diff --git a/src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs b/src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs index dd63f7d7c..c30701c8e 100644 --- a/src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs +++ b/src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs @@ -169,6 +169,25 @@ public void ALongPathIsHashedWhereThePlatformHasALimit() mutex.ReleaseMutex(); } + /// + /// The limit is on encoded bytes, not characters: a name of 104 characters and 304 bytes is + /// already refused, measured, so counting characters lets one through that cannot be created. + /// + [Test] + public void AMultibytePathIsMeasuredInBytes() + { + // Well under the limit as characters, well over it as UTF-8. + string multibyte = "/" + new string('\u4e2d', 200) + "/app.log"; + Assert.That(multibyte, Has.Length.LessThan(255), "the point of the fixture is a short-looking name"); + + string name = MutexNameForPath(multibyte, "_rolling", 255); + + Assert.That(Encoding.UTF8.GetByteCount(name), Is.LessThanOrEqualTo(255)); + using Mutex mutex = new(false, name); + Assert.That(mutex.WaitOne(0), Is.True); + mutex.ReleaseMutex(); + } + /// With no limit, which is Windows, the name is left as earlier versions computed it. [Test] public void ALongPathIsLeftAloneWhereThePlatformHasNoLimit() diff --git a/src/log4net/Appender/FileAppender.cs b/src/log4net/Appender/FileAppender.cs index aa3c242f7..fbbf98bca 100644 --- a/src/log4net/Appender/FileAppender.cs +++ b/src/log4net/Appender/FileAppender.cs @@ -1374,21 +1374,22 @@ protected virtual void SetQWForFiles(TextWriter writer) /// /// /// The flattened path, as earlier versions computed it. Only a name the platform rejects is - /// hashed: Unix stops at , Windows has no limit. Unprefixed, so + /// hashed: Unix stops at , Windows has no limit. Unprefixed, so /// on Windows it coordinates one session. /// internal static string MutexNameForPath(string path, string suffix) - => MutexNameForPath(path, suffix, SystemInfo.IsWindows ? null : MaxMutexNameLength); + => MutexNameForPath(path, suffix, SystemInfo.IsWindows ? null : MaxMutexNameBytes); /// Takes the limit rather than deciding it, so both branches are testable anywhere. - private static string MutexNameForPath(string path, string suffix, int? maxLength) + private static string MutexNameForPath(string path, string suffix, int? maxBytes) { string name = path.EnsureNotNull() .Replace("\\", "_") .Replace(":", "_") .Replace("/", "_") + suffix; - if (maxLength is null || name.Length <= maxLength) + // Encoded bytes, not characters: a name of 104 characters and 304 bytes is already refused. + if (maxBytes is null || Encoding.UTF8.GetByteCount(name) <= maxBytes) { return name; } @@ -1399,8 +1400,8 @@ private static string MutexNameForPath(string path, string suffix, int? maxLengt return "log4net_" + BitConverter.ToString(hash).Replace("-", "") + suffix; } - /// The longest mutex name Unix accepts. Windows has no limit. Both measured. - private const int MaxMutexNameLength = 255; + /// The longest mutex name Unix accepts, in UTF-8 bytes. Windows has no limit. Measured. + private const int MaxMutexNameBytes = 255; /// /// The name of the log file. From 1865b503351371f4177e63665aec7091b7d1c8a5 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Sat, 19 Sep 2026 21:20:40 +0200 Subject: [PATCH 09/14] retry a pending rename outside the size roll path #319 - Date mode never retried: the check sat inside the size-rolling guard. - The startup roll fell through to AppendToFile and truncated the file. --- .../3.5.0/319-rollover-keeps-events.xml | 4 +- .../RollingFileAppenderRollFailureTest.cs | 114 ++++++++++++++++++ src/log4net/Appender/RollingFileAppender.cs | 25 ++-- 3 files changed, 134 insertions(+), 9 deletions(-) diff --git a/src/changelog/3.5.0/319-rollover-keeps-events.xml b/src/changelog/3.5.0/319-rollover-keeps-events.xml index 9ccb7fdb0..fd9fedcee 100644 --- a/src/changelog/3.5.0/319-rollover-keeps-events.xml +++ b/src/changelog/3.5.0/319-rollover-keeps-events.xml @@ -10,6 +10,8 @@ to cause it. The file is appended to now. Only the rename that failed is retried, once per `MaxFileSize` of growth, which is the cadence a working rollover would have had, because a full retry would shift the numbered backups again and lose the oldest one every time; the file - therefore grows past `MaxFileSize` for as long as the rename keeps failing (audit da18b6fd-f036, + therefore grows past `MaxFileSize` for as long as the rename keeps failing. The rollover at + startup keeps the file too, so a failed rename there no longer empties it where `AppendToFile` is + false (audit da18b6fd-f036, fixed by @FreeAndNil) diff --git a/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs b/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs index c896b3c0f..acc626d32 100644 --- a/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs +++ b/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs @@ -298,6 +298,120 @@ public void ATimeRollAfterAFailedRenameTakesEveryBackupWithIt() "the backup stayed under the old base name instead of moving with the group"); } + /// + /// A failed time rename is retried too, where size rolling is switched off entirely. Without + /// that, the pending rename waits for a size roll that never comes, and the next boundary + /// archives the accumulated file under the later period. + /// + [Test] + [NonParallelizable] + public void AFailedTimeRenameIsRetriedWithoutSizeRolling() + { + using AutoTempFolder folder = new(); + Internal.RecordingErrorHandler errors = new(); + string file = Path.Combine(folder.Path, "roll-failure.log"); + MockDateTime clock = new(new DateTime(2026, 1, 1, 12, 0, 0, DateTimeKind.Local)); + RollingFileAppender appender = new() + { + File = file, + Layout = new PatternLayout("%message%newline"), + RollingStyle = RollingFileAppender.RollingMode.Date, + DatePattern = "'.'yyyy-MM-dd", + StaticLogFileName = true, + // Size rolling stays off; this only paces the retry, which is what the defect ignored. + MaximumFileSize = "200", + AppendToFile = true, + LockingModel = new FileAppender.MinimalLock(), + DateTimeStrategy = clock, + ErrorHandler = errors + }; + appender.ActivateOptions(); + string dated = file + ".2026-01-01"; + + try + { + appender.DoAppend(CreateEvent(Marker)); + + BlockRename(dated); + + // A day on, so the time roll runs and cannot move the file. + clock.Now = clock.Now.AddDays(1); + LogLog.ExecuteWithoutEmittingInternalMessages( + () => appender.DoAppend(CreateEvent(new string('a', 200)))); + Assert.That(errors.Messages, Is.Not.Empty, "the time rename never failed, so nothing was exercised"); + Assert.That(File.ReadAllText(file), Does.Contain(Marker), "the failed rename must keep the file"); + + UnblockRename(dated); + + // Grow past the retry threshold. With the retry nested under size rolling, nothing happens. + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + for (int i = 0; i < 20 && !File.Exists(dated); i++) + { + appender.DoAppend(CreateEvent(new string('b', 200))); + } + }); + } + finally + { + LogLog.ExecuteWithoutEmittingInternalMessages(appender.Close); + } + + Assert.That(File.Exists(dated), Is.True, + "the pending time rename was never retried, so the period was never archived"); + Assert.That(File.ReadAllText(dated), Does.Contain(Marker)); + } + + /// + /// The roll ExistingInit performs at startup, before anything is open. Its failed rename used to + /// fall through to the configured AppendToFile, so AppendToFile=false destroyed the period the + /// rename could not archive. + /// + [Test] + [NonParallelizable] + public void AFailedStartupRollKeepsTheFileItCouldNotMove() + { + using AutoTempFolder folder = new(); + Internal.RecordingErrorHandler errors = new(); + string file = Path.Combine(folder.Path, "roll-failure.log"); + MockDateTime clock = new(new DateTime(2026, 1, 2, 12, 0, 0, DateTimeKind.Local)); + + // Yesterday's log, left behind by the previous run, and its archive name is taken. + File.WriteAllText(file, Marker + Environment.NewLine); + File.SetLastWriteTime(file, clock.Now.AddDays(-1)); + string dated = file + ".2026-01-01"; + BlockRename(dated); + + RollingFileAppender appender = new() + { + File = file, + Layout = new PatternLayout("%message%newline"), + RollingStyle = RollingFileAppender.RollingMode.Date, + DatePattern = "'.'yyyy-MM-dd", + StaticLogFileName = true, + // The setting that used to decide it: an explicit request for an empty file at startup. + AppendToFile = false, + LockingModel = new FileAppender.MinimalLock(), + DateTimeStrategy = clock, + ErrorHandler = errors + }; + + try + { + LogLog.ExecuteWithoutEmittingInternalMessages(appender.ActivateOptions); + Assert.That(errors.Messages, Is.Not.Empty, "the startup rename never failed, so nothing was exercised"); + + LogLog.ExecuteWithoutEmittingInternalMessages(() => appender.DoAppend(CreateEvent("after startup"))); + } + finally + { + LogLog.ExecuteWithoutEmittingInternalMessages(appender.Close); + } + + Assert.That(File.ReadAllText(file), Does.Contain(Marker), + "the startup roll could not rename the file, so opening it must not have truncated it"); + } + /// /// Blocks one rename by occupying its target with a directory. /// throws when the destination exists, and the appender's own delete of the target skips it, diff --git a/src/log4net/Appender/RollingFileAppender.cs b/src/log4net/Appender/RollingFileAppender.cs index 7c65d9064..70a2b50fd 100644 --- a/src/log4net/Appender/RollingFileAppender.cs +++ b/src/log4net/Appender/RollingFileAppender.cs @@ -574,17 +574,19 @@ protected virtual void AdjustFileBeforeAppend() } } - if (_rollSize && (File is not null) && CountingWriter.Count >= MaxFileSize) + // A pending rename outranks a size roll, and is retried even where size rolling is off: a + // failed time rename needs the retry just as much, and MaxFileSize only paces it. + if (_pendingRename is not null) { - if (_pendingRename is null) - { - RollOverSize(); - } - else if (CountingWriter.Count >= _pendingRename.RetryAtCount) + if (CountingWriter.Count >= _pendingRename.RetryAtCount) { RetryFailedRoll(); } } + else if (_rollSize && (File is not null) && CountingWriter.Count >= MaxFileSize) + { + RollOverSize(); + } } finally { @@ -612,6 +614,12 @@ protected override void OpenFile(string fileName, bool append) { fileName = GetNextOutputFileName(fileName); + // A rename that failed left its file where it was. Never truncate that one, whatever + // AppendToFile says, or the roll destroys what it could not move. + append = append + || (_pendingRename is not null + && string.Equals(fileName, _pendingRename.From, StringComparison.Ordinal)); + // Calculate the current size of the file long currentCount = 0; if (append) @@ -1171,8 +1179,9 @@ protected void RollOverTime(bool fileIsOpen) } else { - // The startup roll, with no file open to grow, so nothing can trigger a retry. As before. - _pendingRename = null; + // The startup roll, from ExistingInit, with nothing open yet. A failed rename here leaves the + // previous period in the file, so the pending rename stays armed: the open that follows must + // not truncate it, and the first append retries the rename. } } From 5b594a8b667960eceec3576ce6824d00759df489 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Sat, 19 Sep 2026 21:20:40 +0200 Subject: [PATCH 10/14] retry a pending rename every tenth of MaxFileSize #319 CLAUDE.md: a logged raw string keeps its newlines, and only the first line carries the prefix. --- CLAUDE.md | 7 ++++-- .../3.5.0/319-rollover-keeps-events.xml | 6 ++--- .../RollingFileAppenderRollFailureTest.cs | 15 +++++++------ src/log4net/Appender/RollingFileAppender.cs | 22 ++++++++++++++----- 4 files changed, 32 insertions(+), 18 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 3c3ecc5ea..942d9c825 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -37,8 +37,11 @@ almost always be doing. - **Wrap long string literals with a multi-line raw string (`"""`), never with `+` concatenation.** This includes attribute arguments; see the `[Obsolete(...)]` message on `log4net.Appender.SmtpAppender`. Raw strings have no line-continuation, so each source line - break really is a `\n` in the value, but that is fine here: compiler diagnostics render those - newlines as spaces, so a wrapped message still reads as one sentence. Raw strings are constant + break really is a `\n` in the value. For a compiler diagnostic that is free, since the tooling + renders those newlines as spaces. For a message that is **logged**, through `LogLog` or an + `ErrorHandler`, the breaks reach the output: `LogLog` prefixes once per message, so the + continuation lines carry no `log4net:ERROR`. That is accepted, and the rule holds there too; + do not reintroduce `+` concatenation to keep such a message on one line. Raw strings are constant expressions, so they are legal in attributes, and the feature is purely syntactic, so it works on `net462`/`netstandard2.0` too. - Private fields are `_camelCase`. Private fields and helper methods are commonly placed diff --git a/src/changelog/3.5.0/319-rollover-keeps-events.xml b/src/changelog/3.5.0/319-rollover-keeps-events.xml index fd9fedcee..8166fd569 100644 --- a/src/changelog/3.5.0/319-rollover-keeps-events.xml +++ b/src/changelog/3.5.0/319-rollover-keeps-events.xml @@ -7,9 +7,9 @@ Keep the log file when a rollover cannot rename it. The failed rename was reported and the file then reopened without appending, which destroyed everything it held; a reader holding the file without `FILE_SHARE_DELETE`, such as a backup or antivirus agent, is enough - to cause it. The file is appended to now. Only the rename that failed is retried, once per - `MaxFileSize` of growth, which is the cadence a working rollover would have had, because a full - retry would shift the numbered backups again and lose the oldest one every time; the file + to cause it. The file is appended to now. Only the rename that failed is retried, once per tenth + of `MaxFileSize` of growth, because a full retry would shift the numbered backups again and lose + the oldest one every time; the file therefore grows past `MaxFileSize` for as long as the rename keeps failing. The rollover at startup keeps the file too, so a failed rename there no longer empties it where `AppendToFile` is false (audit da18b6fd-f036, diff --git a/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs b/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs index acc626d32..a7e365653 100644 --- a/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs +++ b/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs @@ -84,14 +84,15 @@ public void AFailedRollKeepsTheEventsItCouldNotMove() string[] afterFirstFailure = Backups(file); Assert.That(afterFirstFailure, Is.Not.Empty, "the fixture needs an archive for the roll to shift"); string[] contentAfterFirstFailure = Array.ConvertAll(afterFirstFailure, File.ReadAllText); + int attemptsBeforeGrowth = BaseRenameAttempts(errors, file); - // Events well under MaxFileSize, so a retry per MaxFileSize of growth is measurably rarer - // than a retry per event. At 200 bytes each the two cadences would be the same thing. + // Events well under a tenth of MaxFileSize, which is the retry cadence, so the attempts are + // measurably rarer than the events. At 20 bytes each the two would be the same thing. LogLog.ExecuteWithoutEmittingInternalMessages(() => { for (int i = 0; i < 20; i++) { - appender.DoAppend(CreateEvent(new string('b', 50))); + appender.DoAppend(CreateEvent("b")); } }); @@ -99,10 +100,10 @@ public void AFailedRollKeepsTheEventsItCouldNotMove() "the archive was rotated again while the rename kept failing"); Assert.That(Array.ConvertAll(afterFirstFailure, File.ReadAllText), Is.EqualTo(contentAfterFirstFailure), "the backup contents were rewritten while the rename kept failing"); - // Only the base rename is retried, and only once the file has grown another MaxFileSize, - // so the attempts are far fewer than the 20 events above. - Assert.That(BaseRenameAttempts(errors, file), Is.LessThan(20), - "the rename was retried per event instead of per MaxFileSize of growth"); + // Only the base rename is retried, once per tenth of MaxFileSize of growth: often enough + // that 40 bytes of events bring two attempts, rarely enough that 20 events do not bring 20. + Assert.That(BaseRenameAttempts(errors, file) - attemptsBeforeGrowth, Is.InRange(2, 19), + "the retry cadence is neither a tenth of MaxFileSize nor anything close to it"); } finally { diff --git a/src/log4net/Appender/RollingFileAppender.cs b/src/log4net/Appender/RollingFileAppender.cs index 70a2b50fd..a0344eadc 100644 --- a/src/log4net/Appender/RollingFileAppender.cs +++ b/src/log4net/Appender/RollingFileAppender.cs @@ -1363,9 +1363,10 @@ protected void RollOverSize() ScheduleRollRetry(); // The failing rename already reported, and OnlyOnceErrorHandler silences the handler after // the first report, so this one goes through LogLog to survive. - LogLog.Error(_declaringType, - $"Rolling {_pendingRename.From} failed, so it is kept and appended to. Only that rename is " - + "retried, once per MaxFileSize of growth, so the backups are left alone."); + LogLog.Error(_declaringType, $""" + Rolling {_pendingRename.From} failed, so it is kept and appended to. Only that rename is + retried, once per {MaxFileSize / RetryGrowthDivisor} bytes of growth, so the backups are left alone. + """); } } @@ -1374,15 +1375,18 @@ private void RecordFailedBaseRename(string fromFile, string toFile, bool wasBack => _pendingRename = new(fromFile, toFile, wasBackupCountReverted); /// - /// Schedules the next attempt at the failed base rename, one of growth - /// away: the cadence a working roll would have had. + /// Schedules the next attempt at the failed base rename, a + /// tenth of of growth away. /// private void ScheduleRollRetry() { // A refused lock leaves no writer, and then the threshold simply stays where it was. if (_pendingRename is not null && QuietWriter is CountingQuietTextWriter countingWriter) { - _pendingRename = _pendingRename with { RetryAtCount = countingWriter.Count + MaxFileSize }; + _pendingRename = _pendingRename with + { + RetryAtCount = countingWriter.Count + Math.Max(MaxFileSize / RetryGrowthDivisor, 1) + }; } } @@ -1663,6 +1667,12 @@ protected static DateTime NextCheckDate(DateTime currentDateTime, RollPoint roll /// private PendingRename? _pendingRename; + /// + /// The share of the file grows between retries: soon enough to recover + /// from a transient block, rare enough not to attempt the rename on every event. + /// + private const long RetryGrowthDivisor = 10; + /// How many renames have failed, so one call can be told apart. private int _rollFailures; From ef16930b8cc3c1827b5785972a6aee9d220561ba Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Sat, 19 Sep 2026 21:20:40 +0200 Subject: [PATCH 11/14] the changelog attribution does not repeat the pull request link --- CLAUDE.md | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 942d9c825..0da68f394 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -223,9 +223,10 @@ Every user-visible change gets an entry in `src/changelog//` Write prose. Bullets are fine in commit messages. - Close the description with an attribution in parentheses, crediting both sides: who raised it and who did the work, as in `(reported by @viktorgobbi, fixed by @FreeAndNil)`. `implemented by` reads - better than `fixed by` for an `added` or `changed` entry, and once a pull request exists the house - form appends it: `fixed by @FreeAndNil in https://github.com/apache/logging-log4net/pull/246[#246]`. - Take the fixer from the active committers in `STATUS.txt`, whose Apache ids are the GitHub handles + better than `fixed by` for an `added` or `changed` entry. **Do not append the pull request link to + the attribution**: the `` element above the description already carries it, and entries + that repeat it are the older form. Take the fixer from the active committers in `STATUS.txt`, + whose Apache ids are the GitHub handles (`freeandnil`, `gdziadkiewicz`, `davydm`), and identify which one from the session's `git config user.email`. Ask rather than guess if that does not match a listed committer. - `src/changelog/3.3.2/298-fix-interprocesslock-mutex-leak.xml` shows the shape for a change that From c907f7fe7a638e122e80b437f14482095bbece20 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Sat, 19 Sep 2026 23:07:03 +0200 Subject: [PATCH 12/14] compute the retry threshold once #319 - the message printed 0 bytes of growth where the threshold was really 1 - the retry-count assertion allowed 2 to 19, so a wrong threshold passed it. Two attempts on Unix, three on Windows, and the range says which is which - record what the mutex suffix collision costs - drop the empty else, rewrap a long changelog line --- src/changelog/3.5.0/319-mutex-name-length.xml | 8 ++++---- .../RollingFileAppenderRollFailureTest.cs | 14 ++++++++------ src/log4net/Appender/FileAppender.cs | 6 ++++++ src/log4net/Appender/RollingFileAppender.cs | 16 ++++++++-------- 4 files changed, 26 insertions(+), 18 deletions(-) diff --git a/src/changelog/3.5.0/319-mutex-name-length.xml b/src/changelog/3.5.0/319-mutex-name-length.xml index 3cb6148c8..a4b531d39 100644 --- a/src/changelog/3.5.0/319-mutex-name-length.xml +++ b/src/changelog/3.5.0/319-mutex-name-length.xml @@ -7,8 +7,8 @@ Keep logging to a deep path on Unix. Both the rolling lock and the inter-process file lock name their mutex after the log file, and Unix rejects a name longer than 255 UTF-8 bytes, which a path of 104 characters can already exceed, throwing out of - `ActivateOptions` and taking the appender with it before anything was written. Such a name is replaced by a hash of the path now. Windows enforces no - length limit at all, and names are left alone there, so the only ones that change are the ones - that used to throw and exclusion against an older version is nowhere affected (audit - da18b6fd-f010, da18b6fd-f031, fixed by @FreeAndNil) + `ActivateOptions` and taking the appender with it before anything was written. Such a name is + replaced by a hash of the path now. Windows enforces no length limit at all, and names are left + alone there, so the only ones that change are the ones that used to throw and exclusion against + an older version is nowhere affected (audit da18b6fd-f010, da18b6fd-f031, fixed by @FreeAndNil) diff --git a/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs b/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs index a7e365653..1f95b23af 100644 --- a/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs +++ b/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs @@ -86,8 +86,8 @@ public void AFailedRollKeepsTheEventsItCouldNotMove() string[] contentAfterFirstFailure = Array.ConvertAll(afterFirstFailure, File.ReadAllText); int attemptsBeforeGrowth = BaseRenameAttempts(errors, file); - // Events well under a tenth of MaxFileSize, which is the retry cadence, so the attempts are - // measurably rarer than the events. At 20 bytes each the two would be the same thing. + // Events much smaller than a tenth of MaxFileSize, which is how far the file must grow before + // the next attempt, so there are far fewer attempts than events. At 20 bytes each they match. LogLog.ExecuteWithoutEmittingInternalMessages(() => { for (int i = 0; i < 20; i++) @@ -100,10 +100,12 @@ public void AFailedRollKeepsTheEventsItCouldNotMove() "the archive was rotated again while the rename kept failing"); Assert.That(Array.ConvertAll(afterFirstFailure, File.ReadAllText), Is.EqualTo(contentAfterFirstFailure), "the backup contents were rewritten while the rename kept failing"); - // Only the base rename is retried, once per tenth of MaxFileSize of growth: often enough - // that 40 bytes of events bring two attempts, rarely enough that 20 events do not bring 20. - Assert.That(BaseRenameAttempts(errors, file) - attemptsBeforeGrowth, Is.InRange(2, 19), - "the retry cadence is neither a tenth of MaxFileSize nor anything close to it"); + // Only the base rename is retried, and only after the file has grown another tenth of + // MaxFileSize: two attempts on Unix, three on Windows, because %newline is + // Environment.NewLine and these 20 events are 40 bytes on one and 60 on the other. The range + // is those two values, not a tolerance. + Assert.That(BaseRenameAttempts(errors, file) - attemptsBeforeGrowth, Is.InRange(2, 3), + "the rename is not retried after every tenth of MaxFileSize of growth"); } finally { diff --git a/src/log4net/Appender/FileAppender.cs b/src/log4net/Appender/FileAppender.cs index fbbf98bca..5e2e81b0d 100644 --- a/src/log4net/Appender/FileAppender.cs +++ b/src/log4net/Appender/FileAppender.cs @@ -1376,6 +1376,12 @@ protected virtual void SetQWForFiles(TextWriter writer) /// The flattened path, as earlier versions computed it. Only a name the platform rejects is /// hashed: Unix stops at , Windows has no limit. Unprefixed, so /// on Windows it coordinates one session. + /// + /// The suffix can collide, since it is only appended: the lock for /var/log/app_rolling and + /// the rolling lock for /var/log/app name one mutex. Two unrelated files then contend on + /// it, which costs waiting, not a lost lock or a lost file, and the alternative is renaming every + /// mutex and losing exclusion against older versions everywhere. + /// /// internal static string MutexNameForPath(string path, string suffix) => MutexNameForPath(path, suffix, SystemInfo.IsWindows ? null : MaxMutexNameBytes); diff --git a/src/log4net/Appender/RollingFileAppender.cs b/src/log4net/Appender/RollingFileAppender.cs index a0344eadc..dc6b8e81f 100644 --- a/src/log4net/Appender/RollingFileAppender.cs +++ b/src/log4net/Appender/RollingFileAppender.cs @@ -1169,6 +1169,9 @@ protected void RollOverTime(bool fileIsOpen) //new scheduled name _scheduledFilename = CombinePath(File!, _now.ToString(DatePattern, DateTimeFormatInfo.InvariantInfo)); + // Nothing is open during the startup roll, from ExistingInit. A failed rename there leaves the + // previous period in the file, and the pending rename stays armed: the open that follows must + // not truncate it, and the first append retries the rename. if (fileIsOpen) { // This will also close the file. This is OK since multiple close operations are safe. @@ -1177,12 +1180,6 @@ protected void RollOverTime(bool fileIsOpen) // Its own threshold, or the one from a size failure would fire a retry immediately. ScheduleRollRetry(); } - else - { - // The startup roll, from ExistingInit, with nothing open yet. A failed rename here leaves the - // previous period in the file, so the pending rename stays armed: the open that follows must - // not truncate it, and the first append retries the rename. - } } /// @@ -1365,7 +1362,7 @@ protected void RollOverSize() // the first report, so this one goes through LogLog to survive. LogLog.Error(_declaringType, $""" Rolling {_pendingRename.From} failed, so it is kept and appended to. Only that rename is - retried, once per {MaxFileSize / RetryGrowthDivisor} bytes of growth, so the backups are left alone. + retried, once per {RetryGrowth} bytes of growth, so the backups are left alone. """); } } @@ -1385,7 +1382,7 @@ private void ScheduleRollRetry() { _pendingRename = _pendingRename with { - RetryAtCount = countingWriter.Count + Math.Max(MaxFileSize / RetryGrowthDivisor, 1) + RetryAtCount = countingWriter.Count + RetryGrowth }; } } @@ -1673,6 +1670,9 @@ protected static DateTime NextCheckDate(DateTime currentDateTime, RollPoint roll /// private const long RetryGrowthDivisor = 10; + /// How far the file grows between attempts at a failed rename, at least one byte. + private long RetryGrowth => Math.Max(MaxFileSize / RetryGrowthDivisor, 1); + /// How many renames have failed, so one call can be told apart. private int _rollFailures; From 51a751edf65c5b8fbe2c7be1b5b1453feb5373e4 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Mon, 21 Sep 2026 20:04:56 +0200 Subject: [PATCH 13/14] keep the startup roll from rolling twice #319 - ExistingInit rolled again for AppendToFile=false, moving the file out from under the pending rename, so the first retry archived the new file under the previous date. - The forced append reached AppendToFile through base.OpenFile and replaced the configured value. Every successful roll did this, not just a failed one, so RollingCombinedWithPreserveExtension now asserts it too. - The changelog entries now describe what a user sees. --- .../3.5.0/319-lock-level-underflow.xml | 11 +- src/changelog/3.5.0/319-mutex-name-length.xml | 12 +- .../3.5.0/319-mutex-resolved-path.xml | 15 +- .../3.5.0/319-rollover-keeps-events.xml | 16 +- .../RollingFileAppenderRollFailureTest.cs | 237 ++++++++++++------ .../Appender/RollingFileAppenderTest.cs | 1 + src/log4net/Appender/RollingFileAppender.cs | 29 ++- 7 files changed, 200 insertions(+), 121 deletions(-) diff --git a/src/changelog/3.5.0/319-lock-level-underflow.xml b/src/changelog/3.5.0/319-lock-level-underflow.xml index 82cf7dcd4..d8a5d818f 100644 --- a/src/changelog/3.5.0/319-lock-level-underflow.xml +++ b/src/changelog/3.5.0/319-lock-level-underflow.xml @@ -4,10 +4,9 @@ xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd" type="fixed"> - Stop the file lock counter going negative. Writing the footer, - closing the writer and opening the file released the lock even when acquiring it had failed, and a - negative count made every later acquisition fail. The footer and close paths share one helper now, - which releases only what it took; opening keeps its own acquire, because wrapping an unlocked - stream throws. Nothing was lost by this, because the appender reopens the file on the next - event (audit da18b6fd-f032, fixed by @FreeAndNil) + Stop a lock the appender could not take from + disabling it. Writing the footer, closing the writer and opening the file released the file lock + even when taking it had failed, and every later attempt then failed too, so the footer and + anything still buffered were dropped without a word. Only a lock that was taken is released + now (audit da18b6fd-f032, fixed by @FreeAndNil) diff --git a/src/changelog/3.5.0/319-mutex-name-length.xml b/src/changelog/3.5.0/319-mutex-name-length.xml index a4b531d39..adfb29e3b 100644 --- a/src/changelog/3.5.0/319-mutex-name-length.xml +++ b/src/changelog/3.5.0/319-mutex-name-length.xml @@ -4,11 +4,9 @@ xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd" type="fixed"> - Keep logging to a deep path on Unix. Both the rolling lock and the - inter-process file lock name their mutex after the log file, and Unix rejects a name longer than - 255 UTF-8 bytes, which a path of 104 characters can already exceed, throwing out of - `ActivateOptions` and taking the appender with it before anything was written. Such a name is - replaced by a hash of the path now. Windows enforces no length limit at all, and names are left - alone there, so the only ones that change are the ones that used to throw and exclusion against - an older version is nowhere affected (audit da18b6fd-f010, da18b6fd-f031, fixed by @FreeAndNil) + Keep logging to a deep path on Unix. The locks + that serialise writing and rolling are named after the log file, and Unix rejects a name longer + than 255 UTF-8 bytes, which a path of 104 characters can already exceed, so the appender failed to + start and nothing was written at all. Such a name is hashed now; shorter ones, and every name on + Windows, are unchanged (audit da18b6fd-f010, da18b6fd-f031, fixed by @FreeAndNil) diff --git a/src/changelog/3.5.0/319-mutex-resolved-path.xml b/src/changelog/3.5.0/319-mutex-resolved-path.xml index a4d6d87d2..ffd3a7d36 100644 --- a/src/changelog/3.5.0/319-mutex-resolved-path.xml +++ b/src/changelog/3.5.0/319-mutex-resolved-path.xml @@ -4,12 +4,11 @@ xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd" type="fixed"> - Let two processes that spell the log path differently share one - inter-process file lock. `InterProcessLock` named its mutex after the configured path before that - path was resolved, so a relative and an absolute spelling of one file took two different mutexes - and excluded nothing. The name comes from the resolved path now. That resolves a relative path and - nothing else: symbolic links, hard links, 8.3 short names, letter case and UNC versus mapped-drive - spellings still produce different names. The name is also unprefixed, which on Windows makes it - per-session, so a service and an interactive process have never coordinated through it (audit - da18b6fd-f031, fixed by @FreeAndNil) + Let two processes that spell the log path + differently share one file lock. The lock was named after the configured path before that path was + resolved, so a relative and an absolute spelling of one file took two different locks and excluded + nothing. The resolved path names it now. Only that spelling is covered: symbolic links, hard + links, 8.3 short names, letter case and UNC versus mapped-drive spellings still count as different + files, and on Windows a service and a desktop application never share the lock at + all (audit da18b6fd-f031, fixed by @FreeAndNil) diff --git a/src/changelog/3.5.0/319-rollover-keeps-events.xml b/src/changelog/3.5.0/319-rollover-keeps-events.xml index 8166fd569..42dd37a60 100644 --- a/src/changelog/3.5.0/319-rollover-keeps-events.xml +++ b/src/changelog/3.5.0/319-rollover-keeps-events.xml @@ -4,14 +4,10 @@ xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd" type="fixed"> - Keep the log file when a rollover cannot rename it. The failed rename - was reported and the file then reopened without appending, which destroyed everything it held; a - reader holding the file without `FILE_SHARE_DELETE`, such as a backup or antivirus agent, is enough - to cause it. The file is appended to now. Only the rename that failed is retried, once per tenth - of `MaxFileSize` of growth, because a full retry would shift the numbered backups again and lose - the oldest one every time; the file - therefore grows past `MaxFileSize` for as long as the rename keeps failing. The rollover at - startup keeps the file too, so a failed rename there no longer empties it where `AppendToFile` is - false (audit da18b6fd-f036, - fixed by @FreeAndNil) + Keep the log file when a rollover cannot rename it. The failed + rename was reported and the file then reopened without appending, which destroyed everything it + held; a reader holding the file without `FILE_SHARE_DELETE`, such as a backup or antivirus agent, + is enough to cause it. The file is kept and appended to now, at startup as well, and the rename is + retried as the file grows, so it can exceed `MaxFileSize` while the rename keeps failing (audit + da18b6fd-f036, fixed by @FreeAndNil) diff --git a/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs b/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs index 1f95b23af..918e7f7fe 100644 --- a/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs +++ b/src/log4net.Tests/Appender/RollingFileAppenderRollFailureTest.cs @@ -19,6 +19,7 @@ using System; using System.IO; +using System.Text; using log4net.Appender; using log4net.Core; using log4net.Layout; @@ -52,17 +53,7 @@ public void AFailedRollKeepsTheEventsItCouldNotMove() using AutoTempFolder folder = new(); Internal.RecordingErrorHandler errors = new(); string file = Path.Combine(folder.Path, "roll-failure.log"); - RollingFileAppender appender = new() - { - File = file, - Layout = new PatternLayout("%message%newline"), - RollingStyle = RollingFileAppender.RollingMode.Size, - MaxSizeRollBackups = 3, - MaximumFileSize = "200", - AppendToFile = true, - LockingModel = new FileAppender.MinimalLock(), - ErrorHandler = errors - }; + RollingFileAppender appender = CreateAppender(file, errors, maxSizeRollBackups: 3); appender.ActivateOptions(); try @@ -128,19 +119,8 @@ public void AFailedRollKeepsTheEventsWhenTheFileNameIsDated() using AutoTempFolder folder = new(); Internal.RecordingErrorHandler errors = new(); string file = Path.Combine(folder.Path, "roll-failure.log"); - RollingFileAppender appender = new() - { - File = file, - Layout = new PatternLayout("%message%newline"), - RollingStyle = RollingFileAppender.RollingMode.Composite, - DatePattern = "'.'yyyy-MM-dd", - StaticLogFileName = false, - MaxSizeRollBackups = 3, - MaximumFileSize = "200", - AppendToFile = true, - LockingModel = new FileAppender.MinimalLock(), - ErrorHandler = errors - }; + RollingFileAppender appender = CreateAppender(file, errors, RollingFileAppender.RollingMode.Composite, maxSizeRollBackups: 3, + staticLogFileName: false); appender.ActivateOptions(); // The file that is written and rolled, which is not the configured name. @@ -190,18 +170,8 @@ public void ASuccessfulRetryKeepsTheBackupItRecovered() using AutoTempFolder folder = new(); Internal.RecordingErrorHandler errors = new(); string file = Path.Combine(folder.Path, "roll-failure.log"); - RollingFileAppender appender = new() - { - File = file, - Layout = new PatternLayout("%message%newline"), - RollingStyle = RollingFileAppender.RollingMode.Size, - // Far more than the run needs, so nothing may be discarded as too old. - MaxSizeRollBackups = 10, - MaximumFileSize = "200", - AppendToFile = true, - LockingModel = new FileAppender.MinimalLock(), - ErrorHandler = errors - }; + RollingFileAppender appender = CreateAppender(file, errors, + maxSizeRollBackups: 10); // far more than the run needs, so nothing may be discarded as too old appender.ActivateOptions(); try @@ -256,21 +226,9 @@ public void ATimeRollAfterAFailedRenameTakesEveryBackupWithIt() using AutoTempFolder folder = new(); Internal.RecordingErrorHandler errors = new(); string file = Path.Combine(folder.Path, "roll-failure.log"); - MockDateTime clock = new(new DateTime(2026, 1, 1, 12, 0, 0, DateTimeKind.Local)); - RollingFileAppender appender = new() - { - File = file, - Layout = new PatternLayout("%message%newline"), - RollingStyle = RollingFileAppender.RollingMode.Composite, - DatePattern = "'.'yyyy-MM-dd", - StaticLogFileName = true, - MaxSizeRollBackups = 5, - MaximumFileSize = "200", - AppendToFile = true, - LockingModel = new FileAppender.MinimalLock(), - DateTimeStrategy = clock, - ErrorHandler = errors - }; + MockDateTime clock = new(new(2026, 1, 1, 12, 0, 0, DateTimeKind.Local)); + RollingFileAppender appender = CreateAppender(file, errors, RollingFileAppender.RollingMode.Composite, maxSizeRollBackups: 5, + clock: clock); appender.ActivateOptions(); try @@ -313,21 +271,10 @@ public void AFailedTimeRenameIsRetriedWithoutSizeRolling() using AutoTempFolder folder = new(); Internal.RecordingErrorHandler errors = new(); string file = Path.Combine(folder.Path, "roll-failure.log"); - MockDateTime clock = new(new DateTime(2026, 1, 1, 12, 0, 0, DateTimeKind.Local)); - RollingFileAppender appender = new() - { - File = file, - Layout = new PatternLayout("%message%newline"), - RollingStyle = RollingFileAppender.RollingMode.Date, - DatePattern = "'.'yyyy-MM-dd", - StaticLogFileName = true, - // Size rolling stays off; this only paces the retry, which is what the defect ignored. - MaximumFileSize = "200", - AppendToFile = true, - LockingModel = new FileAppender.MinimalLock(), - DateTimeStrategy = clock, - ErrorHandler = errors - }; + MockDateTime clock = new(new(2026, 1, 1, 12, 0, 0, DateTimeKind.Local)); + RollingFileAppender appender = CreateAppender(file, errors, + RollingFileAppender.RollingMode.Date, // size rolling off; the shared MaximumFileSize only paces the retry + clock: clock); appender.ActivateOptions(); string dated = file + ".2026-01-01"; @@ -377,7 +324,7 @@ public void AFailedStartupRollKeepsTheFileItCouldNotMove() using AutoTempFolder folder = new(); Internal.RecordingErrorHandler errors = new(); string file = Path.Combine(folder.Path, "roll-failure.log"); - MockDateTime clock = new(new DateTime(2026, 1, 2, 12, 0, 0, DateTimeKind.Local)); + MockDateTime clock = new(new(2026, 1, 2, 12, 0, 0, DateTimeKind.Local)); // Yesterday's log, left behind by the previous run, and its archive name is taken. File.WriteAllText(file, Marker + Environment.NewLine); @@ -385,19 +332,9 @@ public void AFailedStartupRollKeepsTheFileItCouldNotMove() string dated = file + ".2026-01-01"; BlockRename(dated); - RollingFileAppender appender = new() - { - File = file, - Layout = new PatternLayout("%message%newline"), - RollingStyle = RollingFileAppender.RollingMode.Date, - DatePattern = "'.'yyyy-MM-dd", - StaticLogFileName = true, - // The setting that used to decide it: an explicit request for an empty file at startup. - AppendToFile = false, - LockingModel = new FileAppender.MinimalLock(), - DateTimeStrategy = clock, - ErrorHandler = errors - }; + RollingFileAppender appender = CreateAppender(file, errors, RollingFileAppender.RollingMode.Date, + appendToFile: false, // an explicit request for an empty file at startup + clock: clock); try { @@ -405,6 +342,9 @@ public void AFailedStartupRollKeepsTheFileItCouldNotMove() Assert.That(errors.Messages, Is.Not.Empty, "the startup rename never failed, so nothing was exercised"); LogLog.ExecuteWithoutEmittingInternalMessages(() => appender.DoAppend(CreateEvent("after startup"))); + + // The reopen appends, but base.OpenFile assigns that to AppendToFile, which is configuration. + Assert.That(appender.AppendToFile, Is.False, "the forced append replaced the configured value"); } finally { @@ -415,6 +355,143 @@ public void AFailedStartupRollKeepsTheFileItCouldNotMove() "the startup roll could not rename the file, so opening it must not have truncated it"); } + /// + /// The rollover ExistingInit performs for AppendToFile=false moved the file out from under a + /// pending rename, so the first retry archived the new file under the previous date. + /// + [Test] + [NonParallelizable] + public void AFailedStartupRollLeavesTheArchiveAlone() + { + using AutoTempFolder folder = new(); + Internal.RecordingErrorHandler errors = new(); + string file = Path.Combine(folder.Path, "roll-failure.log"); + MockDateTime clock = new(new(2026, 1, 2, 12, 0, 0, DateTimeKind.Local)); + + File.WriteAllText(file, Marker + Environment.NewLine); + File.SetLastWriteTime(file, clock.Now.AddDays(-1)); + string dated = file + ".2026-01-01"; + BlockRename(dated); + + RollingFileAppender appender = CreateAppender(file, errors, RollingFileAppender.RollingMode.Composite, maxSizeRollBackups: 3, + appendToFile: false, clock: clock); + + try + { + LogLog.ExecuteWithoutEmittingInternalMessages(appender.ActivateOptions); + Assert.That(errors.Messages, Is.Not.Empty, "the startup rename never failed, so nothing was exercised"); + + Assert.That(Backups(file), Is.Empty, "the startup roll moved the file into the archive anyway"); + Assert.That(File.ReadAllText(file), Does.Contain(Marker), "the startup roll destroyed the file"); + + // The pending rename is still the dated one, so the retry archives the period, not a .1. + UnblockRename(dated); + LogLog.ExecuteWithoutEmittingInternalMessages(() => + { + for (int i = 0; i < 20 && !File.Exists(dated); i++) + { + appender.DoAppend(CreateEvent(new string('a', 200))); + } + }); + } + finally + { + LogLog.ExecuteWithoutEmittingInternalMessages(appender.Close); + } + + Assert.That(File.Exists(dated), Is.True, "the retry did not archive the period the startup roll owed"); + Assert.That(File.ReadAllText(dated), Does.Contain(Marker)); + } + + /// The forced append must not survive an open that throws after taking it. + [Test] + [NonParallelizable] + public void AFailedOpenLeavesAppendToFileAsConfigured() + { + using AutoTempFolder folder = new(); + Internal.RecordingErrorHandler errors = new(); + string file = Path.Combine(folder.Path, "roll-failure.log"); + MockDateTime clock = new(new(2026, 1, 2, 12, 0, 0, DateTimeKind.Local)); + + File.WriteAllText(file, Marker + Environment.NewLine); + File.SetLastWriteTime(file, clock.Now.AddDays(-1)); + BlockRename(file + ".2026-01-01"); + + RollingFileAppender appender = + CreateAppender(file, errors, RollingFileAppender.RollingMode.Date, appendToFile: false, clock: clock); + appender.LockingModel = new ThrowingLock(); + + try + { + LogLog.ExecuteWithoutEmittingInternalMessages(appender.ActivateOptions); + Assert.That(errors.Messages, Has.Some.Contains("call failed"), "the open never failed, so nothing was exercised"); + Assert.That(appender.AppendToFile, Is.False, "a throwing open left the forced append behind"); + } + finally + { + LogLog.ExecuteWithoutEmittingInternalMessages(appender.Close); + } + } + + /// Throws out of every open, as a custom locking model may. + private sealed class ThrowingLock : FileAppender.LockingModelBase + { + /// + public override void OpenFile(string filename, bool append, Encoding encoding) + => throw new IOException("staged open failure"); + + /// + public override Stream? AcquireLock() => null; + + /// + public override void ReleaseLock() + { } + + /// + public override void CloseFile() + { } + + /// + public override void ActivateOptions() + { } + + /// + public override void OnClose() + { } + } + + /// An appender on with the settings these tests share. + private static RollingFileAppender CreateAppender( + string file, + Internal.RecordingErrorHandler errors, + RollingFileAppender.RollingMode rollingStyle = RollingFileAppender.RollingMode.Size, + int maxSizeRollBackups = 0, + bool staticLogFileName = true, + bool appendToFile = true, + RollingFileAppender.IDateTime? clock = null) + { + RollingFileAppender appender = new() + { + File = file, + Layout = new PatternLayout("%message%newline"), + RollingStyle = rollingStyle, + DatePattern = "'.'yyyy-MM-dd", + StaticLogFileName = staticLogFileName, + MaxSizeRollBackups = maxSizeRollBackups, + MaximumFileSize = "200", + AppendToFile = appendToFile, + LockingModel = new FileAppender.MinimalLock(), + ErrorHandler = errors + }; + + if (clock is not null) + { + appender.DateTimeStrategy = clock; + } + + return appender; + } + /// /// Blocks one rename by occupying its target with a directory. /// throws when the destination exists, and the appender's own delete of the target skips it, diff --git a/src/log4net.Tests/Appender/RollingFileAppenderTest.cs b/src/log4net.Tests/Appender/RollingFileAppenderTest.cs index 82c896d58..f67c8818a 100644 --- a/src/log4net.Tests/Appender/RollingFileAppenderTest.cs +++ b/src/log4net.Tests/Appender/RollingFileAppenderTest.cs @@ -234,6 +234,7 @@ public void RollingCombinedWithPreserveExtension() _root.Log(Level.Debug, s.ToString(), null); } + Assert.That(roller.AppendToFile, Is.True, "an ordinary roll replaced the configured value"); VerifyFileCount(2, true); } diff --git a/src/log4net/Appender/RollingFileAppender.cs b/src/log4net/Appender/RollingFileAppender.cs index dc6b8e81f..d6ad43f65 100644 --- a/src/log4net/Appender/RollingFileAppender.cs +++ b/src/log4net/Appender/RollingFileAppender.cs @@ -653,13 +653,19 @@ protected override void OpenFile(string fileName, bool append) } // Open the file (call the base class to do it) - base.OpenFile(fileName, append); - - // Set the file size onto the counting writer - if (QuietWriter is CountingQuietTextWriter countingWriter) + // base.OpenFile assigns append to AppendToFile, and can throw after doing so. + bool configuredAppend = AppendToFile; + try + { + base.OpenFile(fileName, append); + } + finally { - countingWriter.Count = currentCount; + AppendToFile = configuredAppend; } + + // Set the file size onto the counting writer. A refused lock leaves none. + (QuietWriter as CountingQuietTextWriter)?.Count = currentCount; } } @@ -807,6 +813,12 @@ protected void ExistingInit() DetermineCurSizeRollBackups(); RollOverIfDateBoundaryCrossing(); + // Rolling again would overwrite the pending rename, or move its file out from under it. + if (_pendingRename is not null) + { + return; + } + // If file exists, and we are not appending then roll it out of the way if (AppendToFile) { @@ -1377,13 +1389,10 @@ private void RecordFailedBaseRename(string fromFile, string toFile, bool wasBack /// private void ScheduleRollRetry() { - // A refused lock leaves no writer, and then the threshold simply stays where it was. + // A refused lock leaves no writer, so not CountingWriter; the threshold stays where it was. if (_pendingRename is not null && QuietWriter is CountingQuietTextWriter countingWriter) { - _pendingRename = _pendingRename with - { - RetryAtCount = countingWriter.Count + RetryGrowth - }; + _pendingRename = _pendingRename with { RetryAtCount = countingWriter.Count + RetryGrowth }; } } From 2c7cd96f46e79987907a0ad820c9016f0e22db36 Mon Sep 17 00:00:00 2001 From: Jan Friedrich Date: Mon, 21 Sep 2026 20:18:15 +0200 Subject: [PATCH 14/14] assert the deadline, not the wall clock #319 - TheDeadlineCoversTheWholeSendAndNotOneOperation timed the whole send against a 5 s bound, and failed on a slow Windows runner at 6289 ms - the fake transport now records which call found the token cancelled --- .../Appender/FakeSmtpTransport.cs | 18 +++++++++++++----- .../Appender/SmtpAppenderTest.cs | 7 ++----- 2 files changed, 15 insertions(+), 10 deletions(-) diff --git a/src/log4net.Ext.Mail.Tests/Appender/FakeSmtpTransport.cs b/src/log4net.Ext.Mail.Tests/Appender/FakeSmtpTransport.cs index a8f50c3d5..b88990a8c 100644 --- a/src/log4net.Ext.Mail.Tests/Appender/FakeSmtpTransport.cs +++ b/src/log4net.Ext.Mail.Tests/Appender/FakeSmtpTransport.cs @@ -71,6 +71,9 @@ internal sealed class FakeSmtpTransport : ISmtpTransport /// When set, every call that takes a token waits this long, honouring it. internal int DelayMillisPerCall { get; set; } + /// The calls that found the token cancelled, in order. + internal List CancelledCalls { get; } = []; + public int Timeout { get; set; } public bool IsConnected { get; private set; } @@ -81,7 +84,7 @@ public void Connect(string host, int port, SecureSocketOptions secureSocketOptio CancellationToken cancellationToken) { Calls.Add(nameof(Connect)); - Delay(cancellationToken); + Delay(nameof(Connect), cancellationToken); ConnectedHost = host; ConnectedPort = port; SecureSocketOptions = secureSocketOptions; @@ -91,7 +94,7 @@ public void Connect(string host, int port, SecureSocketOptions secureSocketOptio public void Authenticate(ICredentials credentials, CancellationToken cancellationToken) { Calls.Add(nameof(Authenticate)); - Delay(cancellationToken); + Delay(nameof(Authenticate), cancellationToken); Credentials = credentials; IsAuthenticated = true; } @@ -99,7 +102,7 @@ public void Authenticate(ICredentials credentials, CancellationToken cancellatio public void Authenticate(SaslMechanism mechanism, CancellationToken cancellationToken) { Calls.Add(nameof(Authenticate)); - Delay(cancellationToken); + Delay(nameof(Authenticate), cancellationToken); SaslMechanism = mechanism; IsAuthenticated = true; } @@ -107,7 +110,7 @@ public void Authenticate(SaslMechanism mechanism, CancellationToken cancellation public void Send(MimeMessage message, CancellationToken cancellationToken) { Calls.Add(nameof(Send)); - Delay(cancellationToken); + Delay(nameof(Send), cancellationToken); if (SendException is Exception exception) { throw exception; @@ -128,13 +131,18 @@ public void Dispose() IsDisposed = true; } - private void Delay(CancellationToken cancellationToken) + private void Delay(string call, CancellationToken cancellationToken) { if (DelayMillisPerCall > 0) { cancellationToken.WaitHandle.WaitOne(DelayMillisPerCall); } + if (cancellationToken.IsCancellationRequested) + { + CancelledCalls.Add(call); + } + cancellationToken.ThrowIfCancellationRequested(); } } diff --git a/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs b/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs index 24da27eec..b3407a432 100644 --- a/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs +++ b/src/log4net.Ext.Mail.Tests/Appender/SmtpAppenderTest.cs @@ -21,7 +21,6 @@ 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; @@ -655,21 +654,19 @@ public void TheTimeoutReachesTheTransport() [Test] public void TheDeadlineCoversTheWholeSendAndNotOneOperation() { + // Under the timeout per call, over it in sum. 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("Failed to send a logging event.")); - Assert.That(stopwatch.ElapsedMilliseconds, Is.LessThan(generousBoundMillis)); + Assert.That(_transport.CancelledCalls, Is.Not.Empty, "the deadline never stopped the send"); } /// Bounded, so an unreachable server cannot grow the queue without limit.