Merge pull request #246 from david-obee/support-external-scopes

Implement `ISupportExternalScope` in `SerilogLoggerProvider`

Author: nblumhardt

samples/SampleWithExternalScope/Program.cs

@@ -0,0 +1,56 @@
+using System.Diagnostics;
+using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Logging;
+using Serilog;
+using Serilog.Formatting.Json;
+
+// Configure a JsonFormatter to log out scope to the console
+Log.Logger = new LoggerConfiguration()
+    .MinimumLevel.Debug()
+    .WriteTo.Console(new JsonFormatter())
+    .CreateLogger();
+
+// Setup Serilog with M.E.L, and configure the appropriate ActivityTrackingOptions
+var services = new ServiceCollection();
+
+services.AddLogging(l => l
+    .AddSerilog()
+    .Configure(options =>
+    {
+        options.ActivityTrackingOptions =
+            ActivityTrackingOptions.SpanId
+            | ActivityTrackingOptions.TraceId
+            | ActivityTrackingOptions.ParentId
+            | ActivityTrackingOptions.TraceState
+            | ActivityTrackingOptions.TraceFlags
+            | ActivityTrackingOptions.Tags
+            | ActivityTrackingOptions.Baggage;
+    }));
+
+// Add an ActivityListener (required, otherwise Activities don't actually get created if nothing is listening to them)
+ActivitySource.AddActivityListener(new ActivityListener
+{
+    ShouldListenTo = source => true,
+    Sample = (ref ActivityCreationOptions<ActivityContext> options) => ActivitySamplingResult.AllDataAndRecorded
+});
+
+// Run our test
+var activitySource = new ActivitySource("SomeActivitySource");
+
+var serviceProvider = services.BuildServiceProvider();
+var logger = serviceProvider.GetRequiredService<ILogger<Program>>();
+
+using var activity = activitySource.StartActivity();
+
+activity?.SetTag("tag.domain.id", 1234);
+activity?.SetBaggage("baggage.environment", "uat");
+
+using var scope = logger.BeginScope(new
+{
+    User = "Hugh Mann",
+    Time = DateTimeOffset.UtcNow
+});
+
+logger.LogInformation("Hello world!");
+
+serviceProvider.Dispose();

samples/SampleWithExternalScope/SampleWithExternalScope.csproj

@@ -0,0 +1,21 @@
+<Project Sdk="Microsoft.NET.Sdk">
+
+  <PropertyGroup>
+    <OutputType>Exe</OutputType>
+    <TargetFramework>net8.0</TargetFramework>
+    <ImplicitUsings>enable</ImplicitUsings>
+    <OutputType>Exe</OutputType>
+    <Nullable>enable</Nullable>
+  </PropertyGroup>
+
+  <ItemGroup>
+    <ProjectReference Include="..\..\src\Serilog.Extensions.Logging\Serilog.Extensions.Logging.csproj" />
+  </ItemGroup>
+
+  <ItemGroup>
+    <PackageReference Include="Microsoft.Extensions.DependencyInjection" Version="8.0.0" />
+    <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="8.0.0" />
+    <PackageReference Include="Serilog.Sinks.Console" Version="5.0.0" />
+  </ItemGroup>
+
+</Project>

serilog-extensions-logging.sln

@@ -31,6 +31,8 @@ Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "assets", "assets", "{9C21B9
 EndProject
 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Serilog.Extensions.Logging.Benchmarks", "test\Serilog.Extensions.Logging.Benchmarks\Serilog.Extensions.Logging.Benchmarks.csproj", "{6D5986FF-EECD-4E75-8BC6-A5F78AB549B2}"
 EndProject
+Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "SampleWithExternalScope", "samples\SampleWithExternalScope\SampleWithExternalScope.csproj", "{653092A8-CBAD-40AA-A4CE-F8B19D6492C2}"
+EndProject
 Global
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
 		Debug|Any CPU = Debug|Any CPU
@@ -53,6 +55,10 @@ Global
 		{6D5986FF-EECD-4E75-8BC6-A5F78AB549B2}.Debug|Any CPU.Build.0 = Debug|Any CPU
 		{6D5986FF-EECD-4E75-8BC6-A5F78AB549B2}.Release|Any CPU.ActiveCfg = Release|Any CPU
 		{6D5986FF-EECD-4E75-8BC6-A5F78AB549B2}.Release|Any CPU.Build.0 = Release|Any CPU
+		{653092A8-CBAD-40AA-A4CE-F8B19D6492C2}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{653092A8-CBAD-40AA-A4CE-F8B19D6492C2}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{653092A8-CBAD-40AA-A4CE-F8B19D6492C2}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{653092A8-CBAD-40AA-A4CE-F8B19D6492C2}.Release|Any CPU.Build.0 = Release|Any CPU
 	EndGlobalSection
 	GlobalSection(SolutionProperties) = preSolution
 		HideSolutionNode = FALSE
@@ -62,6 +68,7 @@ Global
 		{37EADF84-5E41-4224-A194-1E3299DCD0B8} = {E30F638E-BBBE-4AD1-93CE-48CC69CFEFE1}
 		{65357FBC-9BC4-466D-B621-1C3A19BC2A78} = {F2407211-6043-439C-8E06-3641634332E7}
 		{6D5986FF-EECD-4E75-8BC6-A5F78AB549B2} = {E30F638E-BBBE-4AD1-93CE-48CC69CFEFE1}
+		{653092A8-CBAD-40AA-A4CE-F8B19D6492C2} = {F2407211-6043-439C-8E06-3641634332E7}
 	EndGlobalSection
 	GlobalSection(ExtensibilityGlobals) = postSolution
 		SolutionGuid = {811E61C5-3871-4633-AFAE-B35B619C8A10}

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

