Deferred Log Dispatcher

src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs

@@ -17,5 +17,7 @@ public class DeferredLogEntry
         public Exception Exception { get; set; }
 
         public EventId EventId { get; set; }
+
+        public string Scope { get; set; }
     }
 }

src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs

@@ -0,0 +1,75 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using System;
+using System.Collections.Generic;
+using System.Threading.Channels;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics
+{
+    /// <summary>
+    /// A logger that defers log entries to a channel.
+    /// </summary>
+    public class DeferredLogger : ILogger
+    {
+        private readonly Channel<DeferredLogEntry> _channel;
+        private readonly string _categoryName;
+        private readonly List<string> _scopes = new List<string>();
+
+        public DeferredLogger(Channel<DeferredLogEntry> channel, string categoryName)
+        {
+            _channel = channel;
+            _categoryName = categoryName;
+        }
+
+        public IDisposable BeginScope<TState>(TState state)
+        {
+            string scopeData = state is string value ? value : string.Empty;
+
+            if (!string.IsNullOrEmpty(scopeData))
+            {
+                _scopes.Add(scopeData);
+            }
+
+            // Return IDisposable to remove scope from active scopes when done
+            return new ScopeRemover(() => _scopes.Remove(scopeData));
+        }
+
+        public bool IsEnabled(LogLevel logLevel) => logLevel >= LogLevel.Debug;
+
+        public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
+        {
+            string formattedMessage = formatter?.Invoke(state, exception);
+            if (string.IsNullOrEmpty(formattedMessage))
+            {
+                return;
+            }
+            var log = new DeferredLogEntry
+            {
+                LogLevel = logLevel,
+                Category = _categoryName,
+                Message = formattedMessage,
+                Exception = exception,
+                EventId = eventId,
+                Scope = string.Join(", ", _scopes)
+            };
+            _channel.Writer.TryWrite(log);
+        }
+    }
+
+    public class ScopeRemover : IDisposable
+    {
+        private readonly Action _onDispose;
+
+        public ScopeRemover(Action onDispose)
+        {
+            _onDispose = onDispose;
+        }
+
+        public void Dispose()
+        {
+            _onDispose();
+        }
+    }
+}

src/WebJobs.Script.WebHost/Diagnostics/DeferredLogDispatcher.cs → src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs

@@ -3,13 +3,15 @@
 
 using System;
 using System.Collections.Generic;
