Merge pull request #59 from serilog/dev

nblumhardt · web-flow · commit 40ae58e46f2f · 2016-11-17T09:55:25.000+10:00
1.3.0 Release
diff --git a/README.md b/README.md
@@ -1,5 +1,4 @@
-# Serilog.Extensions.Logging 
-[![Build status](https://ci.appveyor.com/api/projects/status/865nohxfiq1rnby0/branch/master?svg=true)](https://ci.appveyor.com/project/serilog/serilog-framework-logging/history) [![NuGet Version](http://img.shields.io/nuget/v/Serilog.Extensions.Logging.svg?style=flat)](https://www.nuget.org/packages/Serilog.Extensions.Logging/) 
+# Serilog.Extensions.Logging [![Build status](https://ci.appveyor.com/api/projects/status/865nohxfiq1rnby0/branch/master?svg=true)](https://ci.appveyor.com/project/serilog/serilog-framework-logging/history) [![NuGet Version](http://img.shields.io/nuget/v/Serilog.Extensions.Logging.svg?style=flat)](https://www.nuget.org/packages/Serilog.Extensions.Logging/) 
 
 
 A Serilog provider for [Microsoft.Extensions.Logging](https://www.nuget.org/packages/Microsoft.Extensions.Logging), the logging subsystem used by ASP.NET Core.
diff --git a/samples/WebSample/Controllers/HomeController.cs b/samples/WebSample/Controllers/HomeController.cs
@@ -4,22 +4,40 @@
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Mvc;
 using Serilog;
+using Microsoft.Extensions.Logging;
 
 namespace WebSample.Controllers
 {
     public class HomeController : Controller
     {
+        ILogger<HomeController> _logger;
+
+        public HomeController(ILogger<HomeController> logger)
+        {
+            _logger = logger;
+        }
+
         public IActionResult Index()
         {
-            Log.Information("Hello from the Index!");
+            _logger.LogInformation("Before");
+
+            using (_logger.BeginScope("Some name"))
+            using (_logger.BeginScope(42))
+            using (_logger.BeginScope("Formatted {WithValue}", 12345))
+            using (_logger.BeginScope(new Dictionary<string, object> { ["ViaDictionary"] = 100 }))
+            {
+                _logger.LogInformation("Hello from the Index!");
+            }
 
+            _logger.LogInformation("After");
             return View();
         }
 
         public IActionResult About()
         {
             ViewData["Message"] = "Your application description page.";
 
+            // Directly through Serilog
             Log.Information("This is a handler for {Path}", Request.Path);
 
             return View();
diff --git a/samples/WebSample/appsettings.json b/samples/WebSample/appsettings.json
@@ -12,7 +12,8 @@
     ],
     "WriteTo": [
       "Trace",
-      "LiterateConsole"
+      "LiterateConsole",
+      {"Name": "Seq", "Args": {"serverUrl": "http://localhost:5341" }}
     ]
   }
 }
diff --git a/samples/WebSample/project.json b/samples/WebSample/project.json
@@ -23,7 +23,8 @@
     "Serilog.Extensions.Logging": { "target": "project" },
     "Serilog.Settings.Configuration": "2.1.0-dev-00028",
     "Serilog.Sinks.Trace": "2.0.0",
-    "Serilog.Sinks.Literate": "2.0.0"
+    "Serilog.Sinks.Literate": "2.0.0",
+    "Serilog.Sinks.Seq": "3.1.1"
   },
 
   "tools": {
diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerProvider.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerProvider.cs
@@ -12,6 +12,8 @@
 using Serilog.Core;
 using Serilog.Events;
 using FrameworkLogger = Microsoft.Extensions.Logging.ILogger;
+using System.Collections.Generic;
+using Serilog.Context;
 
 namespace Serilog.Extensions.Logging
 {
@@ -21,6 +23,7 @@ namespace Serilog.Extensions.Logging
     public class SerilogLoggerProvider : ILoggerProvider, ILogEventEnricher
     {
         internal const string OriginalFormatPropertyName = "{OriginalFormat}";
+        internal const string ScopePropertyName = "Scope";
 
         // May be null; if it is, Log.Logger will be lazily used
         readonly ILogger _logger;
@@ -54,15 +57,36 @@ public FrameworkLogger CreateLogger(string name)
         /// <inheritdoc />
         public IDisposable BeginScope<T>(T state)
         {
-            return new SerilogLoggerScope(this, state);
+            if (CurrentScope != null)
+                return new SerilogLoggerScope(this, state);
+
+            // The outermost scope pushes and pops the Serilog `LogContext` - once
+            // this enricher is on the stack, the `CurrentScope` property takes care
+            // of the rest of the `BeginScope()` stack.
+            var popSerilogContext = LogContext.PushProperties(this);
+            return new SerilogLoggerScope(this, state, popSerilogContext);
         }
 
         /// <inheritdoc />
         public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
         {
+            List<LogEventPropertyValue> scopeItems = null;
             for (var scope = CurrentScope; scope != null; scope = scope.Parent)
             {
-                scope.Enrich(logEvent, propertyFactory);
+                LogEventPropertyValue scopeItem;
+                scope.EnrichAndCreateScopeItem(logEvent, propertyFactory, out scopeItem);
+
+                if (scopeItem != null)
+                {
+                    scopeItems = scopeItems ?? new List<LogEventPropertyValue>();
+                    scopeItems.Add(scopeItem);
+                }
+            }
+
+            if (scopeItems != null)
+            {
+                scopeItems.Reverse();
+                logEvent.AddPropertyIfAbsent(new LogEventProperty(ScopePropertyName, new SequenceValue(scopeItems)));
             }
         }
 
diff --git a/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs b/src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs
@@ -3,29 +3,30 @@
 
 using System;
 using System.Collections.Generic;
-using Serilog.Context;
 using Serilog.Core;
 using Serilog.Events;
 
 namespace Serilog.Extensions.Logging
 {
-    class SerilogLoggerScope : IDisposable, ILogEventEnricher
+    class SerilogLoggerScope : IDisposable
     {
+        const string NoName = "None";
+
         readonly SerilogLoggerProvider _provider;
         readonly object _state;
-        readonly IDisposable _popSerilogContext;
+        readonly IDisposable _chainedDisposable;
 
         // An optimization only, no problem if there are data races on this.
         bool _disposed;
 
-        public SerilogLoggerScope(SerilogLoggerProvider provider, object state)
+        public SerilogLoggerScope(SerilogLoggerProvider provider, object state, IDisposable chainedDisposable = null)
         {
             _provider = provider;
             _state = state;
 
             Parent = _provider.CurrentScope;
             _provider.CurrentScope = this;
-            _popSerilogContext = LogContext.PushProperties(this);
+            _chainedDisposable = chainedDisposable;
         }
 
         public SerilogLoggerScope Parent { get; }
@@ -44,24 +45,48 @@ public void Dispose()
                         _provider.CurrentScope = Parent;
                 }
 
-                _popSerilogContext.Dispose();
+                _chainedDisposable?.Dispose();
             }
         }
 
-        public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
+        public void EnrichAndCreateScopeItem(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, out LogEventPropertyValue scopeItem)
         {
+            if (_state == null)
+            {
+                scopeItem = null;
+                return;
+            }
+
             var stateProperties = _state as IEnumerable<KeyValuePair<string, object>>;
             if (stateProperties != null)
             {
+                scopeItem = null; // Unless it's `FormattedLogValues`, these are treated as property bags rather than scope items.
+
                 foreach (var stateProperty in stateProperties)
                 {
                     if (stateProperty.Key == SerilogLoggerProvider.OriginalFormatPropertyName && stateProperty.Value is string)
+                    {
+                        scopeItem = new ScalarValue(_state.ToString());
                         continue;
+                    }
+
+                    var key = stateProperty.Key;
+                    var destructureObject = false;
 
-                    var property = propertyFactory.CreateProperty(stateProperty.Key, stateProperty.Value);
+                    if (key.StartsWith("@"))
+                    {
+                        key = key.Substring(1);
+                        destructureObject = true;
+                    }
+                    
+                    var property = propertyFactory.CreateProperty(key, stateProperty.Value, destructureObject);
                     logEvent.AddPropertyIfAbsent(property);
                 }
             }
+            else
+            {
+                scopeItem = propertyFactory.CreateProperty(NoName, _state).Value;
+            }
         }
     }
 }
diff --git a/src/Serilog.Extensions.Logging/project.json b/src/Serilog.Extensions.Logging/project.json
@@ -1,5 +1,5 @@
 {
-  "version": "1.2.0-*",
+  "version": "1.3.0-*",
   "description": "Serilog provider for Microsoft.Extensions.Logging",
   "authors": [ "Microsoft", "Serilog Contributors" ],
   "packOptions": {
@@ -21,6 +21,12 @@
     "net4.5": {
       "dependencies": { "System.Runtime": "4.0.0" }
     },
+    "net4.6": {
+      "dependencies": { "System.Runtime": "4.0.20" },
+      "buildOptions": {
+        "define": [ "ASYNCLOCAL" ]
+      }
+    },
     "netstandard1.3": {
       "buildOptions": {
         "define": ["ASYNCLOCAL"]
diff --git a/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs b/test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs
@@ -288,6 +288,106 @@ public void WhenDisposeIsTrueProvidedLoggerIsDisposed()
             Assert.True(logger.IsDisposed);
         }
 
+        [Fact]
+        public void BeginScopeDestructuresObjectsWhenDestructurerIsUsedInMessageTemplate()
+        {
+            var t = SetUp(LogLevel.Trace);
+            var logger = t.Item1;
+            var sink = t.Item2;
+
+            using (logger.BeginScope("{@Person}", new Person { FirstName = "John", LastName = "Smith" }))
+            {
+                logger.Log(LogLevel.Information, 0, TestMessage, null, null);
+            }
+
+            Assert.Equal(1, sink.Writes.Count);
+            Assert.True(sink.Writes[0].Properties.ContainsKey("Person"));
+
+            var person = (StructureValue)sink.Writes[0].Properties["Person"];
+            var firstName = (ScalarValue)person.Properties.Single(p => p.Name == "FirstName").Value;
+            var lastName = (ScalarValue)person.Properties.Single(p => p.Name == "LastName").Value;
+            Assert.Equal("John", firstName.Value);
+            Assert.Equal("Smith", lastName.Value);
+        }
+
+        [Fact]
+        public void BeginScopeDestructuresObjectsWhenDestructurerIsUsedInDictionary()
+        {
+            var t = SetUp(LogLevel.Trace);
+            var logger = t.Item1;
+            var sink = t.Item2;
+            
+            using (logger.BeginScope(new Dictionary<string, object> {{ "@Person", new Person { FirstName = "John", LastName = "Smith" }}}))
+            {
+                logger.Log(LogLevel.Information, 0, TestMessage, null, null);
+            }
+
+            Assert.Equal(1, sink.Writes.Count);
+            Assert.True(sink.Writes[0].Properties.ContainsKey("Person"));
+
+            var person = (StructureValue)sink.Writes[0].Properties["Person"];
+            var firstName = (ScalarValue)person.Properties.Single(p => p.Name == "FirstName").Value;
+            var lastName = (ScalarValue)person.Properties.Single(p => p.Name == "LastName").Value;
+            Assert.Equal("John", firstName.Value);
+            Assert.Equal("Smith", lastName.Value);
+        }
+
+        [Fact]
+        public void BeginScopeDoesNotModifyKeyWhenDestructurerIsNotUsedInMessageTemplate()
+        {
+            var t = SetUp(LogLevel.Trace);
+            var logger = t.Item1;
+            var sink = t.Item2;
+
+            using (logger.BeginScope("{FirstName}", "John"))
+            {
+                logger.Log(LogLevel.Information, 0, TestMessage, null, null);
+            }
+
+            Assert.Equal(1, sink.Writes.Count);
+            Assert.True(sink.Writes[0].Properties.ContainsKey("FirstName"));
+        }
+
+        [Fact]
+        public void BeginScopeDoesNotModifyKeyWhenDestructurerIsNotUsedInDictionary()
+        {
+            var t = SetUp(LogLevel.Trace);
+            var logger = t.Item1;
+            var sink = t.Item2;
+
+            using (logger.BeginScope(new Dictionary<string, object> { { "FirstName", "John"}}))
+            {
+                logger.Log(LogLevel.Information, 0, TestMessage, null, null);
+            }
+
+            Assert.Equal(1, sink.Writes.Count);
+            Assert.True(sink.Writes[0].Properties.ContainsKey("FirstName"));
+        }
+
+        [Fact]
+        public void NamedScopesAreCaptured()
+        {
+            var t = SetUp(LogLevel.Trace);
+            var logger = t.Item1;
+            var sink = t.Item2;
+
+            using (logger.BeginScope("Outer"))
+            using (logger.BeginScope("Inner"))
+            {
+                logger.Log(LogLevel.Information, 0, TestMessage, null, null);
+            }
+
+            Assert.Equal(1, sink.Writes.Count);
+
+            LogEventPropertyValue scopeValue;
+            Assert.True(sink.Writes[0].Properties.TryGetValue(SerilogLoggerProvider.ScopePropertyName, out scopeValue));
+
+            var items = (scopeValue as SequenceValue)?.Elements.Select(e => ((ScalarValue)e).Value).Cast<string>().ToArray();
+            Assert.Equal(2, items.Length);
+            Assert.Equal("Outer", items[0]);
+            Assert.Equal("Inner", items[1]);
+        }
+
         private class FoodScope : IEnumerable<KeyValuePair<string, object>>
         {
             readonly string _name;
@@ -327,5 +427,11 @@ IEnumerator IEnumerable.GetEnumerator()
                 return GetEnumerator();
             }
         }
+
+        private class Person
+        {
+            public string FirstName { get; set; }
+            public string LastName { get; set; }
+        }
     }
 }

Original file line number	Diff line number	Diff line change
`@@ -12,7 +12,8 @@`
`12`	`12`	`],`
`13`	`13`	`"WriteTo": [`
`14`	`14`	`"Trace",`
`15`		`- "LiterateConsole"`
	`15`	`+ "LiterateConsole",`
	`16`	`+ {"Name": "Seq", "Args": {"serverUrl": "http://localhost:5341" }}`
`16`	`17`	`]`
`17`	`18`	`}`
`18`	`19`	`}`
Original file line number	Diff line number	Diff line change
`@@ -3,29 +3,30 @@`
`3`	`3`
`4`	`4`	`using System;`
`5`	`5`	`using System.Collections.Generic;`
`6`		`-using Serilog.Context;`
`7`	`6`	`using Serilog.Core;`
`8`	`7`	`using Serilog.Events;`
`9`	`8`
`10`	`9`	`namespace Serilog.Extensions.Logging`
`11`	`10`	`{`
`12`		`- class SerilogLoggerScope : IDisposable, ILogEventEnricher`
	`11`	`+ class SerilogLoggerScope : IDisposable`
`13`	`12`	`{`
	`13`	`+ const string NoName = "None";`
	`14`	`+`
`14`	`15`	`readonly SerilogLoggerProvider _provider;`
`15`	`16`	`readonly object _state;`
`16`		`- readonly IDisposable _popSerilogContext;`
	`17`	`+ readonly IDisposable _chainedDisposable;`
`17`	`18`
`18`	`19`	`// An optimization only, no problem if there are data races on this.`
`19`	`20`	`bool _disposed;`
`20`	`21`
`21`		`- public SerilogLoggerScope(SerilogLoggerProvider provider, object state)`
	`22`	`+ public SerilogLoggerScope(SerilogLoggerProvider provider, object state, IDisposable chainedDisposable = null)`
`22`	`23`	`{`
`23`	`24`	`_provider = provider;`
`24`	`25`	`_state = state;`
`25`	`26`
`26`	`27`	`Parent = _provider.CurrentScope;`
`27`	`28`	`_provider.CurrentScope = this;`
`28`		`- _popSerilogContext = LogContext.PushProperties(this);`
	`29`	`+ _chainedDisposable = chainedDisposable;`
`29`	`30`	`}`
`30`	`31`
`31`	`32`	`public SerilogLoggerScope Parent { get; }`
`@@ -44,24 +45,48 @@ public void Dispose()`
`44`	`45`	`_provider.CurrentScope = Parent;`
`45`	`46`	`}`
`46`	`47`
`47`		`- _popSerilogContext.Dispose();`
	`48`	`+ _chainedDisposable?.Dispose();`
`48`	`49`	`}`
`49`	`50`	`}`
`50`	`51`
`51`		`- public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)`
	`52`	`+ public void EnrichAndCreateScopeItem(LogEvent logEvent, ILogEventPropertyFactory propertyFactory, out LogEventPropertyValue scopeItem)`
`52`	`53`	`{`
	`54`	`+ if (_state == null)`
	`55`	`+ {`
	`56`	`+ scopeItem = null;`
	`57`	`+ return;`
	`58`	`+ }`
	`59`	`+`
`53`	`60`	`var stateProperties = _state as IEnumerable<KeyValuePair<string, object>>;`
`54`	`61`	`if (stateProperties != null)`
`55`	`62`	`{`
	`63`	+ scopeItem = null; // Unless it's `FormattedLogValues`, these are treated as property bags rather than scope items.
	`64`	`+`
`56`	`65`	`foreach (var stateProperty in stateProperties)`
`57`	`66`	`{`
`58`	`67`	`if (stateProperty.Key == SerilogLoggerProvider.OriginalFormatPropertyName && stateProperty.Value is string)`
	`68`	`+ {`
	`69`	`+ scopeItem = new ScalarValue(_state.ToString());`
`59`	`70`	`continue;`
	`71`	`+ }`
	`72`	`+`
	`73`	`+ var key = stateProperty.Key;`
	`74`	`+ var destructureObject = false;`
`60`	`75`
`61`		`- var property = propertyFactory.CreateProperty(stateProperty.Key, stateProperty.Value);`
	`76`	`+ if (key.StartsWith("@"))`
	`77`	`+ {`
	`78`	`+ key = key.Substring(1);`
	`79`	`+ destructureObject = true;`
	`80`	`+ }`
	`81`	`+`
	`82`	`+ var property = propertyFactory.CreateProperty(key, stateProperty.Value, destructureObject);`
`62`	`83`	`logEvent.AddPropertyIfAbsent(property);`
`63`	`84`	`}`
`64`	`85`	`}`
	`86`	`+ else`
	`87`	`+ {`
	`88`	`+ scopeItem = propertyFactory.CreateProperty(NoName, _state).Value;`
	`89`	`+ }`
`65`	`90`	`}`
`66`	`91`	`}`
`67`	`92`	`}`