Merge pull request #192 from serilog/dev

3.1.0 Release

README.md

@@ -1,11 +1,14 @@
 # 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.
 
-### ASP.NET Core 2.0+ Instructions
+### ASP.NET Core Instructions
+
+**ASP.NET Core** applications should prefer [Serilog.AspNetCore](https://github.com/serilog/serilog-aspnetcore) and `UseSerilog()` instead.
 
-**ASP.NET Core 2.0** applications should prefer [Serilog.AspNetCore](https://github.com/serilog/serilog-aspnetcore) and `UseSerilog()` instead.
+### Non-web .NET Core Instructions
+
+**Non-web .NET Core** applications should prefer [Serilog.Extensions.Hosting](https://github.com/serilog/serilog-extensions-hosting) and `UseSerilog()` instead.
 
 ### .NET Core 1.0, 1.1 and Default Provider Integration
 
@@ -77,6 +80,69 @@ That's it! With the level bumped up a little you should see log output like:
 [22:14:45.741 DBG] Handled. Status code: 304 File: /css/site.css
 ```
 
+### Notes on Log Scopes
+
+_Microsoft.Extensions.Logging_ provides the `BeginScope` API, which can be used to add arbitrary properties to log events within a certain region of code. The API comes in two forms:
+
+1. The method: `IDisposable BeginScope<TState>(TState state)`
+2. The extension method: `IDisposable BeginScope(this ILogger logger, string messageFormat, params object[] args)`
+
+Using the extension method will add a `Scope` property to your log events. This is most useful for adding simple "scope strings" to your events, as in the following code:
+
+```cs
+using (_logger.BeginScope("Transaction")) {
+    _logger.LogInformation("Beginning...");
+    _logger.LogInformation("Completed in {DurationMs}ms...", 30);
+}
+// Example JSON output:
+// {"@t":"2020-10-29T19:05:56.4126822Z","@m":"Beginning...","@i":"f6a328e9","SourceContext":"SomeNamespace.SomeService","Scope":["Transaction"]}
+// {"@t":"2020-10-29T19:05:56.4176816Z","@m":"Completed in 30ms...","@i":"51812baa","DurationMs":30,"SourceContext":"SomeNamespace.SomeService","Scope":["Transaction"]}
+```
+
+If you simply want to add a "bag" of additional properties to your log events, however, this extension method approach can be overly verbose. For example, to add `TransactionId` and `ResponseJson` properties to your log events, you would have to do something like the following:
+
+```cs
+// WRONG! Prefer the dictionary approach below instead
+using (_logger.BeginScope("TransactionId: {TransactionId}, ResponseJson: {ResponseJson}", 12345, jsonString)) {
+    _logger.LogInformation("Completed in {DurationMs}ms...", 30);
+}
+// Example JSON output:
+// {
+//	"@t":"2020-10-29T19:05:56.4176816Z",
+//	"@m":"Completed in 30ms...",
+//	"@i":"51812baa",
+//	"DurationMs":30,
+//	"SourceContext":"SomeNamespace.SomeService",
+//	"TransactionId": 12345,
+//	"ResponseJson": "{ \"Key1\": \"Value1\", \"Key2\": \"Value2\" }",
+//	"Scope":["TransactionId: 12345, ResponseJson: { \"Key1\": \"Value1\", \"Key2\": \"Value2\" }"]
+// }
+```
+
+Not only does this add the unnecessary `Scope` property to your event, but it also duplicates serialized values between `Scope` and the intended properties, as you can see here with `ResponseJson`. If this were "real" JSON like an API response, then a potentially very large block of text would be duplicated within your log event! Moreover, the template string within `BeginScope` is rather arbitrary when all you want to do is add a bag of properties, and you start mixing enriching concerns with formatting concerns.
+
+A far better alternative is to use the `BeginScope<TState>(TState state)` method. If you provide any `IEnumerable<KeyValuePair<string, object>>` to this method, then Serilog will output the key/value pairs as structured properties _without_ the `Scope` property, as in this example:
+
+```cs
+var scopeProps = new Dictionary<string, object> {
+    { "TransactionId", 12345 },
+    { "ResponseJson", jsonString },
+};
+using (_logger.BeginScope(scopeProps) {
+    _logger.LogInformation("Transaction completed in {DurationMs}ms...", 30);
+}
+// Example JSON output:
+// {
+//	"@t":"2020-10-29T19:05:56.4176816Z",
+//	"@m":"Completed in 30ms...",
+//	"@i":"51812baa",
+//	"DurationMs":30,
+//	"SourceContext":"SomeNamespace.SomeService",
+//	"TransactionId": 12345,
+//	"ResponseJson": "{ \"Key1\": \"Value1\", \"Key2\": \"Value2\" }"
+// }
+```
+
 ### Credits
 
 This package evolved from an earlier package _Microsoft.Framework.Logging.Serilog_ [provided by the ASP.NET team](https://github.com/aspnet/Logging/pull/182).

appveyor.yml

@@ -1,13 +1,8 @@
 version: '{build}'
 skip_tags: true
 image: Visual Studio 2019
-configuration: Release
 install:
   - ps: mkdir -Force ".\build\" | Out-Null
-  #- ps: Invoke-WebRequest "https://raw.githubusercontent.com/dotnet/cli/release/2.0.0/scripts/obtain/dotnet-install.ps1" -OutFile ".\build\installcli.ps1"
-  #- ps: $env:DOTNET_INSTALL_DIR = "$pwd\.dotnetcli"
-  #- ps: '& .\build\installcli.ps1 -InstallDir "$env:DOTNET_INSTALL_DIR" -NoPath -Version 2.0.0-preview2-006497'
-  #- ps: $env:Path = "$env:DOTNET_INSTALL_DIR;$env:Path"
 build_script:
 - ps: ./Build.ps1
 test: off
@@ -16,7 +11,7 @@ artifacts:
 deploy:
 - provider: NuGet
   api_key:
-    secure: N59tiJECUYpip6tEn0xvdmDAEiP9SIzyLEFLpwiigm/8WhJvBNs13QxzT1/3/JW/
+    secure: kYR3BYzJm3wSFbFjPhgTzuDHHcE8ApoNUmHvJvunWZ39nyrqVk6J6srjzYVQ7/gX
   skip_symbols: true
   on:
     branch: /^(master|dev)$/

global.json

@@ -1,5 +1,7 @@
 {
   "sdk": {
-    "version": "2.2.103"
+    "allowPrerelease": false,
+    "version": "3.1.100",
+    "rollForward": "latestFeature"
   }
 }

serilog-extensions-logging.sln.DotSettings

@@ -8,4 +8,5 @@
 	<s:Boolean x:Key="/Default/UserDictionary/Words/=Loggable/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/UserDictionary/Words/=Nonscalar/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/UserDictionary/Words/=Serilog/@EntryIndexedValue">True</s:Boolean>
-	<s:Boolean x:Key="/Default/UserDictionary/Words/=sobj/@EntryIndexedValue">True</s:Boolean></wpf:ResourceDictionary>
+	<s:Boolean x:Key="/Default/UserDictionary/Words/=sobj/@EntryIndexedValue">True</s:Boolean>
+	<s:Boolean x:Key="/Default/UserDictionary/Words/=Stringification/@EntryIndexedValue">True</s:Boolean></wpf:ResourceDictionary>

src/Serilog.Extensions.Logging/Extensions/Logging/CachingMessageTemplateParser.cs

@@ -0,0 +1,67 @@
+// Copyright (c) Serilog Contributors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+
+using System;
+using Serilog.Events;
+using Serilog.Parsing;
+using System.Collections;
+
+namespace Serilog.Extensions.Logging
+{
+    class CachingMessageTemplateParser
+    {
+        readonly MessageTemplateParser _innerParser = new MessageTemplateParser();
+
+        readonly object _templatesLock = new object();
+        readonly Hashtable _templates = new Hashtable();
+
+        const int MaxCacheItems = 1000;
+        const int MaxCachedTemplateLength = 1024;
+
+        public MessageTemplate Parse(string messageTemplate)
+        {
+            if (messageTemplate == null) throw new ArgumentNullException(nameof(messageTemplate));
+
+            if (messageTemplate.Length > MaxCachedTemplateLength)
+                return _innerParser.Parse(messageTemplate);
+
+            // ReSharper disable once InconsistentlySynchronizedField
+            // ignored warning because this is by design
+            var result = (MessageTemplate)_templates[messageTemplate];
+            if (result != null)
+                return result;
+
+            result = _innerParser.Parse(messageTemplate);
+
+            lock (_templatesLock)
+            {
+                // Exceeding MaxCacheItems is *not* the sunny day scenario; all we're doing here is preventing out-of-memory
+                // conditions when the library is used incorrectly. Correct use (templates, rather than
+                // direct message strings) should barely, if ever, overflow this cache.
+
+                // Changing workloads through the lifecycle of an app instance mean we can gain some ground by
+                // potentially dropping templates generated only in startup, or only during specific infrequent
+                // activities.
+
+                if (_templates.Count == MaxCacheItems)
+                    _templates.Clear();
+
+                _templates[messageTemplate] = result;
+            }
+
+            return result;
+        }
+    }
+}

src/Serilog.Extensions.Logging/Extensions/Logging/LoggerProviderCollection.cs

@@ -26,7 +26,7 @@ namespace Serilog.Extensions.Logging
     /// </summary>
     public class LoggerProviderCollection : IDisposable
     {
-        volatile ILoggerProvider[] _providers = new ILoggerProvider[0];
+        volatile ILoggerProvider[] _providers = Array.Empty<ILoggerProvider>();
 
         /// <summary>
         /// Add <paramref name="provider"/> to the collection.
@@ -36,16 +36,16 @@ public void AddProvider(ILoggerProvider provider)
         {
             if (provider == null) throw new ArgumentNullException(nameof(provider));
 
-            var existing = _providers;
-            var added = existing.Concat(new[] {provider}).ToArray();
+            ILoggerProvider[] existing, added;
 
-#pragma warning disable 420 // ref to a volatile field
-            while (Interlocked.CompareExchange(ref _providers, added, existing) != existing)
-#pragma warning restore 420
+            do
             {
                 existing = _providers;
                 added = existing.Concat(new[] { provider }).ToArray();
             }
+#pragma warning disable 420 // ref to a volatile field
+            while (Interlocked.CompareExchange(ref _providers, added, existing) != existing);
+#pragma warning restore 420
         }
 
         /// <summary>

src/Serilog.Extensions.Logging/Extensions/Logging/LoggerProviderCollectionSink.cs

@@ -13,6 +13,7 @@
 // limitations under the License.
 
 using System;
+using Microsoft.Extensions.Logging;
 using Serilog.Core;
 using Serilog.Events;
 
@@ -30,13 +31,26 @@ public LoggerProviderCollectionSink(LoggerProviderCollection providers)
         public void Emit(LogEvent logEvent)
         {
             string categoryName = null;
+            EventId eventId = default;
 
             if (logEvent.Properties.TryGetValue("SourceContext", out var sourceContextProperty) &&
                 sourceContextProperty is ScalarValue sourceContextValue &&
                 sourceContextValue.Value is string sourceContext)
             {
                 categoryName = sourceContext;
             }
+            if (logEvent.Properties.TryGetValue("EventId", out var eventIdPropertyValue) && eventIdPropertyValue is StructureValue structuredEventId)
+            {
+                string name = null;
+                var id = 0;
+                foreach (var item in structuredEventId.Properties)
+                {
+                    if (item.Name == "Id" && item.Value is ScalarValue sv && sv.Value is int i) id = i;
+                    if (item.Name == "Name" && item.Value is ScalarValue sv2 && sv2.Value is string s) name = s;
+                }
+
+                eventId = new EventId(id, name);
+            }
 
             var level = LevelConvert.ToExtensionsLevel(logEvent.Level);
             var slv = new SerilogLogValues(logEvent.MessageTemplate, logEvent.Properties);
@@ -47,7 +61,7 @@ sourceContextProperty is ScalarValue sourceContextValue &&
 
                 logger.Log(
                     level,
-                    default, 
+                    eventId,
                     slv,
                     logEvent.Exception,
                     (s, e) => s.ToString());

src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs

@@ -9,7 +9,7 @@
 using Serilog.Events;
 using FrameworkLogger = Microsoft.Extensions.Logging.ILogger;
 using System.Reflection;
-using Serilog.Parsing;
+using Serilog.Debugging;
 
 namespace Serilog.Extensions.Logging
 {
@@ -18,7 +18,7 @@ class SerilogLogger : FrameworkLogger
         readonly SerilogLoggerProvider _provider;
         readonly ILogger _logger;
 
-        static readonly MessageTemplateParser MessageTemplateParser = new MessageTemplateParser();
+        static readonly CachingMessageTemplateParser MessageTemplateParser = new CachingMessageTemplateParser();
 
         // It's rare to see large event ids, as they are category-specific
         static readonly LogEventProperty[] LowEventIdValues = Enumerable.Range(0, 48)
@@ -60,6 +60,18 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
                 return;
             }
 
+            try
+            {
+                Write(level, eventId, state, exception, formatter);
+            }
+            catch (Exception ex)
+            {
+                SelfLog.WriteLine($"Failed to write event through {typeof(SerilogLogger).Name}: {ex}");
+            }
+        }
+
+        void Write<TState>(LogEventLevel level, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
+        {
             var logger = _logger;
             string messageTemplate = null;
 
@@ -78,6 +90,11 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
                         if (logger.BindProperty(property.Key.Substring(1), property.Value, true, out var destructured))
                             properties.Add(destructured);
                     }
+                    else if (property.Key.StartsWith("$"))
+                    {
+                        if (logger.BindProperty(property.Key.Substring(1), property.Value?.ToString(), true, out var stringified))
+                            properties.Add(stringified);
+                    }
                     else
                     {
                         if (logger.BindProperty(property.Key, property.Value, false, out var bound))
@@ -154,4 +171,4 @@ internal static LogEventProperty CreateEventIdProperty(EventId eventId)
             return new LogEventProperty("EventId", new StructureValue(properties));
         }
     }
-}
+}

src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerProvider.cs

@@ -69,8 +69,7 @@ public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
             List<LogEventPropertyValue> scopeItems = null;
             for (var scope = CurrentScope; scope != null; scope = scope.Parent)
             {
-                LogEventPropertyValue scopeItem;
-                scope.EnrichAndCreateScopeItem(logEvent, propertyFactory, out scopeItem);
+                scope.EnrichAndCreateScopeItem(logEvent, propertyFactory, out LogEventPropertyValue scopeItem);
 
                 if (scopeItem != null)
                 {

src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLoggerScope.cs

@@ -57,8 +57,7 @@ public void EnrichAndCreateScopeItem(LogEvent logEvent, ILogEventPropertyFactory
                 return;
             }
 
-            var stateProperties = _state as IEnumerable<KeyValuePair<string, object>>;
-            if (stateProperties != null)
+            if (_state is IEnumerable<KeyValuePair<string, object>> stateProperties)
             {
                 scopeItem = null; // Unless it's `FormattedLogValues`, these are treated as property bags rather than scope items.
 
@@ -72,14 +71,21 @@ public void EnrichAndCreateScopeItem(LogEvent logEvent, ILogEventPropertyFactory
 
                     var key = stateProperty.Key;
                     var destructureObject = false;
+                    var value = stateProperty.Value;
 
                     if (key.StartsWith("@"))
                     {
                         key = key.Substring(1);
                         destructureObject = true;
                     }
-
-                    var property = propertyFactory.CreateProperty(key, stateProperty.Value, destructureObject);
+
+                    if (key.StartsWith("$"))
+                    {
+                        key = key.Substring(1);
+                        value = value?.ToString();
+                    }
+
+                    var property = propertyFactory.CreateProperty(key, value, destructureObject);
                     logEvent.AddPropertyIfAbsent(property);
                 }
             }