From bd375a491e8477908b9085d71b6e309340a0e18d Mon Sep 17 00:00:00 2001 From: spatil Date: Fri, 18 Aug 2017 14:16:30 +0530 Subject: [PATCH 1/2] https://issues.apache.org/jira/browse/LOG4NET-552 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit services installed on production box are separate process and are configured to write log into single log file. Due to this following two issues are happening, During write/append operation some processes are failing with error “Unable to acquire lock on file. The process cannot access the file because it is being used by another process”. This is because one process acquires lock (thread safe not process safe) for writing into log file and simultaneously another is trying to acquire lock and fails with above error and it just skips writing into log file. During rolling operation, rolled file gets created with less than 1KB size. Thus log entries are lost. Upon investigation we found that, rolling operation is protected by system wide Mutex lock. At the time of rolling, multiple processes may come at the same time for rolling and first process will roll the original file correctly and give a different name to rolled file and re-create blank original file. Now the second process which would have come for rolling will roll the blank original file and overwrite the rolled file created by first process and thus rolled file is losing the data. We locally have fixed above issues by changing latest log4net source code. We have kept locking model as “MinimalLock” which is current configuration in production. During append operation for acquirelock/releaselock we added system wide mutex so that each process will wait for other process to complete append operation. Thus it will not skip log from being written. During rolling operation we added check whether rolling is already happened by some other process. If yes then skip rolling operation. This will resolve rolling file overwrite by other process issue. --- src/Appender/FileAppender.cs | 48 ++++++++++++++++++----------- src/Appender/RollingFileAppender.cs | 12 ++++++-- 2 files changed, 40 insertions(+), 20 deletions(-) diff --git a/src/Appender/FileAppender.cs b/src/Appender/FileAppender.cs index f6bc151e..105929d1 100644 --- a/src/Appender/FileAppender.cs +++ b/src/Appender/FileAppender.cs @@ -620,22 +620,23 @@ public class MinimalLock : LockingModelBase private string m_filename; private bool m_append; private Stream m_stream = null; - - /// - /// Prepares to open the file when the first message is logged. - /// - /// The filename to use - /// Whether to append to the file, or overwrite - /// The encoding to use - /// - /// - /// Open the file specified and prepare for logging. - /// No writes will be made until is called. - /// Must be called before any calls to , - /// and . - /// - /// - public override void OpenFile(string filename, bool append, Encoding encoding) + private Mutex m_appendMutex = null; + private string m_appendMutexFriendlyName = "MUTEX_INTERPROCESS_COMMUNICATION_ACROSS_PROCESSES"; + /// + /// Prepares to open the file when the first message is logged. + /// + /// The filename to use + /// Whether to append to the file, or overwrite + /// The encoding to use + /// + /// + /// Open the file specified and prepare for logging. + /// No writes will be made until is called. + /// Must be called before any calls to , + /// and . + /// + /// + public override void OpenFile(string filename, bool append, Encoding encoding) { m_filename = filename; m_append = append; @@ -671,7 +672,15 @@ public override Stream AcquireLock() { try { - m_stream = CreateStream(m_filename, m_append, FileShare.Read); + if (m_appendMutex == null) + { + if (!Mutex.TryOpenExisting(m_appendMutexFriendlyName, out m_appendMutex)) + m_appendMutex = new Mutex(false, m_appendMutexFriendlyName); + } + + m_appendMutex.WaitOne(); + + m_stream = CreateStream(m_filename, m_append, FileShare.Read); m_append = true; } catch (Exception e1) @@ -695,7 +704,10 @@ public override void ReleaseLock() { CloseStream(m_stream); m_stream = null; - } + + if (m_appendMutex != null) + m_appendMutex.ReleaseMutex(); + } /// /// Initializes all resources used by this locking model. diff --git a/src/Appender/RollingFileAppender.cs b/src/Appender/RollingFileAppender.cs index 9c63f696..77ac638c 100644 --- a/src/Appender/RollingFileAppender.cs +++ b/src/Appender/RollingFileAppender.cs @@ -629,8 +629,16 @@ virtual protected void AdjustFileBeforeAppend() m_now = n; m_nextCheck = NextCheckDate(m_now, m_rollPoint); - RollOverTime(true); - } + if (!FileExists(m_scheduledFilename)) + { + RollOverTime(true); + } + else + { + //As we are skiping rollOver, we need to pupulate new scheduled name + m_scheduledFilename = CombinePath(File, m_now.ToString(m_datePattern, System.Globalization.DateTimeFormatInfo.InvariantInfo)); + } + } } if (m_rollSize) From c77a38322a12c42c695f1f97eadfbff1e30f219c Mon Sep 17 00:00:00 2001 From: spatil Date: Sat, 19 Aug 2017 15:44:31 +0530 Subject: [PATCH 2/2] Implemented review comments given under Pull Request https://github.com/apache/logging-log4net/pull/15 Below was question asked in above PR, Question: Would the patch also work without the mutex but only the fix in the RollingFileAppender class? Ans: Yes we have added new configuration By Default mutex won't be applied with minimal lock unless above config key is set to true. --- src/Appender/FileAppender.cs | 257 ++++++++++++++++------------ src/Appender/RollingFileAppender.cs | 34 ++-- 2 files changed, 166 insertions(+), 125 deletions(-) diff --git a/src/Appender/FileAppender.cs b/src/Appender/FileAppender.cs index 105929d1..1e0fa022 100644 --- a/src/Appender/FileAppender.cs +++ b/src/Appender/FileAppender.cs @@ -371,21 +371,22 @@ public abstract class LockingModelBase { private FileAppender m_appender = null; - /// - /// Open the output file - /// - /// The filename to use - /// Whether to append to the file, or overwrite - /// The encoding to use - /// - /// - /// Open the file specified and prepare for logging. - /// No writes will be made until is called. - /// Must be called before any calls to , - /// and . - /// - /// - public abstract void OpenFile(string filename, bool append, Encoding encoding); + /// + /// Open the output file + /// + /// The filename to use + /// Whether to append to the file, or overwrite + /// The encoding to use + /// Whether to protect append operation in Minimal lock with Mutex + /// + /// + /// Open the file specified and prepare for logging. + /// No writes will be made until is called. + /// Must be called before any calls to , + /// and . + /// + /// + public abstract void OpenFile(string filename, bool append, Encoding encoding, bool useMutexWithMinimalLock = false); /// /// Close the file @@ -456,23 +457,23 @@ public FileAppender CurrentAppender set { m_appender = value; } } - /// - /// Helper method that creates a FileStream under CurrentAppender's SecurityContext. - /// - /// - /// - /// Typically called during OpenFile or AcquireLock. - /// - /// - /// If the directory portion of the does not exist, it is created - /// via Directory.CreateDirecctory. - /// - /// - /// - /// - /// - /// - protected Stream CreateStream(string filename, bool append, FileShare fileShare) + /// + /// Helper method that creates a FileStream under CurrentAppender's SecurityContext. + /// + /// + /// + /// Typically called during OpenFile or AcquireLock. + /// + /// + /// If the directory portion of the does not exist, it is created + /// via Directory.CreateDirecctory. + /// + /// + /// + /// + /// + /// + protected Stream CreateStream(string filename, bool append, FileShare fileShare) { using (CurrentAppender.SecurityContext.Impersonate(this)) { @@ -520,21 +521,22 @@ public class ExclusiveLock : LockingModelBase { private Stream m_stream = null; - /// - /// Open the file specified and prepare for logging. - /// - /// The filename to use - /// Whether to append to the file, or overwrite - /// The encoding to use - /// - /// - /// Open the file specified and prepare for logging. - /// No writes will be made until is called. - /// Must be called before any calls to , - /// and . - /// - /// - public override void OpenFile(string filename, bool append, Encoding encoding) + /// + /// Open the file specified and prepare for logging. + /// + /// The filename to use + /// Whether to append to the file, or overwrite + /// The encoding to use + /// Whether to protect append operation in Minimal lock with Mutex + /// + /// + /// Open the file specified and prepare for logging. + /// No writes will be made until is called. + /// Must be called before any calls to , + /// and . + /// + /// + public override void OpenFile(string filename, bool append, Encoding encoding, bool useMutexWithMinimalLock = false) { try { @@ -621,13 +623,16 @@ public class MinimalLock : LockingModelBase private bool m_append; private Stream m_stream = null; private Mutex m_appendMutex = null; - private string m_appendMutexFriendlyName = "MUTEX_INTERPROCESS_COMMUNICATION_ACROSS_PROCESSES"; + private string m_appendMutexFriendlyName = "LOG4NET_MUTEX_ON_MINIMALLOCK_TO_PROTECT_APPEND_OPERATION"; + private bool m_useMutexWithMinimalLock = false; + /// /// Prepares to open the file when the first message is logged. /// /// The filename to use /// Whether to append to the file, or overwrite /// The encoding to use + /// Whether to protect append operation in Minimal lock with Mutex /// /// /// Open the file specified and prepare for logging. @@ -636,11 +641,13 @@ public class MinimalLock : LockingModelBase /// and . /// /// - public override void OpenFile(string filename, bool append, Encoding encoding) + public override void OpenFile(string filename, bool append, Encoding encoding, bool useMutexWithMinimalLock = false) { m_filename = filename; m_append = append; - } + m_useMutexWithMinimalLock = useMutexWithMinimalLock; + + } /// /// Close the file @@ -672,14 +679,19 @@ public override Stream AcquireLock() { try { - if (m_appendMutex == null) + if (m_useMutexWithMinimalLock) { - if (!Mutex.TryOpenExisting(m_appendMutexFriendlyName, out m_appendMutex)) - m_appendMutex = new Mutex(false, m_appendMutexFriendlyName); + if (m_appendMutex == null) + { + if (!Mutex.TryOpenExisting(m_appendMutexFriendlyName, out m_appendMutex)) + { + m_appendMutex = new Mutex(false, m_appendMutexFriendlyName); + } + } + + m_appendMutex.WaitOne(); } - m_appendMutex.WaitOne(); - m_stream = CreateStream(m_filename, m_append, FileShare.Read); m_append = true; } @@ -705,8 +717,13 @@ public override void ReleaseLock() CloseStream(m_stream); m_stream = null; - if (m_appendMutex != null) - m_appendMutex.ReleaseMutex(); + if (m_useMutexWithMinimalLock) + { + if (m_appendMutex != null) + { + m_appendMutex.ReleaseMutex(); + } + } } /// @@ -738,24 +755,25 @@ public class InterProcessLock : LockingModelBase private Stream m_stream = null; private int m_recursiveWatch = 0; - /// - /// Open the file specified and prepare for logging. - /// - /// The filename to use - /// Whether to append to the file, or overwrite - /// The encoding to use - /// - /// - /// Open the file specified and prepare for logging. - /// No writes will be made until is called. - /// Must be called before any calls to , - /// - and . - /// - /// + /// + /// Open the file specified and prepare for logging. + /// + /// The filename to use + /// Whether to append to the file, or overwrite + /// The encoding to use + /// Whether to protect append operation in Minimal lock with Mutex + /// + /// + /// Open the file specified and prepare for logging. + /// No writes will be made until is called. + /// Must be called before any calls to , + /// - and . + /// + /// #if NET_4_0 || MONO_4_0 || NETSTANDARD1_3 - [System.Security.SecuritySafeCritical] + [System.Security.SecuritySafeCritical] #endif - public override void OpenFile(string filename, bool append, Encoding encoding) + public override void OpenFile(string filename, bool append, Encoding encoding, bool useMutexWithMinimalLock = false) { try { @@ -1070,30 +1088,48 @@ public FileAppender.LockingModelBase LockingModel set { m_lockingModel = value; } } - #endregion Public Instance Properties - - #region Override implementation of AppenderSkeleton - - /// - /// Activate the options on the file appender. - /// - /// - /// - /// This is part of the delayed object - /// activation scheme. The method must - /// be called on this object after the configuration properties have - /// been set. Until is called this - /// object is in an undefined state and must not be used. - /// - /// - /// If any of the configuration properties are modified then - /// must be called again. - /// - /// - /// This will cause the file to be opened. - /// - /// - override public void ActivateOptions() + /// + /// Gets or sets a value indicating whether to protect append operation in Minimal lock with Mutex. + /// + /// + /// true if append operation with Minimal lock should be protected from multiple processes appending into same file, otherwise false + /// + /// + /// + /// By default append operation in Minimal lock won't be protected + /// from multiple processes appending into same file. + /// + /// + public bool UseMutexWithMinimalLock + { + get { return m_useMutexWithMinimalLock; } + set { m_useMutexWithMinimalLock = value; } + } + + #endregion Public Instance Properties + + #region Override implementation of AppenderSkeleton + + /// + /// Activate the options on the file appender. + /// + /// + /// + /// This is part of the delayed object + /// activation scheme. The method must + /// be called on this object after the configuration properties have + /// been set. Until is called this + /// object is in an undefined state and must not be used. + /// + /// + /// If any of the configuration properties are modified then + /// must be called again. + /// + /// + /// This will cause the file to be opened. + /// + /// + override public void ActivateOptions() { base.ActivateOptions(); @@ -1383,7 +1419,7 @@ virtual protected void OpenFile(string fileName, bool append) m_appendToFile = append; LockingModel.CurrentAppender = this; - LockingModel.OpenFile(fileName, append, m_encoding); + LockingModel.OpenFile(fileName, append, m_encoding, m_useMutexWithMinimalLock); m_stream = new LockingStream(LockingModel); if (m_stream != null) @@ -1496,18 +1532,23 @@ protected static string ConvertToFullPath(string path) /// private FileAppender.LockingModelBase m_lockingModel = new FileAppender.ExclusiveLock(); - #endregion Private Instance Fields + /// + /// Value indicating whether to protect append operation in Minimal lock with Mutex. + /// + private bool m_useMutexWithMinimalLock = false; - #region Private Static Fields + #endregion Private Instance Fields - /// - /// The fully qualified type of the FileAppender class. - /// - /// - /// Used by the internal logger to record the Type of the - /// log message. - /// - private readonly static Type declaringType = typeof(FileAppender); + #region Private Static Fields + + /// + /// The fully qualified type of the FileAppender class. + /// + /// + /// Used by the internal logger to record the Type of the + /// log message. + /// + private readonly static Type declaringType = typeof(FileAppender); #endregion Private Static Fields } diff --git a/src/Appender/RollingFileAppender.cs b/src/Appender/RollingFileAppender.cs index 77ac638c..0b16daea 100644 --- a/src/Appender/RollingFileAppender.cs +++ b/src/Appender/RollingFileAppender.cs @@ -536,18 +536,18 @@ public bool StaticLogFileName set { m_staticLogFileName = value; } } - #endregion Public Instance Properties + #endregion Public Instance Properties - #region Private Static Fields + #region Private Static Fields - /// - /// The fully qualified type of the RollingFileAppender class. - /// - /// - /// Used by the internal logger to record the Type of the - /// log message. - /// - private readonly static Type declaringType = typeof(RollingFileAppender); + /// + /// The fully qualified type of the RollingFileAppender class. + /// + /// + /// Used by the internal logger to record the Type of the + /// log message. + /// + private readonly static Type declaringType = typeof(RollingFileAppender); #endregion Private Static Fields @@ -626,8 +626,8 @@ virtual protected void AdjustFileBeforeAppend() DateTime n = m_dateTime.Now; if (n >= m_nextCheck) { - m_now = n; - m_nextCheck = NextCheckDate(m_now, m_rollPoint); + m_now = n; + m_nextCheck = NextCheckDate(m_now, m_rollPoint); if (!FileExists(m_scheduledFilename)) { @@ -639,7 +639,7 @@ virtual protected void AdjustFileBeforeAppend() m_scheduledFilename = CombinePath(File, m_now.ToString(m_datePattern, System.Globalization.DateTimeFormatInfo.InvariantInfo)); } } - } + } if (m_rollSize) { @@ -1687,10 +1687,10 @@ protected DateTime NextCheckDate(DateTime currentDateTime, RollPoint rollPoint) /// private bool m_staticLogFileName = true; - /// - /// Value indicating whether to preserve the file name extension when rolling. - /// - private bool m_preserveLogFileNameExtension = false; + /// + /// Value indicating whether to preserve the file name extension when rolling. + /// + private bool m_preserveLogFileNameExtension = false; ///