common/UnitTests/Common/Logging/FileLoggerTests.cs

using System;
using System.Collections.Generic;
using System.IO;
using System.Linq;
using System.Reflection;
using System.Threading;
using System.Threading.Tasks;
using AMWD.Common.Logging;
using Microsoft.Extensions.Logging;
using Microsoft.VisualStudio.TestTools.UnitTesting;
using Moq;

namespace UnitTests.Common.Logging
{
	[TestClass]
	public class FileLoggerTests
	{
		private Mock<StreamWriter> streamWriterMock;

		private List<string> lines;

		[TestInitialize]
		public void Initialize()
		{
			lines = new List<string>();
		}

		[TestMethod]
		public void ShouldCreateInstance()
		{
			// arrange
			string path = Path.GetTempFileName();

			try
			{
				// act
				using var logger = new FileLogger(path);

				// assert
				Assert.IsNotNull(logger);
				Assert.IsTrue(File.Exists(path));

				Assert.AreEqual(path, logger.FileName);
				Assert.AreEqual(LogLevel.Trace, logger.MinLevel);
				Assert.IsNull(logger.Name);
				Assert.IsNull(logger.ParentLogger);
				Assert.IsNull(logger.TimestampFormat);
				Assert.IsNull(logger.ScopeProvider);
			}
			finally
			{
				File.Delete(path);
			}
		}

		[TestMethod]
		public void ShouldCreateInstanceAsNamedInstance()
		{
			// arrange
			string name = "NamedInstance";
			string path = Path.GetTempFileName();

			try
			{
				// act
				using var logger = new FileLogger(path, name);

				// assert
				Assert.IsNotNull(logger);
				Assert.IsTrue(File.Exists(path));

				Assert.AreEqual(path, logger.FileName);
				Assert.AreEqual(LogLevel.Trace, logger.MinLevel);
				Assert.AreEqual(name, logger.Name);

				Assert.IsNull(logger.ParentLogger);
				Assert.IsNull(logger.TimestampFormat);
				Assert.IsNull(logger.ScopeProvider);
			}
			finally
			{
				File.Delete(path);
			}
		}

		[TestMethod]
		[ExpectedException(typeof(ObjectDisposedException))]
		public void ShouldThrowDisposedOnIsEnabled()
		{
			// arrange
			var logger = GetFileLogger();

			// act
			logger.Dispose();
			logger.IsEnabled(LogLevel.Error);

			// assert - ObjectDisposedException
			Assert.Fail();
		}

		[TestMethod]
		[ExpectedException(typeof(ObjectDisposedException))]
		public void ShouldThrowDisposedOnLog()
		{
			// arrange
			var logger = GetFileLogger();

			// act
			logger.Dispose();
			logger.Log(LogLevel.None, "Some Message");

			// assert - ObjectDisposedException
			Assert.Fail();
		}

		[TestMethod]
		[ExpectedException(typeof(ObjectDisposedException))]
		public void ShouldThrowDisposedOnBeginScope()
		{
			// arrange
			var logger = GetFileLogger();

			// act
			logger.Dispose();
			logger.BeginScope("foo");

			// assert - ObjectDisposedException
			Assert.Fail();
		}

		[DataTestMethod]
		[DataRow(LogLevel.Trace, false)]
		[DataRow(LogLevel.Debug, false)]
		[DataRow(LogLevel.Information, false)]
		[DataRow(LogLevel.Warning, true)]
		[DataRow(LogLevel.Error, true)]
		[DataRow(LogLevel.Critical, true)]
		[DataRow(LogLevel.None, true)]
		public void ShouldReturnIsEnabled(LogLevel logLevel, bool expectedResult)
		{
			// arrange
			using var logger = GetFileLogger();
			logger.MinLevel = LogLevel.Warning;

			// act
			bool result = logger.IsEnabled(logLevel);

			// assert
			Assert.AreEqual(expectedResult, result);
		}

