Skip to content

Commit

Permalink
FileTarget - Skip FileSystemWatcher unless ConcurrentWrites=true
Browse files Browse the repository at this point in the history
  • Loading branch information
@snakefoot
snakefoot committed Apr 20, 2019
1 parent 2fffff4 commit 324d486
Show file tree
Hide file tree
Showing 7 changed files with 126 additions and 45 deletions.
2 changes: 2 additions & 0 deletions src/NLog/Config/LoggingRule.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -165,6 +165,7 @@ public string LoggerNamePattern
/// <summary>
/// Gets the collection of log levels enabled by this rule.
/// </summary>
[NLogConfigurationIgnoreProperty]
public ReadOnlyCollection<LogLevel> Levels
{
get
Expand All @@ -182,6 +183,7 @@ public ReadOnlyCollection<LogLevel> Levels
return levels.AsReadOnly();
}
}

/// <summary>
/// Default action if all filters won't match
/// </summary>
Expand Down
8 changes: 4 additions & 4 deletions src/NLog/Config/XmlLoggingConfiguration.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -293,7 +293,7 @@ public override IEnumerable<string> FileNamesToWatch
public override LoggingConfiguration Reload()
{
if (!string.IsNullOrEmpty(_originalFileName))
return new XmlLoggingConfiguration(_originalFileName);
return new XmlLoggingConfiguration(_originalFileName, LogFactory);
else
return base.Reload();
}
Expand Down Expand Up @@ -459,7 +459,7 @@ private void ParseNLogElement(ILoggingConfigurationElement nlogElement, string f
nlogElement.AssertName("nlog");

bool autoReload = nlogElement.GetOptionalBooleanValue("autoReload", autoReloadDefault);
if (filePath != null)
if (!string.IsNullOrEmpty(filePath))
_fileMustAutoReloadLookup[GetFileLookupKey(filePath)] = autoReload;

try
Expand All @@ -483,8 +483,8 @@ protected override bool ParseNLogSection(ILoggingConfigurationElement configSect
if (configSection.MatchesName("include"))
{
string filePath = _currentFilePath.Peek();
bool autoLoad = filePath != null && _fileMustAutoReloadLookup[GetFileLookupKey(filePath)];
ParseIncludeElement(configSection, filePath != null ? Path.GetDirectoryName(filePath) : null, autoLoad);
bool autoLoad = !string.IsNullOrEmpty(filePath) && _fileMustAutoReloadLookup[GetFileLookupKey(filePath)];
ParseIncludeElement(configSection, !string.IsNullOrEmpty(filePath) ? Path.GetDirectoryName(filePath) : null, autoLoad);
return true;
}
else
Expand Down
2 changes: 1 addition & 1 deletion src/NLog/Internal/FileAppenders/BaseFileAppender.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -67,7 +67,7 @@ protected BaseFileAppender(string fileName, ICreateFileParameters createParamete
/// Gets the path of the file, including file extension.
/// </summary>
/// <value>The name of the file.</value>
public string FileName { get; private set; }
public string FileName { get; }

/// <summary>
/// Gets or sets the creation time for a file associated with the appender. The time returned is in Coordinated
Expand Down
53 changes: 42 additions & 11 deletions src/NLog/Internal/FileAppenders/FileAppenderCache.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -324,20 +324,17 @@ private BaseFileAppender CreateAppender(string fileName, int freeSpot)
/// </summary>
public void CloseAppenders(string reason)
{
if (_appenders != null)
for (int i = 0; i < _appenders.Length; ++i)
{
for (int i = 0; i < _appenders.Length; ++i)
var oldAppender = _appenders[i];
if (oldAppender == null)
{
var oldAppender = _appenders[i];
if (oldAppender == null)
{
break;
}

CloseAppender(oldAppender, reason, true);
_appenders[i] = null;
oldAppender.Dispose(); // Dispose of Archive Mutex
break;
}

CloseAppender(oldAppender, reason, true);
_appenders[i] = null;
oldAppender.Dispose(); // Dispose of Archive Mutex
}
}

Expand Down Expand Up @@ -387,6 +384,40 @@ public void CloseAppenders(DateTime expireTime)
}
}

/// <summary>
/// Checks if any of the active appenders has an unexpected state
/// </summary>
/// <remarks>
/// Must work without the protection of lock, because the checking can be "blocking" on network-drives
/// </remarks>
/// <returns>The filename of first appender detected as strange</returns>
public string CheckForStaleAppender()
{
for (int i = 0; i < _appenders.Length; ++i)
{
var appender = _appenders[i];
if (appender == null)
{
return null;
}

try
{
if (!File.Exists(appender.FileName))
{
return appender.FileName;
}
}
catch (Exception ex)
{
InternalLogger.Error(ex, "Failed to check stale file '{0}'.", appender.FileName);
return appender.FileName;
}
}

return null;
}

/// <summary>
/// Fluch all the allocated appenders.
/// </summary>
Expand Down
2 changes: 1 addition & 1 deletion src/NLog/Internal/MultiFileWatcher.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -131,7 +131,7 @@ internal void Watch(string fileName)
var directory = Path.GetDirectoryName(fileName);
if (!Directory.Exists(directory))
{
InternalLogger.Warn("Cannot watch {0} for changes as it doesn't exist", directory);
InternalLogger.Warn("Cannot watch file {0} for changes as directory {1} doesn't exist", fileName, directory);
return;
}

Expand Down
76 changes: 59 additions & 17 deletions src/NLog/Targets/FileTarget.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -440,7 +440,6 @@ public bool ConcurrentWrites
get
{
#if SupportsMutex

return _concurrentWrites ?? PlatformDetector.SupportsSharableMutex;
#else
return _concurrentWrites ?? false; // Better user experience for mobile platforms
Expand Down Expand Up @@ -740,11 +739,13 @@ private void RefreshArchiveFilePatternToWatch(string fileName, LogEventInfo logE
{
_fileAppenderCache.CheckCloseAppenders -= AutoCloseAppendersAfterArchive;

if (KeepFileOpen)
_fileAppenderCache.CheckCloseAppenders += AutoCloseAppendersAfterArchive;
bool mustWatchArchiving = IsArchivingEnabled && KeepFileOpen && ConcurrentWrites;
if (mustWatchArchiving || (EnableFileDelete && KeepFileOpen && !NetworkWrites && !ReplaceFileContentsOnEachWrite && !EnableMonitorForSimpleKeepFileOpen))
{
_fileAppenderCache.CheckCloseAppenders += AutoCloseAppendersAfterArchive; // Activates FileSystemWatcher
}

#if !SILVERLIGHT && !__IOS__ && !__ANDROID__ && !NETSTANDARD1_3
bool mustWatchArchiving = IsArchivingEnabled && ConcurrentWrites && KeepFileOpen;
if (mustWatchArchiving)
{
string fileNamePattern = GetArchiveFileNamePattern(fileName, logEvent);
Expand Down Expand Up @@ -901,6 +902,10 @@ private IFileAppenderFactory GetFileAppenderFactory()

private bool IsArchivingEnabled => ArchiveAboveSize != ArchiveAboveSizeDisabled || ArchiveEvery != FileArchivePeriod.None;

private bool IsSimpleKeepFileOpen => KeepFileOpen && !NetworkWrites && !ReplaceFileContentsOnEachWrite && !ConcurrentWrites;

private bool EnableMonitorForSimpleKeepFileOpen => EnableFileDelete && !PlatformDetector.IsWin32 && IsSimpleKeepFileOpen;

/// <summary>
/// Initializes file logging by creating data structures that
/// enable efficient multi-file logging.
Expand All @@ -917,16 +922,32 @@ protected override void InitializeTarget()

_fileAppenderCache = new FileAppenderCache(OpenFileCacheSize, appenderFactory, this);

if ((OpenFileCacheSize > 0 || EnableFileDelete) && (OpenFileCacheTimeout > 0 || OpenFileFlushTimeout > 0))
var autoClosingTimerInterval = GetAutoClosingTimerInterval();
if (autoClosingTimerInterval > TimeSpan.Zero)
{
int openFileAutoTimeoutSecs = (OpenFileCacheTimeout > 0 && OpenFileFlushTimeout > 0) ? Math.Min(OpenFileCacheTimeout, OpenFileFlushTimeout) : Math.Max(OpenFileCacheTimeout, OpenFileFlushTimeout);
InternalLogger.Trace("FileTarget(Name={0}): Start autoClosingTimer", Name);
_autoClosingTimer = new Timer(
(state) => AutoClosingTimerCallback(this, EventArgs.Empty),
null,
openFileAutoTimeoutSecs * 1000,
openFileAutoTimeoutSecs * 1000);
(int)autoClosingTimerInterval.TotalMilliseconds,
Timeout.Infinite);
}
}

private TimeSpan GetAutoClosingTimerInterval()
{
if ((OpenFileCacheSize > 0 || EnableFileDelete) && (OpenFileCacheTimeout > 0 || OpenFileFlushTimeout > 0 || EnableMonitorForSimpleKeepFileOpen))
{
int openFileAutoTimeoutSecs = (OpenFileCacheTimeout > 0 && OpenFileFlushTimeout > 0) ? Math.Min(OpenFileCacheTimeout, OpenFileFlushTimeout) : Math.Max(OpenFileCacheTimeout, OpenFileFlushTimeout);
if (EnableMonitorForSimpleKeepFileOpen && openFileAutoTimeoutSecs != 1)
{
openFileAutoTimeoutSecs = 2;
}

return TimeSpan.FromSeconds(openFileAutoTimeoutSecs);
}

return TimeSpan.Zero;
}

/// <summary>
Expand Down Expand Up @@ -1359,7 +1380,7 @@ private void ArchiveFileMove(string fileName, string archiveFileName)
}
catch (IOException ex)
{
if (KeepFileOpen && !ConcurrentWrites)
if (IsSimpleKeepFileOpen)
throw; // No need to retry, when only single process access

if (!EnableFileDelete && KeepFileOpen)
Expand Down Expand Up @@ -1503,7 +1524,7 @@ private string GetArchiveDateFormatString(string defaultFormat)
return previousLogEventTimestamp;
}

if (!AutoFlush && KeepFileOpen && !ConcurrentWrites && !NetworkWrites && previousLogEventTimestamp < lastWriteTimeSource)
if (!AutoFlush && IsSimpleKeepFileOpen && previousLogEventTimestamp < lastWriteTimeSource)
{
InternalLogger.Trace("FileTarget(Name={0}): Using previous LogEvent-TimeStamp {1}, because AutoFlush=false affects File-LastModified {2}", Name, previousLogEventTimestamp, lastWriteTimeSource);
return previousLogEventTimestamp;
Expand Down Expand Up @@ -1940,7 +1961,7 @@ private string GetArchiveFileNameBasedOnTime(string fileName, LogEventInfo logEv
}

// Linux FileSystems doesn't always have file-birth-time, so NLog tries to provide a little help
DateTime? fallbackTimeSourceLinux = (previousLogEventTimestamp != DateTime.MinValue && KeepFileOpen && !ConcurrentWrites && !NetworkWrites) ? previousLogEventTimestamp : (DateTime?)null;
DateTime? fallbackTimeSourceLinux = (previousLogEventTimestamp != DateTime.MinValue && IsSimpleKeepFileOpen) ? previousLogEventTimestamp : (DateTime?)null;
var creationTimeSource = _fileAppenderCache.GetFileCreationTimeSource(fileName, fallbackTimeSourceLinux);
if (creationTimeSource == null)
{
Expand All @@ -1951,7 +1972,7 @@ private string GetArchiveFileNameBasedOnTime(string fileName, LogEventInfo logEv
{
if (TruncateArchiveTime(previousLogEventTimestamp, FileArchivePeriod.Minute) < TruncateArchiveTime(creationTimeSource.Value, FileArchivePeriod.Minute) && PlatformDetector.IsUnix)
{
if (KeepFileOpen && !ConcurrentWrites && !NetworkWrites)
if (IsSimpleKeepFileOpen)
{
InternalLogger.Debug("FileTarget(Name={0}): Adjusted file creation time from {1} to {2}. Linux FileSystem probably don't support file birthtime.", Name, creationTimeSource, previousLogEventTimestamp);
creationTimeSource = previousLogEventTimestamp;
Expand Down Expand Up @@ -2053,21 +2074,36 @@ private void AutoCloseAppendersAfterArchive(object sender, EventArgs state)

private void AutoClosingTimerCallback(object sender, EventArgs state)
{
bool lockTaken = Monitor.TryEnter(SyncRoot, TimeSpan.FromSeconds(0.5));
if (!lockTaken)
return; // Timer will trigger again, no need for timers to queue up
bool lockTaken = false;

try
{
string staleFileAppender = null;
if (EnableMonitorForSimpleKeepFileOpen)
{
// Performing check outside the protection of the lock, because the checking can be "blocking" on network-drives
staleFileAppender = _fileAppenderCache.CheckForStaleAppender();
}

lockTaken = Monitor.TryEnter(SyncRoot, TimeSpan.FromSeconds(0.5));
if (!lockTaken)
return; // Timer will trigger again, no need for stealing thread from ThreadPool forever

if (!IsInitialized)
{
return;
}

if (staleFileAppender != null)
{
InternalLogger.Trace("FileTarget(Name={0}): Auto Close Detected Stale FileAppender", Name);
_fileAppenderCache.InvalidateAppender(staleFileAppender)?.Dispose();
}

if (OpenFileCacheTimeout > 0)
{
DateTime expireTime = DateTime.UtcNow.AddSeconds(-OpenFileCacheTimeout);
InternalLogger.Trace("FileTarget(Name={0}): Auto Close FileAppenders", Name);
InternalLogger.Trace("FileTarget(Name={0}): Auto Close Old FileAppenders", Name);
_fileAppenderCache.CloseAppenders(expireTime);
}

Expand All @@ -2087,7 +2123,13 @@ private void AutoClosingTimerCallback(object sender, EventArgs state)
}
finally
{
Monitor.Exit(SyncRoot);
if (lockTaken)
Monitor.Exit(SyncRoot);

// Manual timer reschedule to avoid too many timer-threads waiting on blocking locks or blocking file-operations
var autoClosingTimerInterval = GetAutoClosingTimerInterval();
if (_autoClosingTimer != null && autoClosingTimerInterval > TimeSpan.Zero)
_autoClosingTimer.Change((int)autoClosingTimerInterval.TotalMilliseconds, Timeout.Infinite);
}
}

Expand Down
28 changes: 17 additions & 11 deletions tests/NLog.UnitTests/Targets/FileTargetTests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -120,25 +120,31 @@ public void SimpleFileTest(bool concurrentWrites, bool keepFileOpen, bool networ
}
}

#if !MONO
[Theory]
#else
[Theory(Skip="Not supported on MONO on Travis, because of FileSystemWatcher not working")]
#endif
[MemberData(nameof(SimpleFileTest_TestParameters))]
public void SimpleFileDeleteTest(bool concurrentWrites, bool keepFileOpen, bool networkWrites, bool forceManaged, bool forceMutexConcurrentWrites, bool optimizeBufferReuse)
{
bool isSimpleKeepFileOpen = keepFileOpen && !networkWrites && !concurrentWrites && IsTravis();
if (IsTravis())
{
if (concurrentWrites && keepFileOpen && !networkWrites)
{
Console.WriteLine("[SKIP] Not supported on MONO on Travis, because of FileSystemWatcher not working");
return;
}
}

var logFile = Path.GetTempFileName();
var logFile2 = Path.Combine(Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString()), Path.GetFileName(logFile));

try
{
var fileTarget = WrapFileTarget(new FileTarget
{
FileName = SimpleLayout.Escape(logFile),
LineEnding = LineEndingMode.LF,
Layout = "${level} ${message}",
OpenFileCacheTimeout = 0,
OpenFileCacheTimeout = isSimpleKeepFileOpen ? 1 : 0,
EnableFileDelete = true,
ConcurrentWrites = concurrentWrites,
KeepFileOpen = keepFileOpen,
Expand All @@ -156,12 +162,12 @@ public void SimpleFileDeleteTest(bool concurrentWrites, bool keepFileOpen, bool

Directory.CreateDirectory(Path.GetDirectoryName(logFile2));
File.Move(logFile, logFile2);
if (keepFileOpen)
#if MONO
Thread.Sleep(500); // Allow AutoClose-Timer-Thread to react (FileWatcher depends on operating system, fallback to polling every 3 secs)
#else

if (isSimpleKeepFileOpen)
Thread.Sleep(1500); // Allow AutoClose-Timer-Thread to react
else if (keepFileOpen && !networkWrites)
Thread.Sleep(150); // Allow AutoClose-Timer-Thread to react (FileWatcher schedules timer after 50 msec)
#endif

logger.Info("bbb");

LogManager.Configuration = null;
Expand Down

0 comments on commit 324d486

Please sign in to comment.