Extensions.Logging: JsonConsoleFormatter serializes scope and state properties using...
authorAlessio Franceschelli <alessio@franceschelli.me>
Tue, 11 Aug 2020 18:13:47 +0000 (19:13 +0100)
committerGitHub <noreply@github.com>
Tue, 11 Aug 2020 18:13:47 +0000 (11:13 -0700)
src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs
src/libraries/Microsoft.Extensions.Logging.Console/tests/Microsoft.Extensions.Logging.Console.Tests/JsonConsoleFormatterTests.cs

index 3a5aafe..aabb5ab 100644 (file)
@@ -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<string, object> 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<string, object> 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<string, object> 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; }
index 09f4050..8cdfd69 100644 (file)
@@ -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<object, string> SpecialCaseValues
+        {
+            get
+            {
+                var data = new TheoryData<object, string>
+                {
+                    // 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<object> FloatingPointValues
+        {
+            get
+            {
+                var data = new TheoryData<object>
+                {
+                    { 1.2 },
+                    { 1.2f },
+
+                    // nullables
+                    { (double?)1.2 },
+                    { (float?)1.2f }
+                };
+                return data;
+            }
+        }
+
+        internal class WithNullValue : IReadOnlyList<KeyValuePair<string, object>>
+        {
+            private readonly string _key;
+
+            public WithNullValue(string key)
+            {
+                _key = key;
+            }
+
+            int IReadOnlyCollection<KeyValuePair<string, object>>.Count { get; } = 1;
+
+            KeyValuePair<string, object> IReadOnlyList<KeyValuePair<string, object>>.this[int index]
+            {
+                get
+                {
+                    if (index == 0)
+                    {
+                        return new KeyValuePair<string, object>(_key, null);
+                    }
+
+                    throw new ArgumentOutOfRangeException(nameof(index));
+                }
+            }
+
+            IEnumerator<KeyValuePair<string, object>> IEnumerable<KeyValuePair<string, object>>.GetEnumerator()
+            {
+                yield return new KeyValuePair<string, object>(_key, null);
+            }
+
+            System.Collections.IEnumerator System.Collections.IEnumerable.GetEnumerator()
+            {
+                return ((IEnumerable<KeyValuePair<string, object>>)this).GetEnumerator();
+            }
+        }
     }
 }