Deferred Log Dispatcher

release_notes.md

@@ -8,3 +8,4 @@
 - Improving console log handling during specialization (#10345)
 - Update Node.js Worker Version to [3.10.1](https://github.com/Azure/azure-functions-nodejs-worker/releases/tag/v3.10.1)
 - Remove packages `Microsoft.Azure.Cosmos.Table` and `Microsoft.Azure.DocumentDB.Core` (#10503)
+- Buffering startup logs and forwarding to ApplicationInsights/OpenTelemetry after logger providers are added to the logging system (#10530)

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

@@ -0,0 +1,23 @@
+// 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 Microsoft.Extensions.Logging;
+
+namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics
+{
+    public class DeferredLogEntry
+    {
+        public LogLevel LogLevel { get; set; }
+
+        public string Category { get; set; }
+
+        public string Message { get; set; }
+
+        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/DeferredLoggerProvider.cs

@@ -0,0 +1,112 @@
+// 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.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 DeferredLoggerProvider : ILoggerProvider
+    {
+        private readonly Channel<DeferredLogEntry> _channel = Channel.CreateBounded<DeferredLogEntry>(new BoundedChannelOptions(150)
+        {
+            FullMode = BoundedChannelFullMode.DropOldest,
+            // Avoids locks and interlocked operations when reading from the channel.
+            SingleReader = true,
+            SingleWriter = false
+        });
+
+        private bool _isEnabled = true;
+        private bool _disposed = false;
+
+        public int Count => _channel.Reader.Count;
+
+        public ILogger CreateLogger(string categoryName)
+        {
+            if (_isEnabled)
+            {
+                return new DeferredLogger(_channel, categoryName);
+            }
+            else
+            {
+                return NullLogger.Instance;
+            }
+        }
+
+        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;
+            _channel.Writer.TryComplete();
+
+            // Forward all buffered logs to the new provider
+            Task.Run(async () =>
+            {
+                if (!runImmediately)
+                {
+                    // Wait for 10 seconds, this will increase the probability of these logs appearing in live metrics.
+                    await Task.Delay(10000);
+                }
+
+                try
+                {
+                    if (!forwardingProviders.Any())
+                    {
+                        // No providers, just drain the messages without logging
+                        while (_channel.Reader.TryRead(out _))
+                        {
+                            // Drain the channel
+                        }
+                    }
+
+                    await foreach (var log in _channel.Reader.ReadAllAsync())
+                    {
+                        foreach (var forwardingProvider in forwardingProviders)
+                        {
+                            var logger = forwardingProvider.CreateLogger(log.Category);
+                            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}");
+                            }
+                        }
+                    }
+                }
+                catch
+                {
+                    // Ignore any exception.
+                }
+            });
+        }
+
+        public void Dispose()
+        {
+            Dispose(true);
+            GC.SuppressFinalize(this);
+        }
+
+        protected virtual void Dispose(bool disposing)
+        {
+            if (_disposed)
+            {
+                return;
+            }
+
+            if (disposing)
+            {
+                _isEnabled = false;
+                // Signal channel completion
+                _channel.Writer.TryComplete();
+                _disposed = true;
+            }
+        }
+    }
+}

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

@@ -3,15 +3,12 @@
 
 using System;
 using System.Collections.Generic;
-using Microsoft.AspNetCore.Http;
 using Microsoft.Azure.WebJobs.Host;
 using Microsoft.Azure.WebJobs.Host.Executors.Internal;
 using Microsoft.Azure.WebJobs.Host.Indexers;
-using Microsoft.Azure.WebJobs.Host.Listeners;
 using Microsoft.Azure.WebJobs.Logging;
 using Microsoft.Azure.WebJobs.Script.Configuration;
 using Microsoft.Azure.WebJobs.Script.Eventing;
-using Microsoft.Azure.WebJobs.Script.Extensions;
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 
@@ -31,7 +28,7 @@ public class SystemLogger : ILogger
         private readonly IExternalScopeProvider _scopeProvider;
         private AppServiceOptions _appServiceOptions;
 
-        public SystemLogger(string hostInstanceId, string categoryName, IEventGenerator eventGenerator, IEnvironment environment,  IDebugStateProvider debugStateProvider,
+        public SystemLogger(string hostInstanceId, string categoryName, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider,
            IScriptEventManager eventManager, IExternalScopeProvider scopeProvider, IOptionsMonitor<AppServiceOptions> appServiceOptionsMonitor)
         {
             _environment = environment;
@@ -181,7 +178,6 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
                 formattedMessage = Sanitizer.Sanitize(formattedMessage);
                 innerExceptionMessage = innerExceptionMessage ?? string.Empty;
             }
-
             _eventGenerator.LogFunctionTraceEvent(logLevel, subscriptionId, appName, functionName, eventName, source, details, summary, innerExceptionType, innerExceptionMessage, invocationId, _hostInstanceId, activityId, runtimeSiteName, slotName, DateTime.UtcNow);
         }
     }

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

@@ -61,4 +61,4 @@ public void SetScopeProvider(IExternalScopeProvider scopeProvider)
             _scopeProvider = scopeProvider;
         }
     }
-}
+}

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

@@ -18,4 +18,4 @@ public WebHostSystemLoggerProvider(IEventGenerator eventGenerator, IEnvironment
         {
         }
     }
-}
+}

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/WebJobsScriptHostService.cs

@@ -2,6 +2,7 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Collections.Generic;
 using System.Collections.ObjectModel;
 using System.IO;
 using System.Linq;
@@ -14,12 +15,14 @@
 using Microsoft.ApplicationInsights.Extensibility.Implementation.ApplicationId;
 using Microsoft.Azure.WebJobs.Host;
 using Microsoft.Azure.WebJobs.Logging;
+using Microsoft.Azure.WebJobs.Logging.ApplicationInsights;
 using Microsoft.Azure.WebJobs.Script.Config;
 using Microsoft.Azure.WebJobs.Script.Configuration;
 using Microsoft.Azure.WebJobs.Script.Diagnostics;
 using Microsoft.Azure.WebJobs.Script.Eventing;
 using Microsoft.Azure.WebJobs.Script.Metrics;
 using Microsoft.Azure.WebJobs.Script.Scale;
+using Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics;
 using Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.Extensions;
 using Microsoft.Azure.WebJobs.Script.Workers;
 using Microsoft.Azure.WebJobs.Script.Workers.Rpc;
@@ -348,6 +351,16 @@ private async Task UnsynchronizedStartHostAsync(ScriptHostStartupOperation activ
 
                 ActiveHost = localHost;
 
+                // 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>();
+                var deferredLogProvider = ActiveHost.Services.GetService<DeferredLoggerProvider>();
+                if (deferredLogProvider is not null && loggerProviders is not null)
+                {
+                    var selectedProviders = loggerProviders.Where(provider => provider is ApplicationInsightsLoggerProvider || provider is OpenTelemetryLoggerProvider);
+                    deferredLogProvider.ProcessBufferedLogs(selectedProviders);
+                }
+
                 var scriptHost = (ScriptHost)ActiveHost.Services.GetService<ScriptHost>();
                 if (scriptHost != null)
                 {

src/WebJobs.Script/WebJobs.Script.csproj

@@ -92,6 +92,7 @@
     <PackageReference Include="System.Security.Cryptography.Xml" Version="4.7.1" />
     <PackageReference Include="System.Text.Json" Version="8.0.4" />
     <PackageReference Include="System.Text.RegularExpressions" Version="4.3.1" />
+    <PackageReference Include="System.Threading.Channels" Version="8.0.0" />
   </ItemGroup>
 
   <ItemGroup>