+using System.Linq;
 using System.Threading.Channels;
 using System.Threading.Tasks;
 using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
 
 namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics
 {
-    public class DeferredLogDispatcher : IDeferredLogDispatcher, IDisposable
+    public class DeferredLoggerProvider : ILoggerProvider
     {
         private readonly Channel<DeferredLogEntry> _channel = Channel.CreateBounded<DeferredLogEntry>(new BoundedChannelOptions(150)
         {
@@ -19,25 +21,24 @@ public class DeferredLogDispatcher : IDeferredLogDispatcher, IDisposable
             SingleWriter = false
         });
 
-        private readonly List<ILoggerProvider> _forwardingProviders = new(1);
         private bool _isEnabled = true;
         private bool _disposed = false;
 
         public int Count => _channel.Reader.Count;
 
-        bool IDeferredLogDispatcher.IsEnabled => _isEnabled;
-
-        public void AddLoggerProvider(ILoggerProvider provider)
-        {
-            _forwardingProviders.Add(provider);
-        }
-
-        public void Log(DeferredLogEntry log)
+        public ILogger CreateLogger(string categoryName)
         {
-            _channel.Writer.TryWrite(log);
+            if (_isEnabled)
+            {
+                return new DeferredLogger(_channel, categoryName);
+            }
+            else
+            {
+                return NullLogger.Instance;
+            }
         }
 
-        public void ProcessBufferedLogs(bool runImmediately = false)
+        public void ProcessBufferedLogs(IEnumerable<ILoggerProvider> forwardingProviders, bool runImmediately = false)
         {
             // Disable the channel and let the consumer know that there won't be any more logs.
             _isEnabled = false;
@@ -54,18 +55,28 @@ public void ProcessBufferedLogs(bool runImmediately = false)
 
                 try
                 {
-                    await foreach (var log in _channel.Reader.ReadAllAsync())
+                    if (!forwardingProviders.Any())
                     {
-                        if (_forwardingProviders.Count == 0)
+                        // No providers, just drain the messages without logging
+                        while (_channel.Reader.TryRead(out _))
                         {
-                            // No providers, just drain the messages without logging
-                            continue;
+                            // Drain the channel
                         }
+                    }
 
-                        foreach (var forwardingProvider in _forwardingProviders)
+                    await foreach (var log in _channel.Reader.ReadAllAsync())
+                    {
+                        foreach (var forwardingProvider in forwardingProviders)
                         {
                             var logger = forwardingProvider.CreateLogger(log.Category);
-                            logger.Log(log.LogLevel, log.EventId, log.Exception, log.Message);
+                            if (string.IsNullOrEmpty(log.Scope))
+                            {
+                                logger.Log(log.LogLevel, log.EventId, log.Exception, log.Message);
+                            }
+                            else
+                            {
+                                logger.Log(log.LogLevel, log.EventId, log.Exception, $"{log.Scope} | {log.Message}");
+                            }
                         }
                     }
                 }
@@ -91,11 +102,10 @@ protected virtual void Dispose(bool disposing)
 
             if (disposing)
             {
-                // Stop accepting logs
                 _isEnabled = false;
-
                 // Signal channel completion
                 _channel.Writer.TryComplete();
+                _disposed = true;
             }
         }
     }

src/WebJobs.Script.WebHost/Diagnostics/SystemLogger.cs

@@ -26,11 +26,10 @@ public class SystemLogger : ILogger
         private readonly IDebugStateProvider _debugStateProvider;
         private readonly IScriptEventManager _eventManager;
         private readonly IExternalScopeProvider _scopeProvider;
-        private readonly IDeferredLogDispatcher _deferredLogDispatcher;
         private AppServiceOptions _appServiceOptions;
 
         public SystemLogger(string hostInstanceId, string categoryName, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider,
-           IScriptEventManager eventManager, IExternalScopeProvider scopeProvider, IOptionsMonitor<AppServiceOptions> appServiceOptionsMonitor, IDeferredLogDispatcher deferredLogDispatcher)
+           IScriptEventManager eventManager, IExternalScopeProvider scopeProvider, IOptionsMonitor<AppServiceOptions> appServiceOptionsMonitor)
         {
             _environment = environment;
             _eventGenerator = eventGenerator;
@@ -45,7 +44,6 @@ public SystemLogger(string hostInstanceId, string categoryName, IEventGenerator
 
             appServiceOptionsMonitor.OnChange(newOptions => _appServiceOptions = newOptions);
             _appServiceOptions = appServiceOptionsMonitor.CurrentValue;
-            _deferredLogDispatcher = deferredLogDispatcher;
         }
 
         public IDisposable BeginScope<TState>(TState state) => _scopeProvider.Push(state);
@@ -181,20 +179,6 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
                 innerExceptionMessage = innerExceptionMessage ?? string.Empty;
             }
             _eventGenerator.LogFunctionTraceEvent(logLevel, subscriptionId, appName, functionName, eventName, source, details, summary, innerExceptionType, innerExceptionMessage, invocationId, _hostInstanceId, activityId, runtimeSiteName, slotName, DateTime.UtcNow);
-
-            if (_deferredLogDispatcher.IsEnabled && !_environment.IsPlaceholderModeEnabled())
-            {
-                var log = new DeferredLogEntry
-                {
-                    LogLevel = logLevel,
-                    Category = _categoryName,
-                    Message = formattedMessage,
-                    Exception = exception,
-                    EventId = eventId
-                };
-
-                _deferredLogDispatcher.Log(log);
-            }
         }
     }
 }

src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs

@@ -20,23 +20,21 @@ public class SystemLoggerProvider : ILoggerProvider, ISupportExternalScope
         private readonly IDebugStateProvider _debugStateProvider;
         private readonly IScriptEventManager _eventManager;
         private readonly IOptionsMonitor<AppServiceOptions> _appServiceOptions;
-        private readonly IDeferredLogDispatcher _deferredLogDispatcher;
         private IExternalScopeProvider _scopeProvider;
 
-        public SystemLoggerProvider(IOptions<ScriptJobHostOptions> scriptOptions, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor<AppServiceOptions> appServiceOptions, IDeferredLogDispatcher deferredLogDispatcher)
-            : this(scriptOptions.Value.InstanceId, eventGenerator, environment, debugStateProvider, eventManager, appServiceOptions, deferredLogDispatcher)
+        public SystemLoggerProvider(IOptions<ScriptJobHostOptions> scriptOptions, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor<AppServiceOptions> appServiceOptions)
+            : this(scriptOptions.Value.InstanceId, eventGenerator, environment, debugStateProvider, eventManager, appServiceOptions)
         {
         }
 
-        protected SystemLoggerProvider(string hostInstanceId, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor<AppServiceOptions> appServiceOptions, IDeferredLogDispatcher deferredLogDispatcher)
+        protected SystemLoggerProvider(string hostInstanceId, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor<AppServiceOptions> appServiceOptions)
         {
             _eventGenerator = eventGenerator;
             _environment = environment;
             _hostInstanceId = hostInstanceId;
             _debugStateProvider = debugStateProvider;
             _eventManager = eventManager;
             _appServiceOptions = appServiceOptions;
-            _deferredLogDispatcher = deferredLogDispatcher;
         }
 
         public ILogger CreateLogger(string categoryName)
