From bfe783ce7c9d294c1670271fcaa4b6832f7541be Mon Sep 17 00:00:00 2001 From: Alessio Franceschelli Date: Tue, 11 Aug 2020 19:13:47 +0100 Subject: [PATCH] Extensions.Logging: JsonConsoleFormatter serializes scope and state properties using native json type (#40067) --- .../src/JsonConsoleFormatter.cs | 65 +++++- .../JsonConsoleFormatterTests.cs | 228 +++++++++++++++++++-- 2 files changed, 274 insertions(+), 19 deletions(-) diff --git a/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs b/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs index 3a5aafe..aabb5ab 100644 --- a/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs +++ b/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs @@ -2,12 +2,16 @@ // The .NET Foundation licenses this file to you under the MIT license. using System; +using System.Buffers; using System.Collections.Generic; using System.Globalization; using System.IO; using System.Linq; +using System.Runtime.CompilerServices; +using System.Runtime.InteropServices; using System.Text; using System.Text.Json; +using System.Text.Json.Serialization; using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Options; @@ -83,7 +87,7 @@ namespace Microsoft.Extensions.Logging.Console { foreach (KeyValuePair item in stateProperties) { - writer.WriteString(item.Key, ToInvariantString(item.Value)); + WriteItem(writer, item); } } writer.WriteEndObject(); @@ -128,7 +132,7 @@ namespace Microsoft.Extensions.Logging.Console state.WriteString("Message", scope.ToString()); foreach (KeyValuePair item in scopes) { - state.WriteString(item.Key, ToInvariantString(item.Value)); + WriteItem(state, item); } state.WriteEndObject(); } @@ -141,6 +145,63 @@ namespace Microsoft.Extensions.Logging.Console } } + private void WriteItem(Utf8JsonWriter writer, KeyValuePair item) + { + var key = item.Key; + switch (item.Value) + { + case bool boolValue: + writer.WriteBoolean(key, boolValue); + break; + case byte byteValue: + writer.WriteNumber(key, byteValue); + break; + case sbyte sbyteValue: + writer.WriteNumber(key, sbyteValue); + break; + case char charValue: +#if NETCOREAPP + writer.WriteString(key, MemoryMarshal.CreateSpan(ref charValue, 1)); +#else + writer.WriteString(key, charValue.ToString()); +#endif + break; + case decimal decimalValue: + writer.WriteNumber(key, decimalValue); + break; + case double doubleValue: + writer.WriteNumber(key, doubleValue); + break; + case float floatValue: + writer.WriteNumber(key, floatValue); + break; + case int intValue: + writer.WriteNumber(key, intValue); + break; + case uint uintValue: + writer.WriteNumber(key, uintValue); + break; + case long longValue: + writer.WriteNumber(key, longValue); + break; + case ulong ulongValue: + writer.WriteNumber(key, ulongValue); + break; + case short shortValue: + writer.WriteNumber(key, shortValue); + break; + case ushort ushortValue: + writer.WriteNumber(key, ushortValue); + break; + case null: + writer.WriteNull(key); + break; + default: + writer.WriteString(key, ToInvariantString(item.Value)); + break; + } + } + private static string ToInvariantString(object obj) => Convert.ToString(obj, CultureInfo.InvariantCulture); internal JsonConsoleFormatterOptions FormatterOptions { get; set; } diff --git a/src/libraries/Microsoft.Extensions.Logging.Console/tests/Microsoft.Extensions.Logging.Console.Tests/JsonConsoleFormatterTests.cs b/src/libraries/Microsoft.Extensions.Logging.Console/tests/Microsoft.Extensions.Logging.Console.Tests/JsonConsoleFormatterTests.cs index 09f4050..8cdfd69 100644 --- a/src/libraries/Microsoft.Extensions.Logging.Console/tests/Microsoft.Extensions.Logging.Console.Tests/JsonConsoleFormatterTests.cs +++ b/src/libraries/Microsoft.Extensions.Logging.Console/tests/Microsoft.Extensions.Logging.Console.Tests/JsonConsoleFormatterTests.cs @@ -2,9 +2,10 @@ // The .NET Foundation licenses this file to you under the MIT license. using System; +using System.Collections.Generic; +using System.Globalization; using System.Text.Json; -using Microsoft.Extensions.Logging.Abstractions; -using Microsoft.Extensions.Logging.Console; +using System.Text.RegularExpressions; using Microsoft.Extensions.Logging.Test.Console; using Xunit; @@ -20,9 +21,10 @@ namespace Microsoft.Extensions.Logging.Console.Test new ConsoleLoggerOptions { FormatterName = ConsoleFormatterNames.Json }, new SimpleConsoleFormatterOptions { IncludeScopes = true }, new ConsoleFormatterOptions { IncludeScopes = true }, - new JsonConsoleFormatterOptions { + new JsonConsoleFormatterOptions + { IncludeScopes = true, - JsonWriterOptions = new JsonWriterOptions() { Encoder = System.Text.Encodings.Web.JavaScriptEncoder.UnsafeRelaxedJsonEscaping } + JsonWriterOptions = new JsonWriterOptions() { Encoder = System.Text.Encodings.Web.JavaScriptEncoder.UnsafeRelaxedJsonEscaping } }); var logger = t.Logger; var sink = t.Sink; @@ -99,12 +101,12 @@ namespace Microsoft.Extensions.Logging.Console.Test Assert.Equal( "{\"EventId\":0,\"LogLevel\":\"Critical\",\"Category\":\"test\",\"Message\":\"[null]\"" + ",\"State\":{\"Message\":\"[null]\",\"{OriginalFormat}\":\"[null]\"}}" - + Environment.NewLine, + + Environment.NewLine, GetMessage(sink.Writes.GetRange(0 * t.WritesPerMsg, t.WritesPerMsg))); Assert.Equal( "{\"EventId\":0,\"LogLevel\":\"Critical\",\"Category\":\"test\",\"Message\":\"[null]\"" + ",\"State\":{\"Message\":\"[null]\",\"{OriginalFormat}\":\"[null]\"}}" - + Environment.NewLine, + + Environment.NewLine, GetMessage(sink.Writes.GetRange(1 * t.WritesPerMsg, t.WritesPerMsg))); Assert.Equal( @@ -112,7 +114,7 @@ namespace Microsoft.Extensions.Logging.Console.Test + ",\"Message\":\"[null]\"" + ",\"Exception\":{\"Message\":\"Invalid value\",\"Type\":\"System.InvalidOperationException\",\"StackTrace\":[],\"HResult\":-2146233079}" + ",\"State\":{\"Message\":\"[null]\",\"{OriginalFormat}\":\"[null]\"}}" - + Environment.NewLine, + + Environment.NewLine, GetMessage(sink.Writes.GetRange(2 * t.WritesPerMsg, t.WritesPerMsg))); } @@ -137,7 +139,7 @@ namespace Microsoft.Extensions.Logging.Console.Test // Act logger.LogInformation(exception, "exception message with {0}", "stacktrace"); logger.Log(LogLevel.Information, 0, state: "exception message", exception: exception, formatter: (a, b) => a); - + using (logger.BeginScope("scope1 {name1}", 123)) using (logger.BeginScope("scope2 {name1} {name2}", 456, 789)) logger.Log(LogLevel.Information, 0, state: "exception message", exception: exception, formatter: (a, b) => a); @@ -150,7 +152,7 @@ namespace Microsoft.Extensions.Logging.Console.Test + ",\"Exception\":{\"Message\":\"Invalid value\",\"Type\":\"System.InvalidOperationException\",\"StackTrace\":[],\"HResult\":-2146233079}" + ",\"State\":{\"Message\":\"exception message with stacktrace\",\"0\":\"stacktrace\",\"{OriginalFormat}\":\"exception message with {0}\"}" + ",\"Scopes\":[]" - +"}" + Environment.NewLine, + + "}" + Environment.NewLine, GetMessage(sink.Writes.GetRange(0 * t.WritesPerMsg, t.WritesPerMsg))); Assert.Equal( "{\"EventId\":0,\"LogLevel\":\"Information\",\"Category\":\"test\"" @@ -158,15 +160,15 @@ namespace Microsoft.Extensions.Logging.Console.Test + ",\"Exception\":{\"Message\":\"Invalid value\",\"Type\":\"System.InvalidOperationException\",\"StackTrace\":[],\"HResult\":-2146233079}" + ",\"State\":{\"Message\":\"exception message\"}" + ",\"Scopes\":[]" - +"}" + Environment.NewLine, + + "}" + Environment.NewLine, GetMessage(sink.Writes.GetRange(1 * t.WritesPerMsg, t.WritesPerMsg))); Assert.Equal( "{\"EventId\":0,\"LogLevel\":\"Information\",\"Category\":\"test\"" + ",\"Message\":\"exception message\"" + ",\"Exception\":{\"Message\":\"Invalid value\",\"Type\":\"System.InvalidOperationException\",\"StackTrace\":[],\"HResult\":-2146233079}" + ",\"State\":{\"Message\":\"exception message\"}" - + ",\"Scopes\":[{\"Message\":\"scope1 123\",\"name1\":\"123\",\"{OriginalFormat}\":\"scope1 {name1}\"},{\"Message\":\"scope2 456 789\",\"name1\":\"456\",\"name2\":\"789\",\"{OriginalFormat}\":\"scope2 {name1} {name2}\"}]" - +"}" + Environment.NewLine, + + ",\"Scopes\":[{\"Message\":\"scope1 123\",\"name1\":123,\"{OriginalFormat}\":\"scope1 {name1}\"},{\"Message\":\"scope2 456 789\",\"name1\":456,\"name2\":789,\"{OriginalFormat}\":\"scope2 {name1} {name2}\"}]" + + "}" + Environment.NewLine, GetMessage(sink.Writes.GetRange(2 * t.WritesPerMsg, t.WritesPerMsg))); } @@ -198,8 +200,8 @@ namespace Microsoft.Extensions.Logging.Console.Test "{\"EventId\":0,\"LogLevel\":\"Information\",\"Category\":\"test\"" + ",\"Message\":\"exception message\"" + ",\"State\":{\"Message\":\"exception message\"}" - + ",\"Scopes\":[{\"Message\":\"scope1 123\",\"name1\":\"123\",\"{OriginalFormat}\":\"scope1 {name1}\"},{\"Message\":\"scope2 456 789\",\"name1\":\"456\",\"name2\":\"789\",\"{OriginalFormat}\":\"scope2 {name1} {name2}\"}]" - +"}" + Environment.NewLine, + + ",\"Scopes\":[{\"Message\":\"scope1 123\",\"name1\":123,\"{OriginalFormat}\":\"scope1 {name1}\"},{\"Message\":\"scope2 456 789\",\"name1\":456,\"name2\":789,\"{OriginalFormat}\":\"scope2 {name1} {name2}\"}]" + + "}" + Environment.NewLine, GetMessage(sink.Writes.GetRange(0 * t.WritesPerMsg, t.WritesPerMsg))); } @@ -232,10 +234,202 @@ namespace Microsoft.Extensions.Logging.Console.Test Assert.Equal( "{\"EventId\":0,\"LogLevel\":\"Information\",\"Category\":\"test\"" + ",\"Message\":\"1\"" - + ",\"State\":{\"Message\":\"1\",\"LogEntryNumber\":\"1\",\"{OriginalFormat}\":\"{LogEntryNumber}\"}" - + ",\"Scopes\":[{\"Message\":\"2\",\"Number\":\"2\",\"{OriginalFormat}\":\"{Number}\"},{\"Message\":\"3\",\"AnotherNumber\":\"3\",\"{OriginalFormat}\":\"{AnotherNumber}\"}]" - +"}" + Environment.NewLine, + + ",\"State\":{\"Message\":\"1\",\"LogEntryNumber\":1,\"{OriginalFormat}\":\"{LogEntryNumber}\"}" + + ",\"Scopes\":[{\"Message\":\"2\",\"Number\":2,\"{OriginalFormat}\":\"{Number}\"},{\"Message\":\"3\",\"AnotherNumber\":3,\"{OriginalFormat}\":\"{AnotherNumber}\"}]" + + "}" + Environment.NewLine, GetMessage(sink.Writes.GetRange(0 * t.WritesPerMsg, t.WritesPerMsg))); } + + [ConditionalTheory(typeof(PlatformDetection), nameof(PlatformDetection.IsThreadingSupported))] + [MemberData(nameof(SpecialCaseValues))] + public void Log_StateAndScopeContainsSpecialCaseValue_SerializesValueAsExpected(object value, string expectedJsonValue) + { + // Arrange + var t = SetUp( + new ConsoleLoggerOptions { FormatterName = ConsoleFormatterNames.Json }, + simpleOptions: null, + systemdOptions: null, + jsonOptions: new JsonConsoleFormatterOptions + { + JsonWriterOptions = new JsonWriterOptions() { Indented = false }, + IncludeScopes = true + } + ); + var logger = (ILogger)t.Logger; + var sink = t.Sink; + + // Act + using (logger.BeginScope("{Value}", value)) + { + logger.LogInformation("{LogEntryValue}", value); + } + + // Assert + string message = sink.Writes[0].Message; + Assert.Contains("\"Value\":" + expectedJsonValue + ",", message); + Assert.Contains("\"LogEntryValue\":" + expectedJsonValue + ",", message); + } + + [ConditionalTheory(typeof(PlatformDetection), nameof(PlatformDetection.IsThreadingSupported))] + [MemberData(nameof(FloatingPointValues))] + public void Log_StateAndScopeContainsFloatingPointType_SerializesValue(object value) + { + // Arrange + var t = SetUp( + new ConsoleLoggerOptions { FormatterName = ConsoleFormatterNames.Json }, + simpleOptions: null, + systemdOptions: null, + jsonOptions: new JsonConsoleFormatterOptions + { + JsonWriterOptions = new JsonWriterOptions() { Indented = false }, + IncludeScopes = true + } + ); + var logger = (ILogger)t.Logger; + var sink = t.Sink; + + // Act + using (logger.BeginScope("{Value}", value)) + { + logger.LogInformation("{LogEntryValue}", value); + } + + // Assert + string message = sink.Writes[0].Message; + AssertMessageValue(message, "Value"); + AssertMessageValue(message, "LogEntryValue"); + + static void AssertMessageValue(string message, string propertyName) + { + var serializedValueMatch = Regex.Match(message, "\"" + propertyName + "\":(.*?),"); + Assert.Equal(2, serializedValueMatch.Groups.Count); + string jsonValue = serializedValueMatch.Groups[1].Value; + Assert.True(double.TryParse(jsonValue, NumberStyles.Any, CultureInfo.InvariantCulture, out var floatingPointValue), "The json doesn not contain a floating point value: " + jsonValue); + Assert.Equal(1.2, floatingPointValue, 2); + } + } + + [ConditionalFact(typeof(PlatformDetection), nameof(PlatformDetection.IsThreadingSupported))] + public void Log_StateAndScopeContainsNullValue_SerializesNull() + { + // Arrange + var t = SetUp( + new ConsoleLoggerOptions { FormatterName = ConsoleFormatterNames.Json }, + simpleOptions: null, + systemdOptions: null, + jsonOptions: new JsonConsoleFormatterOptions + { + JsonWriterOptions = new JsonWriterOptions() { Indented = false }, + IncludeScopes = true + } + ); + var logger = (ILogger)t.Logger; + var sink = t.Sink; + + // Act + using (logger.BeginScope(new WithNullValue("ScopeKey"))) + { + logger.Log(LogLevel.Information, 0, state: new WithNullValue("LogKey"), exception: null, formatter: (a, b) => string.Empty); + } + + // Assert + string message = sink.Writes[0].Message; + Assert.Contains("\"ScopeKey\":null", message); + Assert.Contains("\"LogKey\":null", message); + } + + public static TheoryData SpecialCaseValues + { + get + { + var data = new TheoryData + { + // primitives, excluding floating point + { true, "true" }, + { (byte)1, "1" }, + { (sbyte)1, "1" }, + { 'a', "\"a\"" }, + { 1, "1" }, + { (uint)1, "1" }, + { (long)1, "1" }, + { (ulong)1, "1" }, + { (short)1, "1" }, + { (ushort)1, "1" }, + { 1.2m, "1.2" }, + + // nullables primitives, excluding floating point + { (bool?)true, "true" }, + { (byte?)1, "1" }, + { (sbyte?)1, "1" }, + { (char?)'a', "\"a\"" }, + { (int?)1, "1" }, + { (uint?)1, "1" }, + { (long?)1, "1" }, + { (ulong?)1, "1" }, + { (short?)1, "1" }, + { (ushort?)1, "1" }, + { (decimal?)1.2m, "1.2" }, + + // Dynamic object serialized as string + { new { a = 1, b = 2 }, "\"{ a = 1, b = 2 }\"" }, + + // null serialized as special string + { null, "\"(null)\"" } + }; + return data; + } + } + + public static TheoryData FloatingPointValues + { + get + { + var data = new TheoryData + { + { 1.2 }, + { 1.2f }, + + // nullables + { (double?)1.2 }, + { (float?)1.2f } + }; + return data; + } + } + + internal class WithNullValue : IReadOnlyList> + { + private readonly string _key; + + public WithNullValue(string key) + { + _key = key; + } + + int IReadOnlyCollection>.Count { get; } = 1; + + KeyValuePair IReadOnlyList>.this[int index] + { + get + { + if (index == 0) + { + return new KeyValuePair(_key, null); + } + + throw new ArgumentOutOfRangeException(nameof(index)); + } + } + + IEnumerator> IEnumerable>.GetEnumerator() + { + yield return new KeyValuePair(_key, null); + } + + System.Collections.IEnumerator System.Collections.IEnumerable.GetEnumerator() + { + return ((IEnumerable>)this).GetEnumerator(); + } + } } } -- 2.7.4