This is an automated email from the ASF dual-hosted git repository. FreeAndNil pushed a commit to branch Feature/319-file-locking in repository https://gitbox.apache.org/repos/asf/logging-log4net.git
commit 73b9a17e110bcb6a04c3257d68e6aec9a4710165 Author: Jan Friedrich <[email protected]> AuthorDate: Sat Sep 12 00:55:18 2026 +0200 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 + src/changelog/3.5.0/319-lock-level-underflow.xml | 13 + src/changelog/3.5.0/319-rollover-keeps-events.xml | 15 + src/log4net.Tests/Appender/LockingStreamTest.cs | 143 +++++++++ .../Appender/RollingFileAppenderRollFailureTest.cs | 349 +++++++++++++++++++++ src/log4net/Appender/FileAppender.cs | 86 ++--- src/log4net/Appender/RollingFileAppender.cs | 144 ++++++++- 7 files changed, 715 insertions(+), 47 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 0e7bcaa2..3c3ecc5e 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<ISmtpTransport> 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/<unreleased version>/` `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 `<issue>` 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 00000000..82cf7dcd --- /dev/null +++ b/src/changelog/3.5.0/319-lock-level-underflow.xml @@ -0,0 +1,13 @@ +<?xml version="1.0" encoding="UTF-8"?> +<entry xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; + xmlns="https://logging.apache.org/xml/ns"; + xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"; + type="fixed"> + <issue id="319" link="https://github.com/apache/logging-log4net/pull/319"/> + <description format="asciidoc">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)</description> +</entry> 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 00000000..9ccb7fdb --- /dev/null +++ b/src/changelog/3.5.0/319-rollover-keeps-events.xml @@ -0,0 +1,15 @@ +<?xml version="1.0" encoding="UTF-8"?> +<entry xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; + xmlns="https://logging.apache.org/xml/ns"; + xsi:schemaLocation="https://logging.apache.org/xml/ns https://logging.apache.org/xml/ns/log4j-changelog-0.xsd"; + type="fixed"> + <issue id="319" link="https://github.com/apache/logging-log4net/pull/319"/> + <description format="asciidoc">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)</description> +</entry> diff --git a/src/log4net.Tests/Appender/LockingStreamTest.cs b/src/log4net.Tests/Appender/LockingStreamTest.cs new file mode 100644 index 00000000..abe9d49c --- /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; + +/// <summary>The recursion counter inside the private <c>FileAppender.LockingStream</c>.</summary> +[TestFixture] +public sealed class LockingStreamTest +{ + /// <summary>Hands out a stream only when told to, so a failed acquisition can be staged.</summary> + 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() + { } + } + + /// <summary> + /// An unmatched release drove the counter below zero, after which every later acquisition failed + /// and the model lock was never released. + /// </summary> + [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<bool>(stream, "AcquireLock"), Is.False, "the model was set up to refuse"); + Invoke(stream, "ReleaseLock"); + + model.CanAcquire = true; + + Assert.That(Invoke<bool>(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"); + } + + /// <summary>Nesting still locks and releases the model once.</summary> + [Test] + public void NestedAcquisitionsReleaseTheModelOnce() + { + SwitchableLock model = new() { CanAcquire = true }; + object stream = NewLockingStream(model); + + Assert.That(Invoke<bool>(stream, "AcquireLock"), Is.True); + Assert.That(Invoke<bool>(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)); + } + + /// <summary> + /// 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. + /// </summary> + [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<object?>(target, method); + + private static T Invoke<T>(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 00000000..13d92610 --- /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; + +/// <summary> +/// What <see cref="RollingFileAppender"/> does when a roll cannot complete. Every test here blocks +/// the base rename with <see cref="BlockRename"/>, which leaves the archive shift working, so the +/// state under test is the reported one: a reader holding the log file and nothing else. +/// </summary> +[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); + } + } + + /// <summary> + /// 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. + /// </summary> + [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"); + } + + /// <summary> + /// 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. + /// </summary> + [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"); + } + + /// <summary> + /// A retry that succeeds moves the kept file into the archive, and the next roll has to shift + /// that generation rather than overwrite it. + /// </summary> + [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"); + } + + /// <summary> + /// 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. + /// </summary> + [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"); + } + + /// <summary> + /// Blocks one rename by occupying its target with a directory. <see cref="File.Move(string,string)"/> + /// throws when the destination exists, and the appender's own delete of the target skips it, + /// because <see cref="File.Exists"/> 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. + /// </summary> + 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); + + /// <summary>The numbered backups, excluding the log file itself: a `.*` pattern matches it too.</summary> + private string[] Backups(string file) + => Array.FindAll(Directory.GetFiles(_directory, "roll-failure.log.*"), + f => !string.Equals(f, file, StringComparison.Ordinal)); + + /// <summary> + /// 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. + /// </summary> + private int BaseRenameAttempts(string file) + => _errors.Messages.FindAll(m => m.IndexOf($"[{file}] ->", StringComparison.Ordinal) >= 0).Count; + + /// <summary>Whether any numbered backup holds <paramref name="content"/>.</summary> + 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 5887fbfe..28f74a17 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() /// </remarks> 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) /// </remarks> 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) /// </remarks> 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); } /// <summary> @@ -1168,18 +1163,15 @@ protected override void WriteFooter() /// </remarks> 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() /// </remarks> 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); } /// <summary> @@ -1242,6 +1224,28 @@ protected virtual void SafeOpenFile(string fileName, bool append) } } + /// <summary> + /// Runs <paramref name="action"/> 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. + /// <see cref="Append(LoggingEvent)"/> and <see cref="WriteHeader"/> deliberately skip their work + /// instead when the lock is refused, so they keep their own acquire. + /// </summary> + private void RunWithBestEffortLock(Action action) + { + bool locked = _stream?.AcquireLock() ?? false; + try + { + action(); + } + finally + { + if (locked) + { + _stream!.ReleaseLock(); + } + } + } + /// <summary> /// Sets and <i>opens</i> the file where the log output will go. The specified file must be writable. /// </summary> @@ -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 a15e8f97..1339bb61 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 { + /// <summary>A base rename that failed, kept whole so its parts cannot drift apart.</summary> + /// <param name="From">The file that could not be moved.</param> + /// <param name="To">Where it was heading.</param> + /// <param name="WasBackupCountReverted"> + /// Whether the caller undid a <see cref="CurrentSizeRollBackups"/> increment, which a successful + /// retry has to put back. The time roll does not touch the counter, the size roll does. + /// </param> + /// <param name="RetryAtCount">The size the file must reach before the rename is attempted again.</param> + private sealed record PendingRename(string From, string To, bool WasBackupCountReverted, long RetryAtCount = 0); + /// <summary> /// Style of rolling to use /// </summary> @@ -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) /// </remarks> 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) /// </remarks> 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."); + } + } + + /// <summary>Remembers the base rename to retry, without touching the archive again.</summary> + private void RecordFailedBaseRename(string fromFile, string toFile, bool wasBackupCountReverted) + => _pendingRename = new(fromFile, toFile, wasBackupCountReverted); + + /// <summary> + /// Schedules the next attempt at the failed base rename, one <see cref="MaxFileSize"/> of growth + /// away: the cadence a working roll would have had. + /// </summary> + 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 }; + } + } + + /// <summary> + /// 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 <see cref="RollFile"/> deletes it, which is what that call has always done. + /// </summary> + 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(); + } + + /// <summary>Whether a rename failed and left the file, so it must be appended to.</summary> + private bool ShouldAppendAfterFailedRoll() + => _pendingRename is not null && FileExists(_pendingRename.From); + + /// <summary>Renames as <see cref="RollFile"/> does, reporting whether it worked.</summary> + private bool TryRollFile(string fromFile, string toFile) + { + int failuresBefore = _rollFailures; + RollFile(fromFile, toFile); + return _rollFailures == failuresBefore; } /// <summary> @@ -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 /// </summary> private bool _rollDate = true; + /// <summary> + /// The base rename waiting to be retried, or null when none is. A + /// <see cref="RollOverRenameFiles"/> override that renames itself bypasses it. + /// </summary> + private PendingRename? _pendingRename; + + /// <summary>How many renames have failed, so one call can be told apart.</summary> + private int _rollFailures; + /// <summary> /// Cache flag set if we are rolling by size. /// </summary>
