Skip to content

Commit

Permalink
Merge pull request #1872 from NLog/filetarget-more-logging
Browse files Browse the repository at this point in the history 
FileTarget: more internal logging
  • Loading branch information
@304NotModified
304NotModified committed Oct 6, 2017
2 parents 585c725 + 5ff3eb9 commit b4a0619
Show file tree
Hide file tree
Showing 3 changed files with 37 additions and 3 deletions.
3 changes: 2 additions & 1 deletion src/NLog/Targets/FileArchiveModes/FileArchiveModeDateAndSequence.cs
View file
Expand Up @@ -35,6 +35,7 @@
using System.Collections.Generic;
using System.Globalization;
using System.IO;
using NLog.Common;

namespace NLog.Targets.FileArchiveModes
{
Expand Down Expand Up @@ -141,7 +142,7 @@ private static bool TryParseDateAndSequence(string archiveFileNameWithoutPath, s
{
return false;
}

InternalLogger.Trace("FileTarget: parsed date '{0}' from file-template '{1}'", datePart, fileTemplate?.Template);
return true;
}
}
Expand Down
2 changes: 2 additions & 0 deletions src/NLog/Targets/FileArchiveModes/FileArchiveModeDynamicSequence.cs
View file
Expand Up @@ -36,6 +36,7 @@
using System.Globalization;
using System.IO;
using System.Text;
using NLog.Common;
using NLog.Internal;

namespace NLog.Targets.FileArchiveModes
Expand Down Expand Up @@ -166,6 +167,7 @@ protected override string GenerateFileNameMask(string archiveFilePath, FileNameT
protected override DateAndSequenceArchive GenerateArchiveFileInfo(FileInfo archiveFile, FileNameTemplate fileTemplate)
{
int sequenceNumber = ExtractArchiveNumberFromFileName(archiveFile.FullName);
InternalLogger.Trace("FileTarget: extracted sequenceNumber: {0} from file '{1}'", sequenceNumber, archiveFile.FullName);
var creationTimeUtc = FileCharacteristicsHelper.ValidateFileCreationTime(archiveFile, (f) => f.GetCreationTimeUtc(), (f) => f.GetLastWriteTimeUtc()).Value;
return new DateAndSequenceArchive(archiveFile.FullName, creationTimeUtc, string.Empty, sequenceNumber > 0 ? sequenceNumber : 0);
}
Expand Down
35 changes: 33 additions & 2 deletions src/NLog/Targets/FileTarget.cs
View file
Expand Up @@ -784,6 +784,12 @@ public void CleanupInitializedFiles()
/// </remarks>
public void CleanupInitializedFiles(DateTime cleanupThreshold)
{

if (InternalLogger.IsTraceEnabled)
{
InternalLogger.Trace("FileTarget: Cleanup Initialized Files with cleanupThreshold {0}", cleanupThreshold);
}

List<string> filesToFinalize = null;

// Select the files require to be finalized.
Expand All @@ -807,6 +813,8 @@ public void CleanupInitializedFiles(DateTime cleanupThreshold)
this.FinalizeFile(fileName);
}
}

InternalLogger.Trace("FileTarget: CleanupInitializedFiles Done");
}

