From 8879deb055de62613385fcc65498d025c8a6c29f Mon Sep 17 00:00:00 2001 From: Vitalii Fedorchenko Date: Mon, 25 Sep 2023 12:43:42 +0300 Subject: [PATCH] App deadlock on FileLoggerProvider.WriteEntry #57 --- src/NReco.Logging.File/FileLoggerProvider.cs | 73 +++++++++++++------ test/NReco.Logging.Tests/FileProviderTests.cs | 58 +++++++++++++-- 2 files changed, 102 insertions(+), 29 deletions(-) diff --git a/src/NReco.Logging.File/FileLoggerProvider.cs b/src/NReco.Logging.File/FileLoggerProvider.cs index 99e8890..2984f02 100644 --- a/src/NReco.Logging.File/FileLoggerProvider.cs +++ b/src/NReco.Logging.File/FileLoggerProvider.cs @@ -127,8 +127,35 @@ internal void WriteEntry(string message) { // do nothing } private void ProcessQueue() { + var writeMessageFailed = false; foreach (var message in entryQueue.GetConsumingEnumerable()) { - fWriter.WriteMessage(message, entryQueue.Count==0); + try { + if (!writeMessageFailed) + fWriter.WriteMessage(message, entryQueue.Count == 0); + } catch (Exception ex) { + // something goes wrong. App's code can handle it if 'HandleFileError' is provided + var stopLogging = true; + if (HandleFileError != null) { + var fileErr = new FileError(LogFileName, ex); + try { + HandleFileError(fileErr); + if (fileErr.NewLogFileName != null) { + fWriter.UseNewLogFile(fileErr.NewLogFileName); + // write failed message to a new log file + fWriter.WriteMessage(message, entryQueue.Count == 0); + stopLogging = false; + } + } catch { + // exception is possible in HandleFileError or if proposed file name cannot be used + // let's ignore it in that case -> file logger will stop processing log messages + } + } + if (stopLogging) { + // Stop processing log messages since they cannot be written to a log file + entryQueue.CompleteAdding(); + writeMessageFailed = true; + } + } } } @@ -183,39 +210,41 @@ void DetermineLastFileLogName() { } } - void OpenFile(bool append) { + void createLogFileStream(bool append) { + var fileInfo = new FileInfo(LogFileName); + // Directory.Create will check if the directory already exists, + // so there is no need for a "manual" check first. + fileInfo.Directory.Create(); + LogFileStream = new FileStream(LogFileName, FileMode.OpenOrCreate, FileAccess.Write); + if (append) { + LogFileStream.Seek(0, SeekOrigin.End); + } else { + LogFileStream.SetLength(0); // clear the file + } + LogFileWriter = new StreamWriter(LogFileStream); + } + + internal void UseNewLogFile(string newLogFileName) { + FileLogPrv.LogFileName = newLogFileName; + DetermineLastFileLogName(); // preserve all existing logic related to 'FormatLogFileName' and rolling files + createLogFileStream(FileLogPrv.Append); // if file error occurs here it is not handled by 'HandleFileError' recursively + } + + void OpenFile(bool append) { try { - createLogFileStream(); + createLogFileStream(append); } catch (Exception ex) { if (FileLogPrv.HandleFileError!=null) { var fileErr = new FileError(LogFileName, ex); FileLogPrv.HandleFileError(fileErr); if (fileErr.NewLogFileName!=null) { - FileLogPrv.LogFileName = fileErr.NewLogFileName; - DetermineLastFileLogName(); // preserve all existing logic related to 'FormatLogFileName' and rolling files - createLogFileStream(); // if error occurs it is not handled recursively + UseNewLogFile(fileErr.NewLogFileName); } } else { throw; // do not handle by default to preserve backward compatibility } } - - LogFileWriter = new StreamWriter(LogFileStream); - - void createLogFileStream() { - var fileInfo = new FileInfo(LogFileName); - // Directory.Create will check if the directory already exists, - // so there is no need for a "manual" check first. - fileInfo.Directory.Create(); - - LogFileStream = new FileStream(LogFileName, FileMode.OpenOrCreate, FileAccess.Write); - if (append) { - LogFileStream.Seek(0, SeekOrigin.End); - } else { - LogFileStream.SetLength(0); // clear the file - } - } } diff --git a/test/NReco.Logging.Tests/FileProviderTests.cs b/test/NReco.Logging.Tests/FileProviderTests.cs index ae06489..005b34b 100644 --- a/test/NReco.Logging.Tests/FileProviderTests.cs +++ b/test/NReco.Logging.Tests/FileProviderTests.cs @@ -288,14 +288,14 @@ public void FileOpenErrorHandling() { toDispose.Add(factory); factory.AddProvider(new FileLoggerProvider(logFileName, new FileLoggerOptions() { })); var logger = factory.CreateLogger("TEST"); - writeSomethingToLogger(logger); + writeSomethingToLogger(logger, 15); Assert.Throws(() => { // now try to use currently used file in another logger var factory2 = new LoggerFactory(); factory2.AddProvider(new FileLoggerProvider(logFileName, new FileLoggerOptions() { })); var logger2 = factory2.CreateLogger("TEST"); - writeSomethingToLogger(logger2); + writeSomethingToLogger(logger2, 15); }); var errorHandled = false; @@ -309,7 +309,7 @@ public void FileOpenErrorHandling() { } })); var logger2 = factory2.CreateLogger("TEST"); - writeSomethingToLogger(logger2); + writeSomethingToLogger(logger2, 15); Assert.True(errorHandled); factory2.Dispose(); // ensure that alt file name was used @@ -321,10 +321,54 @@ public void FileOpenErrorHandling() { CleanupTempDir(tmpDir, toDispose); } - void writeSomethingToLogger(ILogger log) { - for (int i = 0; i < 15; i++) { - log.LogInformation("Line" + (i + 1).ToString()); - } + } + + void writeSomethingToLogger(ILogger log, int msgCount) { + for (int i = 0; i < msgCount; i++) { + log.LogInformation("Line" + (i + 1).ToString()); + } + } + + [Theory] + [InlineData(false)] + [InlineData(true)] + public void FileWriteErrorHandling(bool useNewLogFile) { + var tmpDir = Path.Combine( Path.GetTempPath(), Guid.NewGuid().ToString()); + var logFileName = Path.Combine(tmpDir, "testfile.log"); + var fallbackLogFileName = Path.Combine(tmpDir, "fallbackfile.log"); + + var factory = new LoggerFactory(); + var fileLoggerOpts = new FileLoggerOptions() { }; + if (useNewLogFile) { + fileLoggerOpts.HandleFileError = (fileErr) => { + fileErr.UseNewLogFileName(fallbackLogFileName); + }; + } + var fileLogPrv = new FileLoggerProvider(logFileName, fileLoggerOpts); + factory.AddProvider(fileLogPrv); + var logger = factory.CreateLogger("TEST"); + writeSomethingToLogger(logger, 1); + + + var logFileWr = fileLogPrv.GetType() + .GetField("fWriter", System.Reflection.BindingFlags.Instance | System.Reflection.BindingFlags.NonPublic) + .GetValue(fileLogPrv); + // close file handler, this will cause an exception inside FileLoggerProvider.ProcessQueue + var logFileStream = (Stream)logFileWr.GetType() + .GetField("LogFileStream", System.Reflection.BindingFlags.Instance | System.Reflection.BindingFlags.NonPublic) + .GetValue(logFileWr); + logFileStream.Close(); + + var t = Task.Run(() => { + writeSomethingToLogger(logger, 2000); + }); + Assert.True(t.Wait(1000), "Logger queue blocks app's log calls."); + + factory.Dispose(); + + if (useNewLogFile) { + // ensure that it is not empty and was used + Assert.True( new System.IO.FileInfo(fallbackLogFileName).Length > 0, "Alternative log file name was not used."); } }