Merge pull request #5 from martincostello/Support-Scopes

Add support for logging scopes

src/Logging.XUnit/XUnitLogScope.cs

@@ -0,0 +1,90 @@
+// Copyright (c) Martin Costello, 2018. All rights reserved.
+// Licensed under the Apache 2.0 license. See the LICENSE file in the project root for full license information.
+
+using System;
+using System.Threading;
+
+namespace MartinCostello.Logging.XUnit
+{
+    /// <summary>
+    /// A class representing a scope for logging. This class cannot be inherited.
+    /// </summary>
+    internal sealed class XUnitLogScope
+    {
+        /// <summary>
+        /// The scope for the current thread.
+        /// </summary>
+        private static readonly AsyncLocal<XUnitLogScope> _value = new AsyncLocal<XUnitLogScope>();
+
+        /// <summary>
+        /// The name of the logging scope. This class cannot be inherited.
+        /// </summary>
+        private readonly string _name;
+
+        /// <summary>
+        /// The state object for the scope.
+        /// </summary>
+        private readonly object _state;
+
+        /// <summary>
+        /// Initializes a new instance of the <see cref="XUnitLogScope"/> class.
+        /// </summary>
+        /// <param name="name">The name of the logging scope.</param>
+        /// <param name="state">The state object for the scope.</param>
+        internal XUnitLogScope(string name, object state)
+        {
+            _name = name;
+            _state = state;
+        }
+
+        /// <summary>
+        /// Gets or sets the current scope.
+        /// </summary>
+        internal static XUnitLogScope Current
+        {
+            get { return _value.Value; }
+            set { _value.Value = value; }
+        }
+
+        /// <summary>
+        /// Gets the parent scope.
+        /// </summary>
+        internal XUnitLogScope Parent { get; private set; }
+
+        /// <inheritdoc />
+        public override string ToString()
+            => _state.ToString();
+
+        /// <summary>
+        /// Pushes a new value into the scope.
+        /// </summary>
+        /// <param name="name">The name of the logging scope.</param>
+        /// <param name="state">The state object for the scope.</param>
+        /// <returns>
+        /// An <see cref="IDisposable"/> that pops the scope.
+        /// </returns>
+        internal static IDisposable Push(string name, object state)
+        {
+            var temp = Current;
+
+            Current = new XUnitLogScope(name, state)
+            {
+                Parent = temp
+            };
+
+            return new DisposableScope();
+        }
+
+        /// <summary>
+        /// A class the disposes of the current scope. This class cannot be inherited.
+        /// </summary>
+        private sealed class DisposableScope : IDisposable
+        {
+            /// <inheritdoc />
+            public void Dispose()
+            {
+                Current = Current.Parent;
+            }
+        }
+    }
+}

src/Logging.XUnit/XUnitLogger.cs

@@ -4,7 +4,6 @@
 using System;
 using System.Text;
 using Microsoft.Extensions.Logging;
-using Microsoft.Extensions.Logging.Abstractions.Internal;
 using Xunit.Abstractions;
 
 namespace MartinCostello.Logging.XUnit
@@ -60,7 +59,9 @@ public XUnitLogger(string name, ITestOutputHelper outputHelper, XUnitLoggerOptio
         {
             Name = name ?? throw new ArgumentNullException(nameof(name));
             _outputHelper = outputHelper ?? throw new ArgumentNullException(nameof(outputHelper));
+
             Filter = options?.Filter ?? ((category, logLevel) => true);
+            IncludeScopes = options?.IncludeScopes ?? false;
         }
 
         /// <summary>
@@ -75,6 +76,11 @@ public Func<string, LogLevel, bool> Filter
             set { _filter = value ?? throw new ArgumentNullException(nameof(value)); }
         }
 
+        /// <summary>
+        /// Gets or sets a value indicating whether to include scopes.
+        /// </summary>
+        public bool IncludeScopes { get; set; }
+
         /// <summary>
         /// Gets the name of the logger.
         /// </summary>
@@ -86,7 +92,15 @@ public Func<string, LogLevel, bool> Filter
         internal Func<DateTimeOffset> Clock { get; set; } = () => DateTimeOffset.Now;
 
         /// <inheritdoc />
-        public IDisposable BeginScope<TState>(TState state) => NullScope.Instance;
+        public IDisposable BeginScope<TState>(TState state)
+        {
+            if (state == null)
+            {
+                throw new ArgumentNullException(nameof(state));
+            }
+
+            return XUnitLogScope.Push(Name, state);
+        }
 
         /// <inheritdoc />
         public bool IsEnabled(LogLevel logLevel)
@@ -145,6 +159,11 @@ public virtual void WriteMessage(LogLevel logLevel, int eventId, string message,
             logBuilder.Append(eventId);
             logBuilder.AppendLine("]");
 
+            if (IncludeScopes)
+            {
+                GetScopeInformation(logBuilder);
+            }
+
             bool hasMessage = !string.IsNullOrEmpty(message);
 
             if (hasMessage)
@@ -212,5 +231,37 @@ private static string GetLogLevelString(LogLevel logLevel)
                     throw new ArgumentOutOfRangeException(nameof(logLevel));
             }
         }