/// <summary>
Expand All @@ -821,11 +829,14 @@ protected override void FlushAsync(AsyncContinuation asyncContinuation)
{
try
{
InternalLogger.Trace("FileTarget: FlushAsync");
fileAppenderCache.FlushAppenders();
asyncContinuation(null);
InternalLogger.Trace("FileTarget: FlushAsync Done");
}
catch (Exception exception)
{
InternalLogger.Warn(exception, "exception in FlushAsync");
if (exception.MustBeRethrown())
{
throw;
Expand Down Expand Up @@ -903,11 +914,16 @@ protected override void InitializeTarget()
base.InitializeTarget();

this.appenderFactory = GetFileAppenderFactory();
if (InternalLogger.IsTraceEnabled)
{
InternalLogger.Trace("Using appenderFactory: {0}", appenderFactory.GetType());
}

this.fileAppenderCache = new FileAppenderCache(this.OpenFileCacheSize, this.appenderFactory, this);

if ((this.OpenFileCacheSize > 0 || this.EnableFileDelete) && this.OpenFileCacheTimeout > 0)
{
InternalLogger.Trace("FileTarget: Start autoClosingTimer");
this.autoClosingTimer = new Timer(
(state) => this.AutoClosingTimerCallback(this, EventArgs.Empty),
null,
Expand All @@ -933,6 +949,7 @@ protected override void CloseTarget()
var currentTimer = this.autoClosingTimer;
if (currentTimer != null)
{
InternalLogger.Trace("FileTarget: Stop autoClosingTimer");
this.autoClosingTimer = null;
currentTimer.WaitForDispose(TimeSpan.Zero);
}
Expand Down Expand Up @@ -1288,6 +1305,7 @@ private void ArchiveFile(string fileName, string archiveFileName)
{
try
{
InternalLogger.Debug("Move file from '{0}' to '{1}'", fileName, archiveFileName);
File.Move(fileName, archiveFileName);
}
catch (System.IO.IOException ex)
Expand All @@ -1313,7 +1331,7 @@ private void ArchiveFile(string fileName, string archiveFileName)
if (!File.Exists(fileName) || File.Exists(archiveFileName))
throw;

InternalLogger.Info("Archiving retrying move of {0} to {1}.", fileName, archiveFileName);
InternalLogger.Debug("Archiving retrying move of {0} to {1}.", fileName, archiveFileName);
File.Move(fileName, archiveFileName);
}
}
Expand Down Expand Up @@ -1350,6 +1368,7 @@ private static void DeleteAndWaitForFileDelete(string fileName)
{
try
{
InternalLogger.Trace("FileTarget: waiting for file delete of '{0}' for 12 sec", fileName);
var originalFileCreationTime = (new FileInfo(fileName)).CreationTime;
if (DeleteOldArchiveFile(fileName) && File.Exists(fileName))
{
Expand Down Expand Up @@ -1465,7 +1484,7 @@ private bool PreviousLogOverlappedPeriod(LogEventInfo logEvent, DateTime lastWri
string periodAfterPreviousLogEventTimeString = periodAfterPreviousLogEventTime.ToString(formatString, CultureInfo.InvariantCulture);
return lastWriteTimeString == periodAfterPreviousLogEventTimeString;
}

/// <summary>
/// Calculate the DateTime of the requested day of the week.
/// </summary>
Expand All @@ -1492,6 +1511,7 @@ public static DateTime CalculateNextWeekday(DateTime previousLogEventTimestamp,
/// <param name="initializedNewFile">File has just been opened.</param>
private void DoAutoArchive(string fileName, LogEventInfo eventInfo, bool initializedNewFile)
{
InternalLogger.Debug("FileTarget: do archive file '{0}'", fileName);
var fileInfo = new FileInfo(fileName);
if (!fileInfo.Exists)
{
Expand All @@ -1508,12 +1528,14 @@ private void DoAutoArchive(string fileName, LogEventInfo eventInfo, bool initial
InternalLogger.Warn("Skip auto archive because archiveFilePattern is NULL");
return;
}
InternalLogger.Trace("FileTarget: archive pattern '{0}'", archiveFilePattern);

var fileArchiveStyle = GetFileArchiveHelper(archiveFilePattern);
var existingArchiveFiles = fileArchiveStyle.GetExistingArchiveFiles(archiveFilePattern);

if (this.MaxArchiveFiles == 1)
{
InternalLogger.Trace("FileTarget: MaxArchiveFiles = 1");
// Perform archive cleanup before generating the next filename,
// as next archive-filename can be affected by existing files.
for (int i = existingArchiveFiles.Count - 1; i >= 0; i--)
Expand Down Expand Up @@ -1567,7 +1589,9 @@ private void DoAutoArchive(string fileName, LogEventInfo eventInfo, bool initial

var cleanupArchiveFiles = fileArchiveStyle.CheckArchiveCleanup(archiveFilePattern, existingArchiveFiles, this.MaxArchiveFiles);
foreach (var oldArchiveFile in cleanupArchiveFiles)
{
DeleteOldArchiveFile(oldArchiveFile.FileName);
}

ArchiveFile(fileInfo.FullName, archiveFileName.FileName);
}
Expand Down Expand Up @@ -1617,8 +1641,10 @@ private bool TryArchiveFile(string fileName, LogEventInfo ev, int upcomingWriteS
try
{
archiveFile = this.GetArchiveFileName(fileName, ev, upcomingWriteSize);
InternalLogger.Trace("FileTarget: init archiving file '{0}'", archiveFile);
if (!string.IsNullOrEmpty(archiveFile))
{
InternalLogger.Trace("FileTarget: invalidate for file '{0}'", archiveFile);
#if SupportsMutex
// Acquire the mutex from the file-appender, before closing the file-apppender (remember not to close the Mutex)
archiveMutex = this.fileAppenderCache.GetArchiveMutex(fileName);
Expand All @@ -1639,6 +1665,7 @@ private bool TryArchiveFile(string fileName, LogEventInfo ev, int upcomingWriteS
else
{
#if !SILVERLIGHT && !__IOS__ && !__ANDROID__
InternalLogger.Trace("FileTarget: invalidate invalid files");
this.fileAppenderCache.InvalidateAppendersForInvalidFiles();
#endif
}
Expand Down Expand Up @@ -1881,6 +1908,7 @@ private void AutoClosingTimerCallback(object sender, EventArgs state)
}

DateTime expireTime = this.OpenFileCacheTimeout > 0 ? DateTime.UtcNow.AddSeconds(-this.OpenFileCacheTimeout) : DateTime.MinValue;
InternalLogger.Trace("FileTarget: Stop CloseAppenders");
this.fileAppenderCache.CloseAppenders(expireTime);
}
}
Expand Down Expand Up @@ -1977,6 +2005,7 @@ private bool InitializeFile(string fileName, LogEventInfo logEvent, bool justDat
/// <param name="isArchiving">Indicates if the file is being finalized for archiving.</param>
private void FinalizeFile(string fileName, bool isArchiving = false)
{
InternalLogger.Trace("FileTarget: FinalizeFile '{0}, isArchiving: {1}'",fileName, isArchiving);
if ((isArchiving) || (!this.WriteFooterOnArchivingOnly))
WriteFooter(fileName);

Expand Down Expand Up @@ -2009,6 +2038,7 @@ private void WriteFooter(string fileName)
/// <param name="logEvent">Log event that the <see cref="FileTarget"/> instance is currently processing.</param>
private void ProcessOnStartup(string fileName, LogEventInfo logEvent)
{
InternalLogger.Debug("FileTarget: process file '{0}' on startup", fileName);
RefreshArchiveFilePatternToWatch(fileName, logEvent);

if (this.ArchiveOldFileOnStartup)
Expand Down Expand Up @@ -2107,6 +2137,7 @@ private void WriteHeader(BaseFileAppender appender)
// Write header only on empty files or if file info cannot be obtained.
if (length == null || length == 0)
{
InternalLogger.Trace("FileTarget: Write header");
ArraySegment<byte> headerBytes = this.GetLayoutBytes(Header);
if (headerBytes.Count > 0)
{
Expand Down

0 comments on commit b4a0619

Please sign in to comment.