diff --git a/src/Microsoft.Extensions.Logging.Abstractions/Internal/FormattedLogValues.cs b/src/Microsoft.Extensions.Logging.Abstractions/Internal/FormattedLogValues.cs index e65b7f7f..518759de 100644 --- a/src/Microsoft.Extensions.Logging.Abstractions/Internal/FormattedLogValues.cs +++ b/src/Microsoft.Extensions.Logging.Abstractions/Internal/FormattedLogValues.cs @@ -9,11 +9,12 @@ namespace Microsoft.Extensions.Logging.Internal { /// - /// LogValues to enable formatting options supported by . + /// LogValues to enable formatting options supported by . /// This also enables using {NamedformatItem} in the format string. /// public class FormattedLogValues : IReadOnlyList> { + private const string NullFormat = "[null]"; private static ConcurrentDictionary _formatters = new ConcurrentDictionary(); private readonly LogValuesFormatter _formatter; private readonly object[] _values; @@ -21,17 +22,12 @@ public class FormattedLogValues : IReadOnlyList> public FormattedLogValues(string format, params object[] values) { - if (format == null) - { - throw new ArgumentNullException(nameof(format)); - } - - if (values.Length != 0) + if (values?.Length != 0 && format != null) { _formatter = _formatters.GetOrAdd(format, f => new LogValuesFormatter(f)); } - _originalMessage = format; + _originalMessage = format ?? NullFormat; _values = values; } diff --git a/src/Microsoft.Extensions.Logging.Abstractions/Internal/LogValuesFormatter.cs b/src/Microsoft.Extensions.Logging.Abstractions/Internal/LogValuesFormatter.cs index 22199d37..22611e54 100644 --- a/src/Microsoft.Extensions.Logging.Abstractions/Internal/LogValuesFormatter.cs +++ b/src/Microsoft.Extensions.Logging.Abstractions/Internal/LogValuesFormatter.cs @@ -15,12 +15,11 @@ namespace Microsoft.Extensions.Logging.Internal /// public class LogValuesFormatter { + private const string NullValue = "(null)"; + private static readonly object[] EmptyArray = new object[0]; private readonly string _format; private readonly List _valueNames = new List(); - public string OriginalFormat { get; private set; } - public List ValueNames => _valueNames; - public LogValuesFormatter(string format) { OriginalFormat = format; @@ -60,6 +59,9 @@ public LogValuesFormatter(string format) _format = sb.ToString(); } + public string OriginalFormat { get; private set; } + public List ValueNames => _valueNames; + private static int FindBraceIndex(string format, char brace, int startIndex, int endIndex) { // Example: {{prefix{{{Argument}}}suffix}}. @@ -124,6 +126,7 @@ public string Format(object[] values) if (value == null) { + values[i] = NullValue; continue; } @@ -137,12 +140,12 @@ public string Format(object[] values) var enumerable = value as IEnumerable; if (enumerable != null) { - values[i] = string.Join(", ", enumerable.Cast().Where(obj => obj != null)); + values[i] = string.Join(", ", enumerable.Cast().Select(o => o ?? NullValue)); } } } - return string.Format(CultureInfo.InvariantCulture, _format, values); + return string.Format(CultureInfo.InvariantCulture, _format, values ?? EmptyArray); } public KeyValuePair GetValue(object[] values, int index) diff --git a/src/Microsoft.Extensions.Logging.Abstractions/LoggerExtensions.cs b/src/Microsoft.Extensions.Logging.Abstractions/LoggerExtensions.cs index 97cec7ff..7dc09d16 100644 --- a/src/Microsoft.Extensions.Logging.Abstractions/LoggerExtensions.cs +++ b/src/Microsoft.Extensions.Logging.Abstractions/LoggerExtensions.cs @@ -352,11 +352,6 @@ public static IDisposable BeginScope( throw new ArgumentNullException(nameof(logger)); } - if (messageFormat == null) - { - throw new ArgumentNullException(nameof(messageFormat)); - } - return logger.BeginScope(new FormattedLogValues(messageFormat, args)); } diff --git a/src/Microsoft.Extensions.Logging.Debug/DebugLogger.cs b/src/Microsoft.Extensions.Logging.Debug/DebugLogger.cs index a1657217..64d5d67b 100644 --- a/src/Microsoft.Extensions.Logging.Debug/DebugLogger.cs +++ b/src/Microsoft.Extensions.Logging.Debug/DebugLogger.cs @@ -58,7 +58,7 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except return; } - if(formatter == null) + if (formatter == null) { throw new ArgumentNullException(nameof(formatter)); } diff --git a/test/Microsoft.Extensions.Logging.Test/ConsoleLoggerTest.cs b/test/Microsoft.Extensions.Logging.Test/ConsoleLoggerTest.cs index 54d24199..1c6909db 100644 --- a/test/Microsoft.Extensions.Logging.Test/ConsoleLoggerTest.cs +++ b/test/Microsoft.Extensions.Logging.Test/ConsoleLoggerTest.cs @@ -15,6 +15,8 @@ namespace Microsoft.Extensions.Logging.Test { public class ConsoleLoggerTest { + private const int WritesPerMsg = 3; + private const int WritesPerError = 4; private readonly string _paddingString; private const string _loggerName = "test"; private const string _state = "This is a test, and {curly braces} are just fine!"; @@ -54,16 +56,24 @@ private Tuple SetUpFactory(Func(() => logger.LogCritical(eventId: 0, exception: null, message: null)); - exception = Assert.Throws(() => logger.LogCritical(eventId: 0, message: null)); + // Act + logger.LogCritical(eventId: 0, exception: null, message: null); + logger.LogCritical(eventId: 0, message: null); + logger.LogCritical(eventId: 0, message: null, exception: exception); + + // Assert + Assert.Equal(10, sink.Writes.Count); + Assert.Equal(GetMessage("crit", 0, "[null]", null ), GetMessage(sink.Writes.GetRange(0 * WritesPerMsg, WritesPerMsg))); + Assert.Equal(GetMessage("crit", 0, "[null]", null ), GetMessage(sink.Writes.GetRange(1 * WritesPerMsg, WritesPerMsg))); + Assert.Equal(GetMessage("crit", 0, "[null]", exception), GetMessage(sink.Writes.GetRange(2 * WritesPerMsg, WritesPerError))); } [Fact] @@ -74,7 +84,6 @@ public void DoesNotLog_NewLine_WhenNoExceptionIsProvided() var logger = (ILogger)t.Item1; var sink = t.Item2; var logMessage = "Route with name 'Default' was not found."; - var expectedMessage = _paddingString + logMessage + Environment.NewLine; // Act logger.LogCritical(logMessage); @@ -84,10 +93,10 @@ public void DoesNotLog_NewLine_WhenNoExceptionIsProvided() // Assert Assert.Equal(12, sink.Writes.Count); - Assert.Equal(expectedMessage, sink.Writes[2].Message); - Assert.Equal(expectedMessage, sink.Writes[5].Message); - Assert.Equal(expectedMessage, sink.Writes[8].Message); - Assert.Equal(expectedMessage, sink.Writes[11].Message); + Assert.Equal(GetMessage("crit", 0, logMessage, null), GetMessage(sink.Writes.GetRange(0 * WritesPerMsg, WritesPerMsg))); + Assert.Equal(GetMessage("crit", 10, logMessage, null), GetMessage(sink.Writes.GetRange(1 * WritesPerMsg, WritesPerMsg))); + Assert.Equal(GetMessage("crit", 10, logMessage, null), GetMessage(sink.Writes.GetRange(2 * WritesPerMsg, WritesPerMsg))); + Assert.Equal(GetMessage("crit", 10, logMessage, null), GetMessage(sink.Writes.GetRange(3 * WritesPerMsg, WritesPerMsg))); } [Theory] @@ -114,18 +123,6 @@ public void Writes_NewLine_WhenExceptionIsProvided(string message) Assert.Equal(expectedExceptionMessage, sink.Writes[3].Message); } - [Fact] - public void ThrowsException_WhenNoMessageIsProvided() - { - // Arrange - var t = SetUp(null); - var logger = (ILogger)t.Item1; - var exception = new InvalidOperationException("Invalid value"); - - // Act & Assert - Assert.Throws(() => logger.LogCritical(10, message: null, exception: exception)); - } - [Fact] public void ThrowsException_WhenNoFormatterIsProvided() { @@ -445,12 +442,12 @@ public void WriteCore_LogsCorrectMessages() // Assert Assert.Equal(24, sink.Writes.Count); - Assert.Equal(GetMessage("crit", 0, ex), GetMessage(sink.Writes.GetRange(0, 4))); - Assert.Equal(GetMessage("fail", 0, ex), GetMessage(sink.Writes.GetRange(4, 4))); - Assert.Equal(GetMessage("warn", 0, ex), GetMessage(sink.Writes.GetRange(8, 4))); - Assert.Equal(GetMessage("info", 0, ex), GetMessage(sink.Writes.GetRange(12, 4))); - Assert.Equal(GetMessage("dbug", 0, ex), GetMessage(sink.Writes.GetRange(16, 4))); - Assert.Equal(GetMessage("trce", 0, ex), GetMessage(sink.Writes.GetRange(20, 4))); + Assert.Equal(GetMessage("crit", 0, ex), GetMessage(sink.Writes.GetRange(0 * WritesPerError, WritesPerError))); + Assert.Equal(GetMessage("fail", 0, ex), GetMessage(sink.Writes.GetRange(1 * WritesPerError, WritesPerError))); + Assert.Equal(GetMessage("warn", 0, ex), GetMessage(sink.Writes.GetRange(2 * WritesPerError, WritesPerError))); + Assert.Equal(GetMessage("info", 0, ex), GetMessage(sink.Writes.GetRange(3 * WritesPerError, WritesPerError))); + Assert.Equal(GetMessage("dbug", 0, ex), GetMessage(sink.Writes.GetRange(4 * WritesPerError, WritesPerError))); + Assert.Equal(GetMessage("trce", 0, ex), GetMessage(sink.Writes.GetRange(5 * WritesPerError, WritesPerError))); } [Fact] @@ -518,7 +515,7 @@ public void WritingScopes_LogsExpectedMessage() var sink = t.Item2; var expectedMessage = _paddingString - + $"=> RequestId: 100" + + "=> RequestId: 100" + Environment.NewLine; // Act @@ -536,6 +533,34 @@ public void WritingScopes_LogsExpectedMessage() Assert.Equal(TestConsole.DefaultForegroundColor, write.ForegroundColor); } + [Fact] + public void WritingNestedScope_LogsNullScopeName() + { + // Arrange + var t = SetUp(filter: null, includeScopes: true); + var logger = t.Item1; + var sink = t.Item2; + var expectedMessage = + _paddingString + + "=> [null] => Request matched action: (null)" + + Environment.NewLine; + + // Act + using (logger.BeginScope(null)) + { + using (logger.BeginScope("Request matched action: {ActionName}", new object[] { null })) + { + logger.Log(LogLevel.Information, 0, _state, null, _defaultFormatter); + } + } + + // Assert + Assert.Equal(4, sink.Writes.Count); + // scope + var write = sink.Writes[2]; + Assert.Equal(expectedMessage, write.Message); + } + [Fact] public void WritingNestedScopes_LogsExpectedMessage() { @@ -545,7 +570,7 @@ public void WritingNestedScopes_LogsExpectedMessage() var sink = t.Item2; var expectedMessage = _paddingString - + $"=> RequestId: 100 => Request matched action: Index" + + "=> RequestId: 100 => Request matched action: Index" + Environment.NewLine; // Act @@ -575,11 +600,11 @@ public void WritingMultipleScopes_LogsExpectedMessage() var sink = t.Item2; var expectedMessage1 = _paddingString - + $"=> RequestId: 100 => Request matched action: Index" + + "=> RequestId: 100 => Request matched action: Index" + Environment.NewLine; var expectedMessage2 = _paddingString - + $"=> RequestId: 100 => Created product: Car" + + "=> RequestId: 100 => Created product: Car" + Environment.NewLine; // Act @@ -786,12 +811,12 @@ public void WriteCore_MessageWithNullException() // Assert Assert.Equal(18, sink.Writes.Count); - Assert.Equal(GetMessage("crit", 0, ex), GetMessage(sink.Writes.GetRange(0, 3))); - Assert.Equal(GetMessage("fail", 0, ex), GetMessage(sink.Writes.GetRange(3, 3))); - Assert.Equal(GetMessage("warn", 0, ex), GetMessage(sink.Writes.GetRange(6, 3))); - Assert.Equal(GetMessage("info", 0, ex), GetMessage(sink.Writes.GetRange(9, 3))); - Assert.Equal(GetMessage("dbug", 0, ex), GetMessage(sink.Writes.GetRange(12, 3))); - Assert.Equal(GetMessage("trce", 0, ex), GetMessage(sink.Writes.GetRange(15, 3))); + Assert.Equal(GetMessage("crit", 0, ex), GetMessage(sink.Writes.GetRange(0 * WritesPerMsg, WritesPerMsg))); + Assert.Equal(GetMessage("fail", 0, ex), GetMessage(sink.Writes.GetRange(1 * WritesPerMsg, WritesPerMsg))); + Assert.Equal(GetMessage("warn", 0, ex), GetMessage(sink.Writes.GetRange(2 * WritesPerMsg, WritesPerMsg))); + Assert.Equal(GetMessage("info", 0, ex), GetMessage(sink.Writes.GetRange(3 * WritesPerMsg, WritesPerMsg))); + Assert.Equal(GetMessage("dbug", 0, ex), GetMessage(sink.Writes.GetRange(4 * WritesPerMsg, WritesPerMsg))); + Assert.Equal(GetMessage("trce", 0, ex), GetMessage(sink.Writes.GetRange(5 * WritesPerMsg, WritesPerMsg))); } [Fact] @@ -817,6 +842,9 @@ public void WriteCore_NullMessageWithNullException() } private string GetMessage(string logLevelString, int eventId, Exception exception) + => GetMessage(logLevelString, eventId, _state, exception); + + private string GetMessage(string logLevelString, int eventId, TState state, Exception exception) { var loglevelStringWithPadding = $"{logLevelString}: "; @@ -825,7 +853,7 @@ private string GetMessage(string logLevelString, int eventId, Exception exceptio + $"{_loggerName}[{eventId}]" + Environment.NewLine + _paddingString - + ReplaceMessageNewLinesWithPadding(_state.ToString()) + + ReplaceMessageNewLinesWithPadding(state?.ToString()) + Environment.NewLine + ( exception != null ? exception.ToString() + Environment.NewLine diff --git a/test/Microsoft.Extensions.Logging.Test/FormattedLogValuesTest.cs b/test/Microsoft.Extensions.Logging.Test/FormattedLogValuesTest.cs index f5812520..d59fd74e 100644 --- a/test/Microsoft.Extensions.Logging.Test/FormattedLogValuesTest.cs +++ b/test/Microsoft.Extensions.Logging.Test/FormattedLogValuesTest.cs @@ -11,6 +11,7 @@ namespace Microsoft.Extensions.Logging.Test public class FormattedLogValuesTest { [Theory] + [InlineData("", "", null)] [InlineData("", "", new object[] { })] [InlineData("arg1 arg2", "{0} {1}", new object[] { "arg1", "arg2" })] [InlineData("arg1 arg2", "{Start} {End}", new object[] { "arg1", "arg2" })] @@ -25,6 +26,26 @@ public void LogValues_With_Basic_Types(string expected, string format, object[] Assert.Equal(format, logValues.First(v => v.Key == "{OriginalFormat}").Value); } + [Theory] + [InlineData("[null]", null, null)] + [InlineData("[null]", null, new object[] { })] + [InlineData("[null]", null, new object[] { null })] + [InlineData("[null]", null, new object[] { 1 })] + public void Log_NullFormat(string expected, string format, object[] args) + { + var logValues = new FormattedLogValues(format, args); + Assert.Equal(expected, logValues.ToString()); + } + + [Theory] + [InlineData("(null), (null) : (null)", "{0} : {1}", new object[] { new object[] { null, null }, null })] + [InlineData("(null)", "{0}", new object[] { null })] + public void LogValues_WithNulls(string expected, string format, object[] args) + { + var logValues = new FormattedLogValues(format, args); + Assert.Equal(expected, logValues.ToString()); + } + [Theory] [InlineData("1 2015", "{Year,6:d yyyy}")] [InlineData("1:01:2015 AM,: 01", "{Year,-10:d:MM:yyyy tt},:{second,10:ss}")] @@ -83,7 +104,7 @@ public static TheoryData FormatsEnumerableValuesData { "The view '{ViewName}' was not found. Searched locations: {SearchedLocations}", new object[] { "Index", null }, - "The view 'Index' was not found. Searched locations: " + "The view 'Index' was not found. Searched locations: (null)" }, // empty enumerable { @@ -101,13 +122,13 @@ public static TheoryData FormatsEnumerableValuesData { "The view '{ViewName}' was not found. Searched locations: {SearchedLocations}", new object[] { "Index", new string[] { null } }, - "The view 'Index' was not found. Searched locations: " + "The view 'Index' was not found. Searched locations: (null)" }, // null value item in enumerable { "The view '{ViewName}' was not found. Searched locations: {SearchedLocations}", new object[] { "Index", new string[] { null, "Views/Home/Index.cshtml" } }, - "The view 'Index' was not found. Searched locations: Views/Home/Index.cshtml" + "The view 'Index' was not found. Searched locations: (null), Views/Home/Index.cshtml" }, // multi item enumerable { @@ -151,7 +172,7 @@ public static TheoryData FormatsEnumerableValuesData "The view '{ViewName}' was not found. Searched locations: {SearchedLocations}", new object[] { "Index", new Uri[][] { null, new[] { new Uri("http://def") } } }, "The view 'Index' was not found. Searched locations: " + - "System.Uri[]" + "(null), System.Uri[]" }, // non-string sub-enumerables {