-
-
Notifications
You must be signed in to change notification settings - Fork 333
file locking: keep the log on a failed roll, fix the mutex name #319
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Open
FreeAndNil
wants to merge
3
commits into
master
Choose a base branch
from
Feature/319-file-locking
base: master
Could not load branches
Branch not found: {{ refName }}
Loading
Could not load tags
Nothing to show
Loading
Are you sure you want to change the base?
Some commits from the old base branch may be removed from the timeline,
and old review comments may become outdated.
+1,023
−123
Open
Changes from all commits
Commits
Show all changes
3 commits
Select commit
Hold shift + click to select a range
File filter
Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
There are no files selected for viewing
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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> |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,14 @@ | ||
| <?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 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)</description> | ||
| </entry> |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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">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)</description> | ||
| </entry> |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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> |
222 changes: 222 additions & 0 deletions
222
src/log4net.Tests/Appender/FileAppenderMutexNameTest.cs
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -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; | ||
|
|
||
| /// <summary>The mutex name the file lock and the rolling lock derive from the log file path.</summary> | ||
| [TestFixture] | ||
| public sealed class FileAppenderMutexNameTest | ||
| { | ||
| /// <summary>Records what the appender had resolved by the time the locking model was activated.</summary> | ||
| 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); | ||
| } | ||
| } | ||
|
|
||
| /// <summary> | ||
| /// The model was activated before the path was resolved, so a relative and an absolute spelling | ||
| /// of one file never shared a mutex. | ||
| /// </summary> | ||
| [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); | ||
| } | ||
| } | ||
| } | ||
|
|
||
| /// <summary>A name past the Unix limit took the appender down before anything was logged.</summary> | ||
| [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")); | ||
| } | ||
|
|
||
| /// <summary>A name that fits is left alone, so no existing deployment's mutex changes.</summary> | ||
| [Test] | ||
| public void AShortPathKeepsTheNameEarlierVersionsComputed() | ||
| => Assert.That(MutexNameForPath("/var/log/app.log", "_rolling"), Is.EqualTo("_var_log_app.log_rolling")); | ||
|
|
||
| /// <summary>Under a limit, a long name is hashed below it and stays distinct.</summary> | ||
| [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(); | ||
| } | ||
|
|
||
| /// <summary>With no limit, which is Windows, the name is left as earlier versions computed it.</summary> | ||
| [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")); | ||
| } | ||
|
|
||
| /// <summary> | ||
| /// 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. | ||
| /// </summary> | ||
| [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])!; | ||
| } | ||
Oops, something went wrong.
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
very minor: if you'd like to keep stuff in the test, you're welcome to try PeanutButter.Utils' AutoTempFolder - a disposable which creates a folder in the system temp location and destroys it when disposed, and you can use it like:
I must admit that I have an aversion to storing state on a test fixture and keeping that state useful via setup/teardown methods - I've found that at worst it introduces shared state that someone forgets is shared, failing a test, and at best, it means that when I'm trying to figure out what a test actually does, I have to hop around the test fixture. Anyhoo, it's just a preference of mine.