		[TestMethod]
		public void ShouldLogMessage()
		{
			// arrange
			using var logger = GetFileLogger();

			// act
			logger.Log(LogLevel.Information, "Test Message");
			SpinWait.SpinUntil(() => lines.Count == 1);

			// assert
			Assert.AreEqual("INFO | Test Message", lines.First());

			streamWriterMock.Verify(sw => sw.WriteLineAsync(It.IsAny<string>()), Times.Once);
			streamWriterMock.Verify(sw => sw.FlushAsync(), Times.Once);
			streamWriterMock.VerifyNoOtherCalls();
		}

		[TestMethod]
		public void ShouldLogAllLevels()
		{
			// arrange
			using var logger = GetFileLogger();

			// act
			foreach (LogLevel level in Enum.GetValues<LogLevel>())
				logger.Log(level, "Test Message");

			SpinWait.SpinUntil(() => lines.Count == 7);

			// assert
			streamWriterMock.Verify(sw => sw.WriteLineAsync("TRCE | Test Message"), Times.Once);
			streamWriterMock.Verify(sw => sw.WriteLineAsync("DBUG | Test Message"), Times.Once);
			streamWriterMock.Verify(sw => sw.WriteLineAsync("INFO | Test Message"), Times.Once);
			streamWriterMock.Verify(sw => sw.WriteLineAsync("WARN | Test Message"), Times.Once);
			streamWriterMock.Verify(sw => sw.WriteLineAsync("FAIL | Test Message"), Times.Once);
			streamWriterMock.Verify(sw => sw.WriteLineAsync("CRIT | Test Message"), Times.Once);
			streamWriterMock.Verify(sw => sw.WriteLineAsync("     | Test Message"), Times.Once);
			streamWriterMock.Verify(sw => sw.FlushAsync(), Times.AtLeastOnce);
			streamWriterMock.VerifyNoOtherCalls();
		}

		[TestMethod]
		public void ShouldLogOnlyAboveMinLevel()
		{
			// arrange
			using var logger = GetFileLogger();
			logger.MinLevel = LogLevel.Error;

			// act
			foreach (LogLevel level in Enum.GetValues<LogLevel>())
				logger.Log(level, "Test Message");

			SpinWait.SpinUntil(() => lines.Count == 3);

			// assert
			streamWriterMock.Verify(sw => sw.WriteLineAsync("FAIL | Test Message"), Times.Once);
			streamWriterMock.Verify(sw => sw.WriteLineAsync("CRIT | Test Message"), Times.Once);
			streamWriterMock.Verify(sw => sw.WriteLineAsync("     | Test Message"), Times.Once);
			streamWriterMock.Verify(sw => sw.FlushAsync(), Times.AtLeastOnce);
			streamWriterMock.VerifyNoOtherCalls();
		}

		[TestMethod]
		public void ShouldLogWithLocalTimestamp()
		{
			// arrange
			using var logger = GetFileLogger();
			logger.UseUtcTimestamp = false;
			logger.TimestampFormat = "yyyy-MM-dd HH:mm";

			// act
			logger.LogWarning("Some Warning");
			SpinWait.SpinUntil(() => lines.Count == 1);

			// assert

			streamWriterMock.Verify(sw => sw.WriteLineAsync($"{DateTime.Now:yyyy-MM-dd HH:mm} | WARN | Some Warning"), Times.Once);
			streamWriterMock.Verify(sw => sw.FlushAsync(), Times.Once);
			streamWriterMock.VerifyNoOtherCalls();
		}

		[TestMethod]
		public void ShouldLogWithUtcTimestamp()
		{
			// arrange
			using var logger = GetFileLogger();
			logger.UseUtcTimestamp = true;
			logger.TimestampFormat = "yyyy-MM-dd HH:mm";

			// act
			logger.LogWarning("Some Warning");
			SpinWait.SpinUntil(() => lines.Count == 1);

			// assert
			streamWriterMock.Verify(sw => sw.WriteLineAsync($"{DateTime.UtcNow:yyyy-MM-dd HH:mm} | WARN | Some Warning"), Times.Once);
			streamWriterMock.Verify(sw => sw.FlushAsync(), Times.Once);
			streamWriterMock.VerifyNoOtherCalls();
		}

