- Push contexts to stack so they can be read in reverse so that the display makes sense

- Supports multiple scopes each with keyvaluepairs displayed correctly

Author: gkinsman

src/Logging.XUnit/XUnitLogger.cs

@@ -4,6 +4,7 @@
 using System;
 using System.Collections;
 using System.Collections.Generic;
+using System.Linq;
 using System.Text;
 using Microsoft.Extensions.Logging;
 using Xunit.Abstractions;
@@ -266,32 +267,26 @@ private static string GetLogLevelString(LogLevel logLevel)
         private static void GetScopeInformation(StringBuilder builder)
         {
             var current = XUnitLogScope.Current;
-            string scopeLog;
-            int length = builder.Length;
 
+            var stack = new Stack<XUnitLogScope>();
             while (current != null)
             {
-                foreach (var property in StringifyScope(current))
-                {
-                    if (length == builder.Length)
-                    {
-                        scopeLog = $"=> {property}";
-                    }
-                    else
-                    {
-                        scopeLog = $"=> {property} ";
-                    }
-
-                    builder.Insert(length, scopeLog);
-                }
-
+                stack.Push(current);
                 current = current.Parent;
             }
 
-            if (builder.Length > length)
+            var depth = 0;
+            string DepthPadding(int depth) => new string(' ', depth * 2);
+
+            while (stack.Any())
             {
-                builder.Insert(length, MessagePadding);
-                builder.AppendLine();
+                var elem = stack.Pop();
+                foreach (var property in StringifyScope(elem))
+                {
+                    builder.AppendLine($"{MessagePadding}{DepthPadding(depth)}=> {property}");
+                }
+
+                depth++;
             }
         }
 

tests/Logging.XUnit.Tests/XUnitLoggerTests.cs

@@ -453,7 +453,12 @@ public static void XUnitLogger_Log_Logs_Message_If_Scopes_Included_And_There_Are
 
             string expected = string.Join(
                 Environment.NewLine,
-                new[] { "[2018-08-19 16:12:16Z] info: MyName[0]", "      => _ => __ => ___ => [null]", "      Message|False|False" });
+                "[2018-08-19 16:12:16Z] info: MyName[0]",
+                "      => _",
+                "        => __",
+                "          => ___",
+                "            => {OriginalFormat}: [null]",
+                "      Message|False|False");
 
             // Act
             using (logger.BeginScope("_"))
@@ -533,7 +538,11 @@ public static void XUnitLogger_Log_Logs_Message_If_Scopes_Included_And_There_Is_
 
             string expected = string.Join(
                 Environment.NewLine,
-                new[] { "[2018-08-19 16:12:16Z] info: MyName[0]", "      => ScopeKeyThree: ScopeValueThree => ScopeKeyTwo: ScopeValueTwo => ScopeKeyOne: ScopeValueOne", "      Message|False|False" });
+                "[2018-08-19 16:12:16Z] info: MyName[0]",
+                "      => ScopeKeyOne: ScopeValueOne",
+                "      => ScopeKeyTwo: ScopeValueTwo",
+                "      => ScopeKeyThree: ScopeValueThree",
+                "      Message|False|False");
 
             // Act
             using (logger.BeginScope(new[]
@@ -550,6 +559,60 @@ public static void XUnitLogger_Log_Logs_Message_If_Scopes_Included_And_There_Is_
             mock.Verify((p) => p.WriteLine(expected), Times.Once());
         }
 
+        [Fact]
+        public static void XUnitLogger_Log_Logs_Message_If_Scopes_Included_And_There_Are_Scopes_Of_KeyValuePairs()
+        {
+            // Arrange
+            var mock = new Mock<ITestOutputHelper>();
+
+            string name = "MyName";
+            var outputHelper = mock.Object;
+
+            var options = new XUnitLoggerOptions()
+            {
+                Filter = FilterTrue,
+                IncludeScopes = true,
+            };
+
+            var logger = new XUnitLogger(name, outputHelper, options)
+            {
+                Clock = StaticClock,
+            };
+
+            string expected = string.Join(
+                Environment.NewLine,
+                "[2018-08-19 16:12:16Z] info: MyName[0]",
+                "      => ScopeKeyOne: ScopeValueOne",
+                "      => ScopeKeyTwo: ScopeValueTwo",
+                "      => ScopeKeyThree: ScopeValueThree",
+                "        => ScopeKeyFour: ScopeValueFour",
+                "        => ScopeKeyFive: ScopeValueFive",
+                "        => ScopeKeySix: ScopeValueSix",
+                "      Message|False|False");
+
+            // Act
+            using (logger.BeginScope(new[]
+            {
+                new KeyValuePair<string, object>("ScopeKeyOne", "ScopeValueOne"),
+                new KeyValuePair<string, object>("ScopeKeyTwo", "ScopeValueTwo"),
+                new KeyValuePair<string, object>("ScopeKeyThree", "ScopeValueThree"),
+            }))
+            {
+                using (logger.BeginScope(new[]
+                {
+                    new KeyValuePair<string, object>("ScopeKeyFour", "ScopeValueFour"),
+                    new KeyValuePair<string, object>("ScopeKeyFive", "ScopeValueFive"),
+                    new KeyValuePair<string, object>("ScopeKeySix", "ScopeValueSix"),
+                }))
+                {
+                    logger.Log<string>(LogLevel.Information, 0, null, null, Formatter);
+                }
+            }
+
+            // Assert
+            mock.Verify((p) => p.WriteLine(expected), Times.Once());
+        }
+
         private static DateTimeOffset StaticClock() => new DateTimeOffset(2018, 08, 19, 17, 12, 16, TimeSpan.FromHours(1));
 
         private static bool FilterTrue(string categoryName, LogLevel level) => true;