+
+        /// <summary>
+        /// Gets the scope information for the current operation.
+        /// </summary>
+        /// <param name="builder">The <see cref="StringBuilder"/> to write the scope to.</param>
+        private static void GetScopeInformation(StringBuilder builder)
+        {
+            var current = XUnitLogScope.Current;
+            string scopeLog = string.Empty;
+            int length = builder.Length;
+
+            while (current != null)
+            {
+                if (length == builder.Length)
+                {
+                    scopeLog = $"=> {current}";
+                }
+                else
+                {
+                    scopeLog = $"=> {current} ";
+                }
+
+                builder.Insert(length, scopeLog);
+                current = current.Parent;
+            }
+
+            if (builder.Length > length)
+            {
+                builder.Insert(length, MessagePadding);
+                builder.AppendLine();
+            }
+        }
     }
 }

src/Logging.XUnit/XUnitLoggerOptions.cs

@@ -22,5 +22,10 @@ public XUnitLoggerOptions()
         /// Gets or sets the category filter to apply to logs.
         /// </summary>
         public Func<string, LogLevel, bool> Filter { get; set; } = (c, l) => true; // By default log everything
+
+        /// <summary>
+        /// Gets or sets a value indicating whether to include scopes.
+        /// </summary>
+        public bool IncludeScopes { get; set; }
     }
 }

tests/Logging.XUnit.Tests/XUnitLoggerProviderTests.cs

@@ -44,6 +44,7 @@ public static void XUnitLoggerProvider_Creates_Logger()
                 var xunit = actual.ShouldBeOfType<XUnitLogger>();
                 xunit.Name.ShouldBe(categoryName);
                 xunit.Filter.ShouldBeSameAs(options.Filter);
+                xunit.IncludeScopes.ShouldBeFalse();
             }
         }
     }

tests/Logging.XUnit.Tests/XUnitLoggerTests.cs

@@ -45,13 +45,15 @@ public static void XUnitLogger_Constructor_Initializes_Instance()
             var options = new XUnitLoggerOptions()
             {
                 Filter = FilterTrue,
+                IncludeScopes = true,
             };
 
             // Act
             var actual = new XUnitLogger(name, outputHelper, options);
 
             // Assert
             actual.Filter.ShouldBeSameAs(options.Filter);
+            actual.IncludeScopes.ShouldBeTrue();
             actual.Name.ShouldBe(name);
 
             // Act
@@ -60,6 +62,7 @@ public static void XUnitLogger_Constructor_Initializes_Instance()
             // Assert
             actual.Filter.ShouldNotBeNull();
             actual.Filter(null, LogLevel.None).ShouldBeTrue();
+            actual.IncludeScopes.ShouldBeFalse();
             actual.Name.ShouldBe(name);
         }
 
@@ -80,6 +83,19 @@ public static void XUnitLogger_BeginScope_Returns_Value()
             }
         }
 
+        [Fact]
+        public static void XUnitLogger_BeginScope_Throws_If_State_Is_Null()
+        {
+            // Arrange
+            string name = "MyName";
+            var outputHelper = Mock.Of<ITestOutputHelper>();
+            var options = new XUnitLoggerOptions();
+            var logger = new XUnitLogger(name, outputHelper, options);
+
+            // Act
+            Assert.Throws<ArgumentNullException>("state", () => logger.BeginScope(null as string));
+        }
+
         [Theory]
         [InlineData(LogLevel.Critical, true)]
         [InlineData(LogLevel.Debug, false)]
@@ -365,6 +381,80 @@ public static void XUnitLogger_Log_Logs_Very_Long_Messages()
             mock.Verify((p) => p.WriteLine(It.Is<string>((r) => r.Length > 1024)), Times.Once());
         }
 
+        [Fact]
+        public static void XUnitLogger_Log_Logs_Message_If_Scopes_Included_But_There_Are_No_Scopes()
+        {
+            // 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,
+                new[] { "[2018-08-19 16:12:16Z] info: MyName[0]", "      Message|False|False" });
+
+            // Act
+            logger.Log<string>(LogLevel.Information, 0, null, null, Formatter);
+
+            // Assert
+            mock.Verify((p) => p.WriteLine(expected), Times.Once());
+        }
+
+        [Fact]
+        public static void XUnitLogger_Log_Logs_Message_If_Scopes_Included_And_There_Are_Scopes()
+        {
+            // 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,
+                new[] { "[2018-08-19 16:12:16Z] info: MyName[0]", "      => _ => __ => ___ => [null]", "      Message|False|False" });
+
+            // Act
+            using (logger.BeginScope("_"))
+            {
+                using (logger.BeginScope("__"))
+                {
+                    using (logger.BeginScope("___"))
+                    {
+                        using (logger.BeginScope(null))
+                        {
+                            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;