Fix JSON possible dupe key issue (#39860)

diff --git a/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs b/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs
index 418350e..3a5aafe 100644 (file)
--- a/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs
+++ b/src/libraries/Microsoft.Extensions.Logging.Console/src/JsonConsoleFormatter.cs
@@ -41,14 +41,12 @@ namespace Microsoft.Extensions.Logging.Console
                 using (var writer = new Utf8JsonWriter(output, FormatterOptions.JsonWriterOptions))
                 {
                     writer.WriteStartObject();
-                    string timestamp = null;
                     var timestampFormat = FormatterOptions.TimestampFormat;
                     if (timestampFormat != null)
                     {
                         DateTimeOffset dateTimeOffset = FormatterOptions.UseUtcTimestamp ? DateTimeOffset.UtcNow : DateTimeOffset.Now;
-                        timestamp = dateTimeOffset.ToString(timestampFormat);
+                        writer.WriteString("Timestamp", dateTimeOffset.ToString(timestampFormat));
                     }
-                    writer.WriteString("Timestamp", timestamp);
                     writer.WriteNumber(nameof(logEntry.EventId), eventId);
                     writer.WriteString(nameof(logEntry.LogLevel), GetLogLevelString(logLevel));
                     writer.WriteString(nameof(logEntry.Category), category);
@@ -77,12 +75,18 @@ namespace Microsoft.Extensions.Logging.Console
                         writer.WriteEndObject();
                     }
 
-                    if (logEntry.State is IReadOnlyCollection<KeyValuePair<string, object>> stateDictionary)
+                    if (logEntry.State != null)
                     {
-                        foreach (KeyValuePair<string, object> item in stateDictionary)
+                        writer.WriteStartObject(nameof(logEntry.State));
+                        writer.WriteString("Message", logEntry.State.ToString());
+                        if (logEntry.State is IReadOnlyCollection<KeyValuePair<string, object>> stateProperties)
                         {
-                            writer.WriteString(item.Key, Convert.ToString(item.Value, CultureInfo.InvariantCulture));
+                            foreach (KeyValuePair<string, object> item in stateProperties)
+                            {
+                                writer.WriteString(item.Key, ToInvariantString(item.Value));
+                            }
                         }
+                        writer.WriteEndObject();
                     }
                     WriteScopeInformation(writer, scopeProvider);
                     writer.WriteEndObject();
@@ -115,26 +119,30 @@ namespace Microsoft.Extensions.Logging.Console
         {
             if (FormatterOptions.IncludeScopes && scopeProvider != null)
             {
-                int numScopes = 0;
-                writer.WriteStartObject("Scopes");
+                writer.WriteStartArray("Scopes");
                 scopeProvider.ForEachScope((scope, state) =>
                 {
-                    if (scope is IReadOnlyCollection<KeyValuePair<string, object>> scopeDictionary)
+                    if (scope is IReadOnlyCollection<KeyValuePair<string, object>> scopes)
                     {
-                        foreach (KeyValuePair<string, object> item in scopeDictionary)
+                        state.WriteStartObject();
+                        state.WriteString("Message", scope.ToString());
+                        foreach (KeyValuePair<string, object> item in scopes)
                         {
-                            state.WriteString(item.Key, Convert.ToString(item.Value, CultureInfo.InvariantCulture));
+                            state.WriteString(item.Key, ToInvariantString(item.Value));
                         }
+                        state.WriteEndObject();
                     }
                     else
                     {
-                        state.WriteString(numScopes++.ToString(), scope.ToString());
+                        state.WriteStringValue(ToInvariantString(scope));
                     }
                 }, writer);
-                writer.WriteEndObject();
+                writer.WriteEndArray();
             }
         }
 
+        private static string ToInvariantString(object obj) => Convert.ToString(obj, CultureInfo.InvariantCulture);
+
         internal JsonConsoleFormatterOptions FormatterOptions { get; set; }
 
         private void ReloadLoggerOptions(JsonConsoleFormatterOptions options)

diff --git a/src/libraries/Microsoft.Extensions.Logging.Console/tests/JsonConsoleFormatterTests.cs b/src/libraries/Microsoft.Extensions.Logging.Console/tests/JsonConsoleFormatterTests.cs
index f5e536d..09f4050 100644 (file)
--- a/src/libraries/Microsoft.Extensions.Logging.Console/tests/JsonConsoleFormatterTests.cs
+++ b/src/libraries/Microsoft.Extensions.Logging.Console/tests/JsonConsoleFormatterTests.cs
@@ -44,5 +44,198 @@ namespace Microsoft.Extensions.Logging.Console.Test
             Assert.Contains("123", write.Message);
             Assert.Contains("SimpleScope", write.Message);
         }
