Skip to content
This repository was archived by the owner on Dec 13, 2018. It is now read-only.

Harden log formatters to handle null formats, null arguments, and null arrays of arguments #480

Merged
merged 1 commit into from
Aug 26, 2016
Merged

Harden log formatters to handle null formats, null arguments, and null arrays of arguments #480

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 4 additions & 8 deletions src/Microsoft.Extensions.Logging.Abstractions/Internal/FormattedLogValues.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,29 +9,25 @@
namespace Microsoft.Extensions.Logging.Internal
{
/// <summary>
/// LogValues to enable formatting options supported by <see cref="M:string.Format"/>.
/// LogValues to enable formatting options supported by <see cref="M:string.Format"/>.
/// This also enables using {NamedformatItem} in the format string.
/// </summary>
public class FormattedLogValues : IReadOnlyList<KeyValuePair<string, object>>
{
private const string NullFormat = "[null]";
private static ConcurrentDictionary<string, LogValuesFormatter> _formatters = new ConcurrentDictionary<string, LogValuesFormatter>();
private readonly LogValuesFormatter _formatter;
private readonly object[] _values;
private readonly string _originalMessage;

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

Expand Down
13 changes: 8 additions & 5 deletions src/Microsoft.Extensions.Logging.Abstractions/Internal/LogValuesFormatter.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,12 +15,11 @@ namespace Microsoft.Extensions.Logging.Internal
/// </summary>
public class LogValuesFormatter
{
private const string NullValue = "(null)";
private static readonly object[] EmptyArray = new object[0];
private readonly string _format;
private readonly List<string> _valueNames = new List<string>();

public string OriginalFormat { get; private set; }
public List<string> ValueNames => _valueNames;

public LogValuesFormatter(string format)
{
OriginalFormat = format;
Expand Down Expand Up @@ -60,6 +59,9 @@ public LogValuesFormatter(string format)
_format = sb.ToString();
}

public string OriginalFormat { get; private set; }
public List<string> ValueNames => _valueNames;

private static int FindBraceIndex(string format, char brace, int startIndex, int endIndex)
{
// Example: {{prefix{{{Argument}}}suffix}}.
Expand Down Expand Up @@ -124,6 +126,7 @@ public string Format(object[] values)

if (value == null)
{
values[i] = NullValue;
continue;
}

Expand All @@ -137,12 +140,12 @@ public string Format(object[] values)
var enumerable = value as IEnumerable;
if (enumerable != null)
{
values[i] = string.Join(", ", enumerable.Cast<object>().Where(obj => obj != null));
values[i] = string.Join(", ", enumerable.Cast<object>().Select(o => o ?? NullValue));
}
}
}

return string.Format(CultureInfo.InvariantCulture, _format, values);
return string.Format(CultureInfo.InvariantCulture, _format, values ?? EmptyArray);
}

public KeyValuePair<string, object> GetValue(object[] values, int index)
Expand Down
5 changes: 0 additions & 5 deletions src/Microsoft.Extensions.Logging.Abstractions/LoggerExtensions.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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));
}

Expand Down
2 changes: 1 addition & 1 deletion src/Microsoft.Extensions.Logging.Debug/DebugLogger.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -58,7 +58,7 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
return;
}

if(formatter == null)
if (formatter == null)
{
throw new ArgumentNullException(nameof(formatter));
}
Expand Down
104 changes: 66 additions & 38 deletions test/Microsoft.Extensions.Logging.Test/ConsoleLoggerTest.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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!";
Expand Down Expand Up @@ -54,16 +56,24 @@ private Tuple<ILoggerFactory, ConsoleSink> SetUpFactory(Func<string, LogLevel, b
}

[Fact]
public void ThrowsException_WhenNoMessageAndExceptionAreProvided()
public void LogsWhenMessageIsNotProvided()
{
// Arrange
var t = SetUp(null);
var logger = (ILogger)t.Item1;
var sink = t.Item2;
var exception = new InvalidOperationException("Invalid value");

// Act & Assert
var exception = Assert.Throws<ArgumentNullException>(() => logger.LogCritical(eventId: 0, exception: null, message: null));
exception = Assert.Throws<ArgumentNullException>(() => 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]
Expand All @@ -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);
Expand All @@ -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]
Expand All @@ -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<ArgumentNullException>(() => logger.LogCritical(10, message: null, exception: exception));
}

[Fact]
public void ThrowsException_WhenNoFormatterIsProvided()
{
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -518,7 +515,7 @@ public void WritingScopes_LogsExpectedMessage()
var sink = t.Item2;
var expectedMessage =
_paddingString
+ $"=> RequestId: 100"
+ "=> RequestId: 100"
+ Environment.NewLine;

// Act
Expand All @@ -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()
{
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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]
Expand All @@ -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<TState>(string logLevelString, int eventId, TState state, Exception exception)
{
var loglevelStringWithPadding = $"{logLevelString}: ";

Expand All @@ -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
Expand Down
29 changes: 25 additions & 4 deletions test/Microsoft.Extensions.Logging.Test/FormattedLogValuesTest.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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" })]
Expand All @@ -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}")]
Expand Down Expand Up @@ -83,7 +104,7 @@ public static TheoryData<string, object[], string> 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
{
Expand All @@ -101,13 +122,13 @@ public static TheoryData<string, object[], string> 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
{
Expand Down Expand Up @@ -151,7 +172,7 @@ public static TheoryData<string, object[], string> 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
{
Expand Down