App deadlock on FileLoggerProvider.WriteEntry #57

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
-					}
-				}
 			}
 
 

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<IOException>(() => {
 					// 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.");
 			}
 		}