@@ -13,14 +13,15 @@ namespace Serilog.Extensions.Logging;
 /// An <see cref="ILoggerProvider"/> that pipes events through Serilog.
 /// </summary>
 [ProviderAlias("Serilog")]
-public class SerilogLoggerProvider : ILoggerProvider, ILogEventEnricher
+public class SerilogLoggerProvider : ILoggerProvider, ILogEventEnricher, ISupportExternalScope
 {
     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;
     readonly Action? _dispose;
+    private IExternalScopeProvider? _externalScopeProvider;
 
     /// <summary>
     /// Construct a <see cref="SerilogLoggerProvider"/>.
@@ -75,13 +76,32 @@ public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
             }
         }
 
+        _externalScopeProvider?.ForEachScope((state, accumulatingLogEvent) =>
+        {
+            var scope = new SerilogLoggerScope(this, state);
+
+            scope.EnrichAndCreateScopeItem(accumulatingLogEvent, propertyFactory, out var scopeItem);
+
+            if (scopeItem != null)
+            {
+                scopeItems ??= new List<LogEventPropertyValue>();
+                scopeItems.Add(scopeItem);
+            }
+        }, logEvent);
+
         if (scopeItems != null)
         {
             scopeItems.Reverse();
             logEvent.AddPropertyIfAbsent(new LogEventProperty(ScopePropertyName, new SequenceValue(scopeItems)));
         }
     }
 
+    /// <inheritdoc />
+    public void SetScopeProvider(IExternalScopeProvider scopeProvider)
+    {
+        _externalScopeProvider = scopeProvider;
+    }
+
     readonly AsyncLocal<SerilogLoggerScope?> _value = new();
 
     internal SerilogLoggerScope? CurrentScope

test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs

@@ -17,7 +17,7 @@ public class SerilogLoggerTest
     const string Name = "test";
     const string TestMessage = "This is a test";
 
-    static Tuple<SerilogLogger, SerilogSink> SetUp(LogLevel logLevel)
+    static Tuple<SerilogLogger, SerilogSink> SetUp(LogLevel logLevel, IExternalScopeProvider? externalScopeProvider = null)
     {
         var sink = new SerilogSink();
 
@@ -29,6 +29,11 @@ static Tuple<SerilogLogger, SerilogSink> SetUp(LogLevel logLevel)
         var provider = new SerilogLoggerProvider(serilogLogger);
         var logger = (SerilogLogger)provider.CreateLogger(Name);
 
+        if (externalScopeProvider is not null)
+        {
+            provider.SetScopeProvider(externalScopeProvider);
+        }
+
         return new Tuple<SerilogLogger, SerilogSink>(logger, sink);
     }
 
@@ -397,6 +402,35 @@ public void NamedScopesAreCaptured()
         Assert.Equal("Inner", items[1]);
     }
 
+    [Fact]
+    public void ExternalScopesAreCaptured()
+    {
+        var externalScopeProvider = new FakeExternalScopeProvider();
+        var (logger, sink) = SetUp(LogLevel.Trace, externalScopeProvider);
+
+        externalScopeProvider.Push(new Dictionary<string, int>()
+        {
+            { "FirstKey", 1 },
+            { "SecondKey", 2 }
+        });
+
+        var scopeObject = new { ObjectKey = "Some value" };
+        externalScopeProvider.Push(scopeObject);
+
+        logger.Log(LogLevel.Information, 0, TestMessage, null!, null!);
+
+        Assert.Single(sink.Writes);
+        Assert.True(sink.Writes[0].Properties.TryGetValue(SerilogLoggerProvider.ScopePropertyName, out var scopeValue));
+        var sequence = Assert.IsType<SequenceValue>(scopeValue);
+
+        var objectScope = (ScalarValue) sequence.Elements.Single(e => e is ScalarValue);
+        Assert.Equal(scopeObject.ToString(), (string?)objectScope.Value);
+
+        var dictionaryScope = (DictionaryValue) sequence.Elements.Single(e => e is DictionaryValue);
+        Assert.Equal(1, ((ScalarValue)dictionaryScope.Elements.Single(pair => pair.Key.Value!.Equals("FirstKey")).Value).Value);
+        Assert.Equal(2, ((ScalarValue)dictionaryScope.Elements.Single(pair => pair.Key.Value!.Equals("SecondKey")).Value).Value);
+    }
+
     class FoodScope : IEnumerable<KeyValuePair<string, object>>
     {
         readonly string _name;
@@ -446,6 +480,43 @@ class Person
         public string? LastName { get; set; }
     }
 
+    class FakeExternalScopeProvider : IExternalScopeProvider
+    {
+        private readonly List<Scope> _scopes = new List<Scope>();
+
+        public void ForEachScope<TState>(Action<object?, TState> callback, TState state)
+        {
+            foreach (var scope in _scopes)
+            {
+                if (scope.IsDisposed) continue;
+                callback(scope.Value, state);
+            }
+        }
+
+        public IDisposable Push(object? state)
+        {
+            var scope = new Scope(state);
+            _scopes.Add(scope);
+            return scope;
+        }
+
+        private class Scope : IDisposable
+        {
+            public bool IsDisposed { get; set; } = false;
+            public object? Value { get; set; }
+
+            public Scope(object? value)
+            {
+                Value = value;
+            }
+
+            public void Dispose()
+            {
+                IsDisposed = true;
+            }
+        }
+    }
+
     [Theory]
     [InlineData(1)]
     [InlineData(10)]