+
+        [ConditionalFact(typeof(PlatformDetection), nameof(PlatformDetection.IsThreadingSupported))]
+        public void Log_TimestampFormatSet_ContainsTimestamp()
+        {
+            // Arrange
+            var t = SetUp(
+                new ConsoleLoggerOptions { FormatterName = ConsoleFormatterNames.Json },
+                simpleOptions: null,
+                systemdOptions: null,
+                jsonOptions: new JsonConsoleFormatterOptions
+                {
+                    TimestampFormat = "hh:mm:ss ",
+                }
+            );
+            var logger = (ILogger)t.Logger;
+            var sink = t.Sink;
+            var exception = new InvalidOperationException("Invalid value");
+
+            // Act
+            logger.LogCritical(eventId: 0, message: null);
+
+            // Assert
+            Assert.Equal(1, sink.Writes.Count);
+            Assert.Contains(
+                "\"Timestamp\":",
+                GetMessage(sink.Writes.GetRange(0 * t.WritesPerMsg, t.WritesPerMsg)));
+        }
+
+        [ConditionalFact(typeof(PlatformDetection), nameof(PlatformDetection.IsThreadingSupported))]
+        public void Log_NullMessage_LogsWhenMessageIsNotProvided()
+        {
+            // Arrange
+            var t = SetUp(
+                new ConsoleLoggerOptions { FormatterName = ConsoleFormatterNames.Json },
+                simpleOptions: null,
+                systemdOptions: null,
+                jsonOptions: new JsonConsoleFormatterOptions
+                {
+                    JsonWriterOptions = new JsonWriterOptions() { Indented = false }
+                }
+            );
+            var logger = (ILogger)t.Logger;
+            var sink = t.Sink;
+            var exception = new InvalidOperationException("Invalid value");
+
+            // 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(3, sink.Writes.Count);
+            Assert.Equal(
+                "{\"EventId\":0,\"LogLevel\":\"Critical\",\"Category\":\"test\",\"Message\":\"[null]\""
+                + ",\"State\":{\"Message\":\"[null]\",\"{OriginalFormat}\":\"[null]\"}}"
+                +  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,
+                GetMessage(sink.Writes.GetRange(1 * t.WritesPerMsg, t.WritesPerMsg)));
+
+            Assert.Equal(
+                "{\"EventId\":0,\"LogLevel\":\"Critical\",\"Category\":\"test\""
+                + ",\"Message\":\"[null]\""
+                + ",\"Exception\":{\"Message\":\"Invalid value\",\"Type\":\"System.InvalidOperationException\",\"StackTrace\":[],\"HResult\":-2146233079}"
+                + ",\"State\":{\"Message\":\"[null]\",\"{OriginalFormat}\":\"[null]\"}}"
+                +  Environment.NewLine,
+                GetMessage(sink.Writes.GetRange(2 * t.WritesPerMsg, t.WritesPerMsg)));
+        }
+
+        [ConditionalFact(typeof(PlatformDetection), nameof(PlatformDetection.IsThreadingSupported))]
+        public void Log_ExceptionWithMessage_ExtractsInfo()
+        {
+            // 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;
+            var exception = new InvalidOperationException("Invalid value");
+
+            // 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);
+
+            // Assert
+            Assert.Equal(3, sink.Writes.Count);
+            Assert.Equal(
+                "{\"EventId\":0,\"LogLevel\":\"Information\",\"Category\":\"test\""
+                + ",\"Message\":\"exception message with stacktrace\""
+                + ",\"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,
+                GetMessage(sink.Writes.GetRange(0 * 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\":[]"
+                +"}" +  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,
+                GetMessage(sink.Writes.GetRange(2 * t.WritesPerMsg, t.WritesPerMsg)));
+        }
+
+        [ConditionalFact(typeof(PlatformDetection), nameof(PlatformDetection.IsThreadingSupported))]
+        public void Log_IncludeScopes_ContainsDuplicateNamedPropertiesInScope_AcceptableJson()
+        {
+            // 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("scope1 {name1}", 123))
+            using (logger.BeginScope("scope2 {name1} {name2}", 456, 789))
+                logger.Log(LogLevel.Information, 0, state: "exception message", exception: null, formatter: (a, b) => a);
+
+            // Assert
+            Assert.Equal(1, sink.Writes.Count);
+            Assert.Equal(
+                "{\"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,
+                GetMessage(sink.Writes.GetRange(0 * t.WritesPerMsg, t.WritesPerMsg)));
+        }
+
+        [ConditionalFact(typeof(PlatformDetection), nameof(PlatformDetection.IsThreadingSupported))]
+        public void Log_StateAndScopeAreCollections_IncludesMessageAndCollectionValues()
+        {
+            // 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("{Number}", 2))
+            using (logger.BeginScope("{AnotherNumber}", 3))
+            {
+                logger.LogInformation("{LogEntryNumber}", 1);
+            }
+
+            // Assert
+            Assert.Equal(1, sink.Writes.Count);
+            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,
+                GetMessage(sink.Writes.GetRange(0 * t.WritesPerMsg, t.WritesPerMsg)));
+        }
     }
 }