@@ -46,7 +44,7 @@ public ILogger CreateLogger(string categoryName)
                 // The SystemLogger is not used for user logs.
                 return NullLogger.Instance;
             }
-            return new SystemLogger(_hostInstanceId, categoryName, _eventGenerator, _environment, _debugStateProvider, _eventManager, _scopeProvider, _appServiceOptions, _deferredLogDispatcher);
+            return new SystemLogger(_hostInstanceId, categoryName, _eventGenerator, _environment, _debugStateProvider, _eventManager, _scopeProvider, _appServiceOptions);
         }
 
         private bool IsUserLogCategory(string categoryName)

src/WebJobs.Script.WebHost/Diagnostics/WebHostSystemLoggerProvider.cs

@@ -13,8 +13,8 @@ namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics
     /// </summary>
     public class WebHostSystemLoggerProvider : SystemLoggerProvider
     {
-        public WebHostSystemLoggerProvider(IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor<AppServiceOptions> appServiceOptions, IDeferredLogDispatcher deferredLogDispatcher)
-            : base(string.Empty, eventGenerator, environment, debugStateProvider, eventManager, appServiceOptions, deferredLogDispatcher)
+        public WebHostSystemLoggerProvider(IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor<AppServiceOptions> appServiceOptions)
+            : base(string.Empty, eventGenerator, environment, debugStateProvider, eventManager, appServiceOptions)
         {
         }
     }

src/WebJobs.Script.WebHost/Program.cs

@@ -88,6 +88,8 @@ public static IWebHostBuilder CreateWebHostBuilder(string[] args = null)
 
                     loggingBuilder.AddDefaultWebJobsFilters();
                     loggingBuilder.AddWebJobsSystem<WebHostSystemLoggerProvider>();
+                    loggingBuilder.Services.AddSingleton<DeferredLoggerProvider>();
+                    loggingBuilder.Services.AddSingleton<ILoggerProvider>(s => s.GetRequiredService<DeferredLoggerProvider>());
                 })
                 .UseStartup<Startup>();
         }

src/WebJobs.Script.WebHost/WebHostServiceCollectionExtensions.cs

@@ -223,7 +223,6 @@ public static void AddWebJobsScriptHost(this IServiceCollection services, IConfi
 
             // Add AzureBlobStorageProvider to WebHost (also needed for ScriptHost) and AzureTableStorageProvider
             services.AddAzureStorageProviders();
-            services.AddSingleton<IDeferredLogDispatcher, DeferredLogDispatcher>();
         }
 
         internal static void AddHostingConfigOptions(this IServiceCollection services, IConfiguration configuration)

src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs

@@ -351,20 +351,14 @@ private async Task UnsynchronizedStartHostAsync(ScriptHostStartupOperation activ
 
                 ActiveHost = localHost;
 
-                var deferredLogDispatcher = ActiveHost.Services.GetService<IDeferredLogDispatcher>();
+                // Forward initial startup logs to AppInsights/OpenTelemetry.
+                // These are not tracked by the AppInsights and OpenTelemetry logger provider as these are added in the script host.
                 var loggerProviders = ActiveHost.Services.GetServices<ILoggerProvider>();
-
-                if (deferredLogDispatcher is not null && loggerProviders is not null)
+                var deferredLogProvider = ActiveHost.Services.GetService<DeferredLoggerProvider>();
+                if (deferredLogProvider is not null && loggerProviders is not null)
                 {
-                    foreach (var provider in loggerProviders)
-                    {
-                        // Add AppInsights and OpenTelemetry providers to the deferred log dispatcher
-                        if (provider is ApplicationInsightsLoggerProvider || provider is OpenTelemetryLoggerProvider)
-                        {
-                            deferredLogDispatcher.AddLoggerProvider(provider);
-                        }
-                    }
-                    deferredLogDispatcher.ProcessBufferedLogs();
+                    var selectedProviders = loggerProviders.Where(provider => provider is ApplicationInsightsLoggerProvider || provider is OpenTelemetryLoggerProvider);
+                    deferredLogProvider.ProcessBufferedLogs(selectedProviders);
                 }
 
                 var scriptHost = (ScriptHost)ActiveHost.Services.GetService<ScriptHost>();

test/WebJobs.Script.Tests.Shared/TestHostBuilderExtensions.cs

@@ -79,7 +79,6 @@ public static IHostBuilder ConfigureDefaultTestWebScriptHost(this IHostBuilder b
             services.AddLogging();
             services.AddFunctionMetadataManager();
             services.AddHostMetrics();
-            services.AddSingleton<IDeferredLogDispatcher, DeferredLogDispatcher>();
 
             configureRootServices?.Invoke(services);