		[TestMethod]
		public void ShouldUseParentLogger()
		{
			// arrange
			string file = Path.GetTempFileName();
			try
			{
				using var parent = GetFileLogger();
				parent.UseUtcTimestamp = false;
				parent.TimestampFormat = "yyyy-MM-dd HH:mm";

				using var logger = new FileLogger(file, "NamedInstance", parent);

				// act
				logger.LogWarning("Some Warning");
				SpinWait.SpinUntil(() => lines.Count == 1);

				// assert
				streamWriterMock.Verify(sw => sw.WriteLineAsync($"{DateTime.Now:yyyy-MM-dd HH:mm} | WARN | [NamedInstance] Some Warning"), Times.Once);
				streamWriterMock.Verify(sw => sw.FlushAsync(), Times.Once);
				streamWriterMock.VerifyNoOtherCalls();

				Assert.AreEqual(0, new FileInfo(file).Length);
			}
			finally
			{
				File.Delete(file);
			}
		}

		[TestMethod]
		public void ShouldUseScopeProvider()
		{
			// arrange
			var scopeProvider = new Mock<IExternalScopeProvider>();
			using var logger = GetFileLogger("NamedInstance", scopeProvider.Object);

			// act
			using (var scope = logger.BeginScope("scope"))
			{
				logger.LogError("Test");
				SpinWait.SpinUntil(() => lines.Count == 1);
			}

			// assert
			streamWriterMock.Verify(sw => sw.WriteLineAsync("FAIL | [NamedInstance] Test"), Times.Once);
			streamWriterMock.Verify(sw => sw.FlushAsync(), Times.Once);
			streamWriterMock.VerifyNoOtherCalls();

			scopeProvider.Verify(sp => sp.Push("scope"), Times.Once);
			scopeProvider.Verify(sp => sp.ForEachScope(It.IsAny<Action<object, It.IsAnyType>>(), It.IsAny<It.IsAnyType>()), Times.Once);
			scopeProvider.VerifyNoOtherCalls();
		}

		[TestMethod]
		public void ShouldLogException()
		{
			// arrange
			using var logger = GetFileLogger();

			// act
			logger.LogCritical(new Exception("TestException"), "");
			SpinWait.SpinUntil(() => lines.Count == 1);

			// assert
			streamWriterMock.Verify(sw => sw.WriteLineAsync("CRIT | System.Exception: TestException"), Times.Once);
			streamWriterMock.Verify(sw => sw.FlushAsync(), Times.Once);
			streamWriterMock.VerifyNoOtherCalls();
		}

		[TestMethod]
		public void ShouldLogExceptionWithMessage()
		{
			// arrange
			using var logger = GetFileLogger();

			// act
			logger.LogCritical(new Exception("TestException"), "Bad things happen...");
			SpinWait.SpinUntil(() => lines.Count == 1);

			// assert
			streamWriterMock.Verify(sw => sw.WriteLineAsync($"CRIT | Bad things happen...{Environment.NewLine}       System.Exception: TestException"), Times.Once);
			streamWriterMock.Verify(sw => sw.FlushAsync(), Times.Once);
			streamWriterMock.VerifyNoOtherCalls();
		}

		private FileLogger GetFileLogger(string name = null, IExternalScopeProvider scopeProvider = null)
		{
			string tmpFilePath = Path.GetTempFileName();
			try
			{
				streamWriterMock = new Mock<StreamWriter>(Stream.Null);
				streamWriterMock
					.Setup(sw => sw.WriteLineAsync(It.IsAny<string>()))
					.Callback<string>(line => lines.Add(line))
					.Returns(Task.CompletedTask);

				FileLogger fileLogger;
				if (name == null || scopeProvider == null)
				{
					fileLogger = new FileLogger(tmpFilePath);
				}
				else
				{
					fileLogger = new FileLogger(tmpFilePath, name, scopeProvider);
				}

				var fieldInfo = fileLogger.GetType().GetField("fileWriter", BindingFlags.NonPublic | BindingFlags.Instance);
				(fieldInfo.GetValue(fileLogger) as StreamWriter).Dispose();
				fieldInfo.SetValue(fileLogger, streamWriterMock.Object);

				return fileLogger;
			}
			finally
			{
				File.Delete(tmpFilePath);
			}
		}
	}
}