From fee8a2d306590a9c095937bd5c51c9e07b9aa24b Mon Sep 17 00:00:00 2001 From: Rohit Ranjan <90008725+RohitRanjanMS@users.noreply.github.com> Date: Thu, 17 Oct 2024 01:55:40 -0700 Subject: [PATCH 01/12] Deferred Log Dispatcher --- .../Diagnostics/DeferredLogDispatcher.cs | 102 ++++++++++++++++++ .../Diagnostics/DeferredLogEntry.cs | 21 ++++ .../Diagnostics/IDeferredLogDispatcher.cs | 20 ++++ .../Diagnostics/SystemLogger.cs | 24 +++-- .../Diagnostics/SystemLoggerProvider.cs | 12 ++- .../WebHostSystemLoggerProvider.cs | 6 +- .../WebHostServiceCollectionExtensions.cs | 1 + .../WebJobsScriptHostService.cs | 19 ++++ src/WebJobs.Script/WebJobs.Script.csproj | 1 + .../TestHostBuilderExtensions.cs | 1 + .../Eventing/DeferredLogDispatcherTests.cs | 84 +++++++++++++++ .../Eventing/InMemoryLogger.cs | 23 ++++ .../Eventing/SystemLoggerProviderTests.cs | 3 +- .../Eventing/SystemLoggerTests.cs | 14 +-- 14 files changed, 310 insertions(+), 21 deletions(-) create mode 100644 src/WebJobs.Script.WebHost/Diagnostics/DeferredLogDispatcher.cs create mode 100644 src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs create mode 100644 src/WebJobs.Script.WebHost/Diagnostics/IDeferredLogDispatcher.cs create mode 100644 test/WebJobs.Script.Tests/Eventing/DeferredLogDispatcherTests.cs create mode 100644 test/WebJobs.Script.Tests/Eventing/InMemoryLogger.cs diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogDispatcher.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogDispatcher.cs new file mode 100644 index 0000000000..640f1aa51d --- /dev/null +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogDispatcher.cs @@ -0,0 +1,102 @@ +// 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 System.Threading.Tasks; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics +{ + public class DeferredLogDispatcher : IDeferredLogDispatcher, IDisposable + { + private readonly Channel _channel = Channel.CreateBounded(new BoundedChannelOptions(150) + { + FullMode = BoundedChannelFullMode.DropOldest, + // Avoids locks and interlocked operations when reading and writing to the channel. + SingleReader = true, + SingleWriter = true + }); + + private readonly List _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) + { + _channel.Writer.TryWrite(log); + } + + public void ProcessBufferedLogs(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 + { + await foreach (var log in _channel.Reader.ReadAllAsync()) + { + if (_forwardingProviders.Count == 0) + { + // No providers, just drain the messages without logging + continue; + } + + foreach (var forwardingProvider in _forwardingProviders) + { + var logger = forwardingProvider.CreateLogger(log.Category); + logger.Log(log.LogLevel, log.EventId, log.Exception, 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) + { + // Stop accepting logs + _isEnabled = false; + + // Signal channel completion + _channel.Writer.TryComplete(); + } + } + } +} \ No newline at end of file diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs new file mode 100644 index 0000000000..5b90e86d02 --- /dev/null +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs @@ -0,0 +1,21 @@ +// 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; } + } +} \ No newline at end of file diff --git a/src/WebJobs.Script.WebHost/Diagnostics/IDeferredLogDispatcher.cs b/src/WebJobs.Script.WebHost/Diagnostics/IDeferredLogDispatcher.cs new file mode 100644 index 0000000000..57aadb2dc6 --- /dev/null +++ b/src/WebJobs.Script.WebHost/Diagnostics/IDeferredLogDispatcher.cs @@ -0,0 +1,20 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics +{ + public interface IDeferredLogDispatcher + { + int Count { get; } + + bool IsEnabled { get; } + + void Log(DeferredLogEntry log); + + void AddLoggerProvider(ILoggerProvider provider); + + void ProcessBufferedLogs(bool runImmediately = false); + } +} \ No newline at end of file diff --git a/src/WebJobs.Script.WebHost/Diagnostics/SystemLogger.cs b/src/WebJobs.Script.WebHost/Diagnostics/SystemLogger.cs index bccc7a144a..cbe9b5c1c5 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/SystemLogger.cs +++ b/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; @@ -29,10 +26,11 @@ 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 appServiceOptionsMonitor) + public SystemLogger(string hostInstanceId, string categoryName, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, + IScriptEventManager eventManager, IExternalScopeProvider scopeProvider, IOptionsMonitor appServiceOptionsMonitor, IDeferredLogDispatcher deferredLogDispatcher) { _environment = environment; _eventGenerator = eventGenerator; @@ -47,6 +45,7 @@ public SystemLogger(string hostInstanceId, string categoryName, IEventGenerator appServiceOptionsMonitor.OnChange(newOptions => _appServiceOptions = newOptions); _appServiceOptions = appServiceOptionsMonitor.CurrentValue; + _deferredLogDispatcher = deferredLogDispatcher; } public IDisposable BeginScope(TState state) => _scopeProvider.Push(state); @@ -181,8 +180,21 @@ public void Log(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); + + if (_deferredLogDispatcher.IsEnabled && !_environment.IsPlaceholderModeEnabled()) + { + var log = new DeferredLogEntry + { + LogLevel = logLevel, + Category = _categoryName, + Message = formattedMessage, + Exception = exception, + EventId = eventId + }; + + _deferredLogDispatcher.Log(log); + } } } } \ No newline at end of file diff --git a/src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs b/src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs index cc9ee68bd0..1a8832e905 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs @@ -20,14 +20,15 @@ public class SystemLoggerProvider : ILoggerProvider, ISupportExternalScope private readonly IDebugStateProvider _debugStateProvider; private readonly IScriptEventManager _eventManager; private readonly IOptionsMonitor _appServiceOptions; + private readonly IDeferredLogDispatcher _deferredLogDispatcher; private IExternalScopeProvider _scopeProvider; - public SystemLoggerProvider(IOptions scriptOptions, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor appServiceOptions) - : this(scriptOptions.Value.InstanceId, eventGenerator, environment, debugStateProvider, eventManager, appServiceOptions) + public SystemLoggerProvider(IOptions scriptOptions, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor appServiceOptions, IDeferredLogDispatcher deferredLogDispatcher) + : this(scriptOptions.Value.InstanceId, eventGenerator, environment, debugStateProvider, eventManager, appServiceOptions, deferredLogDispatcher) { } - protected SystemLoggerProvider(string hostInstanceId, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor appServiceOptions) + protected SystemLoggerProvider(string hostInstanceId, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor appServiceOptions, IDeferredLogDispatcher deferredLogDispatcher) { _eventGenerator = eventGenerator; _environment = environment; @@ -35,6 +36,7 @@ protected SystemLoggerProvider(string hostInstanceId, IEventGenerator eventGener _debugStateProvider = debugStateProvider; _eventManager = eventManager; _appServiceOptions = appServiceOptions; + _deferredLogDispatcher = deferredLogDispatcher; } public ILogger CreateLogger(string categoryName) @@ -44,7 +46,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); + return new SystemLogger(_hostInstanceId, categoryName, _eventGenerator, _environment, _debugStateProvider, _eventManager, _scopeProvider, _appServiceOptions, _deferredLogDispatcher); } private bool IsUserLogCategory(string categoryName) @@ -61,4 +63,4 @@ public void SetScopeProvider(IExternalScopeProvider scopeProvider) _scopeProvider = scopeProvider; } } -} +} \ No newline at end of file diff --git a/src/WebJobs.Script.WebHost/Diagnostics/WebHostSystemLoggerProvider.cs b/src/WebJobs.Script.WebHost/Diagnostics/WebHostSystemLoggerProvider.cs index caf8568c7b..75effc909b 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/WebHostSystemLoggerProvider.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/WebHostSystemLoggerProvider.cs @@ -13,9 +13,9 @@ namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics /// public class WebHostSystemLoggerProvider : SystemLoggerProvider { - public WebHostSystemLoggerProvider(IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor appServiceOptions) - : base(string.Empty, eventGenerator, environment, debugStateProvider, eventManager, appServiceOptions) + public WebHostSystemLoggerProvider(IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor appServiceOptions, IDeferredLogDispatcher deferredLogDispatcher) + : base(string.Empty, eventGenerator, environment, debugStateProvider, eventManager, appServiceOptions, deferredLogDispatcher) { } } -} +} \ No newline at end of file diff --git a/src/WebJobs.Script.WebHost/WebHostServiceCollectionExtensions.cs b/src/WebJobs.Script.WebHost/WebHostServiceCollectionExtensions.cs index 3e0a7f98d2..dc278d8d02 100644 --- a/src/WebJobs.Script.WebHost/WebHostServiceCollectionExtensions.cs +++ b/src/WebJobs.Script.WebHost/WebHostServiceCollectionExtensions.cs @@ -223,6 +223,7 @@ public static void AddWebJobsScriptHost(this IServiceCollection services, IConfi // Add AzureBlobStorageProvider to WebHost (also needed for ScriptHost) and AzureTableStorageProvider services.AddAzureStorageProviders(); + services.AddSingleton(); } internal static void AddHostingConfigOptions(this IServiceCollection services, IConfiguration configuration) diff --git a/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs b/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs index 6c0f21484b..b1df97f529 100644 --- a/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs +++ b/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,22 @@ private async Task UnsynchronizedStartHostAsync(ScriptHostStartupOperation activ ActiveHost = localHost; + var deferredLogDispatcher = ActiveHost.Services.GetService(); + var loggerProviders = ActiveHost.Services.GetServices(); + + if (deferredLogDispatcher 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 scriptHost = (ScriptHost)ActiveHost.Services.GetService(); if (scriptHost != null) { diff --git a/src/WebJobs.Script/WebJobs.Script.csproj b/src/WebJobs.Script/WebJobs.Script.csproj index e02f1a3dfb..2aa63d2518 100644 --- a/src/WebJobs.Script/WebJobs.Script.csproj +++ b/src/WebJobs.Script/WebJobs.Script.csproj @@ -92,6 +92,7 @@ + diff --git a/test/WebJobs.Script.Tests.Shared/TestHostBuilderExtensions.cs b/test/WebJobs.Script.Tests.Shared/TestHostBuilderExtensions.cs index d36d757541..5966cd7ad1 100644 --- a/test/WebJobs.Script.Tests.Shared/TestHostBuilderExtensions.cs +++ b/test/WebJobs.Script.Tests.Shared/TestHostBuilderExtensions.cs @@ -79,6 +79,7 @@ public static IHostBuilder ConfigureDefaultTestWebScriptHost(this IHostBuilder b services.AddLogging(); services.AddFunctionMetadataManager(); services.AddHostMetrics(); + services.AddSingleton(); configureRootServices?.Invoke(services); diff --git a/test/WebJobs.Script.Tests/Eventing/DeferredLogDispatcherTests.cs b/test/WebJobs.Script.Tests/Eventing/DeferredLogDispatcherTests.cs new file mode 100644 index 0000000000..6a3552ee9c --- /dev/null +++ b/test/WebJobs.Script.Tests/Eventing/DeferredLogDispatcherTests.cs @@ -0,0 +1,84 @@ +// 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.Threading.Tasks; +using Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics; +using Microsoft.Extensions.Logging; +using Moq; +using Xunit; + +namespace Microsoft.Azure.WebJobs.Script.Tests.Eventing +{ + public class DeferredLogDispatcherTests + { + [Fact] + public async Task ShouldForwardLogsToLoggerProviders_WhenProvidersAreAddedAsync() + { + // Arrange + var deferredLogDispatcher = new DeferredLogDispatcher(); + var logLevel = LogLevel.Information; + var logMessage = "Test log message"; + var logCategory = "TestCategory"; + var exception = new Exception("Test exception"); + + // Mock ILoggerProvider and ILogger + var loggerProviderMock = new Mock(); + var loggerMock = new InMemoryLogger(); + + loggerProviderMock.Setup(provider => provider.CreateLogger(It.IsAny())) + .Returns(loggerMock); + + // Add the logger provider to the dispatcher + deferredLogDispatcher.AddLoggerProvider(loggerProviderMock.Object); + + // Act + deferredLogDispatcher.Log(new DeferredLogEntry + { + EventId = new EventId(1), + LogLevel = logLevel, + Category = logCategory, + Message = logMessage, + Exception = exception + }); + + // Process buffered logs + deferredLogDispatcher.ProcessBufferedLogs(runImmediately: true); + await Task.Delay(1000); + // Assert + loggerProviderMock.Verify(provider => provider.CreateLogger(logCategory), Times.Once); + + Assert.Single(loggerMock.LogEntries); + Assert.Equal(0, deferredLogDispatcher.Count); + Assert.Contains(logMessage, loggerMock.LogEntries[0]); + } + + [Fact] + public async Task ShouldDrainLogs_WhenNoLoggerProvidersAreAddedAsync() + { + // Arrange + var deferredLogDispatcher = new DeferredLogDispatcher(); + var logMessage = "Test log message"; + + // Act + deferredLogDispatcher.Log(new DeferredLogEntry + { + LogLevel = LogLevel.Information, + Category = "TestCategory", + Message = logMessage, + Exception = null + }); + + Assert.Equal(1, deferredLogDispatcher.Count); + // Process logs with no providers + deferredLogDispatcher.ProcessBufferedLogs(runImmediately: true); + await Task.Delay(1000); + + // Assert + // No provider was added, so nothing should be forwarded. + // We expect no exceptions to be thrown and the channel to be drained. + Assert.Equal(0, deferredLogDispatcher.Count); + Assert.True(true); // This is a trivial assertion to ensure test passed. + } + } +} \ No newline at end of file diff --git a/test/WebJobs.Script.Tests/Eventing/InMemoryLogger.cs b/test/WebJobs.Script.Tests/Eventing/InMemoryLogger.cs new file mode 100644 index 0000000000..0eb873d14f --- /dev/null +++ b/test/WebJobs.Script.Tests/Eventing/InMemoryLogger.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 System.Collections.Generic; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Script.Tests.Eventing +{ + public class InMemoryLogger : ILogger + { + public List LogEntries { get; set; } = new List(); + + public IDisposable BeginScope(TState state) => null; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + LogEntries.Add(formatter?.Invoke(state, exception)); + } + } +} \ No newline at end of file diff --git a/test/WebJobs.Script.Tests/Eventing/SystemLoggerProviderTests.cs b/test/WebJobs.Script.Tests/Eventing/SystemLoggerProviderTests.cs index 87f046fd86..7263b35d97 100644 --- a/test/WebJobs.Script.Tests/Eventing/SystemLoggerProviderTests.cs +++ b/test/WebJobs.Script.Tests/Eventing/SystemLoggerProviderTests.cs @@ -17,6 +17,7 @@ public class SystemLoggerProviderTests { private readonly IOptions _options; private readonly IEnvironment _environment = new TestEnvironment(); + private readonly IDeferredLogDispatcher _deferredLogDispatcher = new DeferredLogDispatcher(); private readonly SystemLoggerProvider _provider; private bool _inDiagnosticMode; @@ -33,7 +34,7 @@ public SystemLoggerProviderTests() debugStateProvider.Setup(p => p.InDiagnosticMode).Returns(() => _inDiagnosticMode); var appServiceOptions = new TestOptionsMonitor(new AppServiceOptions()); - _provider = new SystemLoggerProvider(_options, null, _environment, debugStateProvider.Object, null, appServiceOptions); + _provider = new SystemLoggerProvider(_options, null, _environment, debugStateProvider.Object, null, appServiceOptions, _deferredLogDispatcher); } [Fact] diff --git a/test/WebJobs.Script.Tests/Eventing/SystemLoggerTests.cs b/test/WebJobs.Script.Tests/Eventing/SystemLoggerTests.cs index cb5c4430b7..3f54ca4b8f 100644 --- a/test/WebJobs.Script.Tests/Eventing/SystemLoggerTests.cs +++ b/test/WebJobs.Script.Tests/Eventing/SystemLoggerTests.cs @@ -35,6 +35,7 @@ public class SystemLoggerTests private readonly TestChangeTokenSource _changeTokenSource; private readonly string _slotName = "production"; private readonly string _runtimeSiteName = "test"; + private readonly IDeferredLogDispatcher _deferredLogDispatcher; private bool _inDiagnosticMode; public SystemLoggerTests() @@ -68,8 +69,9 @@ public SystemLoggerTests() _category = LogCategories.CreateFunctionCategory(_functionName); _debugStateProvider = new Mock(MockBehavior.Strict); _debugStateProvider.Setup(p => p.InDiagnosticMode).Returns(() => _inDiagnosticMode); + _deferredLogDispatcher = new DeferredLogDispatcher(); - _logger = new SystemLogger(_hostInstanceId, _category, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + _logger = new SystemLogger(_hostInstanceId, _category, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions, _deferredLogDispatcher); } [Fact] @@ -161,7 +163,7 @@ public void Log_FunctionException_EmitsExpectedEvent(FunctionException functionE _mockEventGenerator.Setup(p => p.LogFunctionTraceEvent(LogLevel.Error, _subscriptionId, _websiteName, functionName, eventName, string.Empty, functionException.ToFormattedString(), functionException.Message, functionException.InnerException.GetType().ToString(), functionException.InnerException.Message, functionInvocationId, _hostInstanceId, activityId, _runtimeSiteName, _slotName, It.IsAny())); - ILogger localLogger = new SystemLogger(_hostInstanceId, string.Empty, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + ILogger localLogger = new SystemLogger(_hostInstanceId, string.Empty, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions, _deferredLogDispatcher); localLogger.LogError(functionException, functionException.Message); _mockEventGenerator.VerifyAll(); @@ -196,7 +198,7 @@ public void Log_Sanitization() public void Log_Ignores_FunctionUserCategory() { // Create a logger with the Function.{FunctionName}.User category, which is what determines user logs. - ILogger logger = new SystemLogger(Guid.NewGuid().ToString(), LogCategories.CreateFunctionUserCategory(_functionName), _mockEventGenerator.Object, new TestEnvironment(), _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + ILogger logger = new SystemLogger(Guid.NewGuid().ToString(), LogCategories.CreateFunctionUserCategory(_functionName), _mockEventGenerator.Object, new TestEnvironment(), _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions, _deferredLogDispatcher); logger.LogDebug("TestMessage"); // Make sure it's never been called. @@ -247,7 +249,7 @@ public void Log_UsesStateFunctionName_IfNoCategory(string key) [key] = "TestFunction2" }; - var localLogger = new SystemLogger(_hostInstanceId, "Not.A.Function", _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + var localLogger = new SystemLogger(_hostInstanceId, "Not.A.Function", _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions, _deferredLogDispatcher); _mockEventGenerator.Setup(p => p.LogFunctionTraceEvent(LogLevel.Debug, It.IsAny(), It.IsAny(), "TestFunction2", It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny())); localLogger.Log(LogLevel.Debug, 0, logState, null, (s, e) => "TestMessage"); @@ -266,7 +268,7 @@ public void Log_UsesScopeFunctionName_IfNoCategory(string key) [key] = "TestFunction3" }; - var localLogger = new SystemLogger(_hostInstanceId, "Not.A.Function", _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + var localLogger = new SystemLogger(_hostInstanceId, "Not.A.Function", _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions, _deferredLogDispatcher); _mockEventGenerator.Setup(p => p.LogFunctionTraceEvent(LogLevel.Debug, It.IsAny(), It.IsAny(), "TestFunction3", It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny())); @@ -282,7 +284,7 @@ public void Log_UsesScopeFunctionName_IfNoCategory(string key) public void AppEnvironment_Reset_OnSpecialization() { var testEventGenerator = new TestEventGenerator(); - var localLogger = new SystemLogger(_hostInstanceId, "Test", testEventGenerator, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + var localLogger = new SystemLogger(_hostInstanceId, "Test", testEventGenerator, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions, _deferredLogDispatcher); localLogger.LogInformation("test"); From daa7b28b50d358d25f7120e9866a5d88f9c845dc Mon Sep 17 00:00:00 2001 From: Rohit Ranjan <90008725+RohitRanjanMS@users.noreply.github.com> Date: Thu, 17 Oct 2024 02:24:33 -0700 Subject: [PATCH 02/12] Updated SingleWriter. --- .../Diagnostics/DeferredLogDispatcher.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogDispatcher.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogDispatcher.cs index 640f1aa51d..05d78d1edc 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogDispatcher.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogDispatcher.cs @@ -14,9 +14,9 @@ public class DeferredLogDispatcher : IDeferredLogDispatcher, IDisposable private readonly Channel _channel = Channel.CreateBounded(new BoundedChannelOptions(150) { FullMode = BoundedChannelFullMode.DropOldest, - // Avoids locks and interlocked operations when reading and writing to the channel. + // Avoids locks and interlocked operations when reading from the channel. SingleReader = true, - SingleWriter = true + SingleWriter = false }); private readonly List _forwardingProviders = new(1); From a32ae156544f68d95d55b08fb42f715439bd36fa Mon Sep 17 00:00:00 2001 From: Rohit Ranjan <90008725+RohitRanjanMS@users.noreply.github.com> Date: Thu, 17 Oct 2024 02:40:55 -0700 Subject: [PATCH 03/12] Updated release notes. --- release_notes.md | 1 + 1 file changed, 1 insertion(+) diff --git a/release_notes.md b/release_notes.md index d7715e1f0b..5139404803 100644 --- a/release_notes.md +++ b/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) From 821e0c12ddf0460642e4a3d03a50c8d01bd74569 Mon Sep 17 00:00:00 2001 From: Rohit Ranjan <90008725+RohitRanjanMS@users.noreply.github.com> Date: Fri, 18 Oct 2024 03:34:12 -0700 Subject: [PATCH 04/12] Added Loggerprovider --- .../Diagnostics/DeferredLogEntry.cs | 2 + .../Diagnostics/DeferredLogger.cs | 75 +++++++++ ...ispatcher.cs => DeferredLoggerProvider.cs} | 50 +++--- .../Diagnostics/IDeferredLogDispatcher.cs | 20 --- .../Diagnostics/SystemLogger.cs | 18 +-- .../Diagnostics/SystemLoggerProvider.cs | 10 +- .../WebHostSystemLoggerProvider.cs | 4 +- src/WebJobs.Script.WebHost/Program.cs | 2 + .../WebHostServiceCollectionExtensions.cs | 1 - .../WebJobsScriptHostService.cs | 18 +-- .../TestHostBuilderExtensions.cs | 1 - .../Eventing/DeferredLogDispatcherTests.cs | 84 ---------- .../Eventing/DeferredLoggerProviderTests.cs | 150 ++++++++++++++++++ .../Eventing/SystemLoggerProviderTests.cs | 3 +- .../Eventing/SystemLoggerTests.cs | 14 +- 15 files changed, 279 insertions(+), 173 deletions(-) create mode 100644 src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs rename src/WebJobs.Script.WebHost/Diagnostics/{DeferredLogDispatcher.cs => DeferredLoggerProvider.cs} (63%) delete mode 100644 src/WebJobs.Script.WebHost/Diagnostics/IDeferredLogDispatcher.cs delete mode 100644 test/WebJobs.Script.Tests/Eventing/DeferredLogDispatcherTests.cs create mode 100644 test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs index 5b90e86d02..253f3358a6 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs +++ b/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; } } } \ No newline at end of file diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs new file mode 100644 index 0000000000..753de4a0ba --- /dev/null +++ b/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 +{ + /// + /// A logger that defers log entries to a channel. + /// + public class DeferredLogger : ILogger + { + private readonly Channel _channel; + private readonly string _categoryName; + private readonly List _scopes = new List(); + + public DeferredLogger(Channel channel, string categoryName) + { + _channel = channel; + _categoryName = categoryName; + } + + public IDisposable BeginScope(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(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func 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(); + } + } +} \ No newline at end of file diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogDispatcher.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs similarity index 63% rename from src/WebJobs.Script.WebHost/Diagnostics/DeferredLogDispatcher.cs rename to src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs index 05d78d1edc..97eed8b080 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogDispatcher.cs +++ b/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 _channel = Channel.CreateBounded(new BoundedChannelOptions(150) { @@ -19,25 +21,24 @@ public class DeferredLogDispatcher : IDeferredLogDispatcher, IDisposable SingleWriter = false }); - private readonly List _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 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; } } } diff --git a/src/WebJobs.Script.WebHost/Diagnostics/IDeferredLogDispatcher.cs b/src/WebJobs.Script.WebHost/Diagnostics/IDeferredLogDispatcher.cs deleted file mode 100644 index 57aadb2dc6..0000000000 --- a/src/WebJobs.Script.WebHost/Diagnostics/IDeferredLogDispatcher.cs +++ /dev/null @@ -1,20 +0,0 @@ -// Copyright (c) .NET Foundation. All rights reserved. -// Licensed under the MIT License. See License.txt in the project root for license information. - -using Microsoft.Extensions.Logging; - -namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics -{ - public interface IDeferredLogDispatcher - { - int Count { get; } - - bool IsEnabled { get; } - - void Log(DeferredLogEntry log); - - void AddLoggerProvider(ILoggerProvider provider); - - void ProcessBufferedLogs(bool runImmediately = false); - } -} \ No newline at end of file diff --git a/src/WebJobs.Script.WebHost/Diagnostics/SystemLogger.cs b/src/WebJobs.Script.WebHost/Diagnostics/SystemLogger.cs index cbe9b5c1c5..a3cd1a484f 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/SystemLogger.cs +++ b/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 appServiceOptionsMonitor, IDeferredLogDispatcher deferredLogDispatcher) + IScriptEventManager eventManager, IExternalScopeProvider scopeProvider, IOptionsMonitor 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 state) => _scopeProvider.Push(state); @@ -181,20 +179,6 @@ public void Log(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); - } } } } \ No newline at end of file diff --git a/src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs b/src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs index 1a8832e905..e81a9686a9 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs @@ -20,15 +20,14 @@ public class SystemLoggerProvider : ILoggerProvider, ISupportExternalScope private readonly IDebugStateProvider _debugStateProvider; private readonly IScriptEventManager _eventManager; private readonly IOptionsMonitor _appServiceOptions; - private readonly IDeferredLogDispatcher _deferredLogDispatcher; private IExternalScopeProvider _scopeProvider; - public SystemLoggerProvider(IOptions scriptOptions, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor appServiceOptions, IDeferredLogDispatcher deferredLogDispatcher) - : this(scriptOptions.Value.InstanceId, eventGenerator, environment, debugStateProvider, eventManager, appServiceOptions, deferredLogDispatcher) + public SystemLoggerProvider(IOptions scriptOptions, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor appServiceOptions) + : this(scriptOptions.Value.InstanceId, eventGenerator, environment, debugStateProvider, eventManager, appServiceOptions) { } - protected SystemLoggerProvider(string hostInstanceId, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor appServiceOptions, IDeferredLogDispatcher deferredLogDispatcher) + protected SystemLoggerProvider(string hostInstanceId, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor appServiceOptions) { _eventGenerator = eventGenerator; _environment = environment; @@ -36,7 +35,6 @@ protected SystemLoggerProvider(string hostInstanceId, IEventGenerator eventGener _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) diff --git a/src/WebJobs.Script.WebHost/Diagnostics/WebHostSystemLoggerProvider.cs b/src/WebJobs.Script.WebHost/Diagnostics/WebHostSystemLoggerProvider.cs index 75effc909b..e3e1596474 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/WebHostSystemLoggerProvider.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/WebHostSystemLoggerProvider.cs @@ -13,8 +13,8 @@ namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics /// public class WebHostSystemLoggerProvider : SystemLoggerProvider { - public WebHostSystemLoggerProvider(IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor appServiceOptions, IDeferredLogDispatcher deferredLogDispatcher) - : base(string.Empty, eventGenerator, environment, debugStateProvider, eventManager, appServiceOptions, deferredLogDispatcher) + public WebHostSystemLoggerProvider(IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider, IScriptEventManager eventManager, IOptionsMonitor appServiceOptions) + : base(string.Empty, eventGenerator, environment, debugStateProvider, eventManager, appServiceOptions) { } } diff --git a/src/WebJobs.Script.WebHost/Program.cs b/src/WebJobs.Script.WebHost/Program.cs index 5cf29d9952..308f6a5416 100644 --- a/src/WebJobs.Script.WebHost/Program.cs +++ b/src/WebJobs.Script.WebHost/Program.cs @@ -88,6 +88,8 @@ public static IWebHostBuilder CreateWebHostBuilder(string[] args = null) loggingBuilder.AddDefaultWebJobsFilters(); loggingBuilder.AddWebJobsSystem(); + loggingBuilder.Services.AddSingleton(); + loggingBuilder.Services.AddSingleton(s => s.GetRequiredService()); }) .UseStartup(); } diff --git a/src/WebJobs.Script.WebHost/WebHostServiceCollectionExtensions.cs b/src/WebJobs.Script.WebHost/WebHostServiceCollectionExtensions.cs index dc278d8d02..3e0a7f98d2 100644 --- a/src/WebJobs.Script.WebHost/WebHostServiceCollectionExtensions.cs +++ b/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(); } internal static void AddHostingConfigOptions(this IServiceCollection services, IConfiguration configuration) diff --git a/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs b/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs index b1df97f529..375396021e 100644 --- a/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs +++ b/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs @@ -351,20 +351,14 @@ private async Task UnsynchronizedStartHostAsync(ScriptHostStartupOperation activ ActiveHost = localHost; - var deferredLogDispatcher = ActiveHost.Services.GetService(); + // 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(); - - if (deferredLogDispatcher is not null && loggerProviders is not null) + var deferredLogProvider = ActiveHost.Services.GetService(); + 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(); diff --git a/test/WebJobs.Script.Tests.Shared/TestHostBuilderExtensions.cs b/test/WebJobs.Script.Tests.Shared/TestHostBuilderExtensions.cs index 5966cd7ad1..d36d757541 100644 --- a/test/WebJobs.Script.Tests.Shared/TestHostBuilderExtensions.cs +++ b/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(); configureRootServices?.Invoke(services); diff --git a/test/WebJobs.Script.Tests/Eventing/DeferredLogDispatcherTests.cs b/test/WebJobs.Script.Tests/Eventing/DeferredLogDispatcherTests.cs deleted file mode 100644 index 6a3552ee9c..0000000000 --- a/test/WebJobs.Script.Tests/Eventing/DeferredLogDispatcherTests.cs +++ /dev/null @@ -1,84 +0,0 @@ -// 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.Threading.Tasks; -using Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics; -using Microsoft.Extensions.Logging; -using Moq; -using Xunit; - -namespace Microsoft.Azure.WebJobs.Script.Tests.Eventing -{ - public class DeferredLogDispatcherTests - { - [Fact] - public async Task ShouldForwardLogsToLoggerProviders_WhenProvidersAreAddedAsync() - { - // Arrange - var deferredLogDispatcher = new DeferredLogDispatcher(); - var logLevel = LogLevel.Information; - var logMessage = "Test log message"; - var logCategory = "TestCategory"; - var exception = new Exception("Test exception"); - - // Mock ILoggerProvider and ILogger - var loggerProviderMock = new Mock(); - var loggerMock = new InMemoryLogger(); - - loggerProviderMock.Setup(provider => provider.CreateLogger(It.IsAny())) - .Returns(loggerMock); - - // Add the logger provider to the dispatcher - deferredLogDispatcher.AddLoggerProvider(loggerProviderMock.Object); - - // Act - deferredLogDispatcher.Log(new DeferredLogEntry - { - EventId = new EventId(1), - LogLevel = logLevel, - Category = logCategory, - Message = logMessage, - Exception = exception - }); - - // Process buffered logs - deferredLogDispatcher.ProcessBufferedLogs(runImmediately: true); - await Task.Delay(1000); - // Assert - loggerProviderMock.Verify(provider => provider.CreateLogger(logCategory), Times.Once); - - Assert.Single(loggerMock.LogEntries); - Assert.Equal(0, deferredLogDispatcher.Count); - Assert.Contains(logMessage, loggerMock.LogEntries[0]); - } - - [Fact] - public async Task ShouldDrainLogs_WhenNoLoggerProvidersAreAddedAsync() - { - // Arrange - var deferredLogDispatcher = new DeferredLogDispatcher(); - var logMessage = "Test log message"; - - // Act - deferredLogDispatcher.Log(new DeferredLogEntry - { - LogLevel = LogLevel.Information, - Category = "TestCategory", - Message = logMessage, - Exception = null - }); - - Assert.Equal(1, deferredLogDispatcher.Count); - // Process logs with no providers - deferredLogDispatcher.ProcessBufferedLogs(runImmediately: true); - await Task.Delay(1000); - - // Assert - // No provider was added, so nothing should be forwarded. - // We expect no exceptions to be thrown and the channel to be drained. - Assert.Equal(0, deferredLogDispatcher.Count); - Assert.True(true); // This is a trivial assertion to ensure test passed. - } - } -} \ No newline at end of file diff --git a/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs b/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs new file mode 100644 index 0000000000..db29df4c57 --- /dev/null +++ b/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs @@ -0,0 +1,150 @@ +// 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.Tasks; +using Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using Moq; +using Xunit; + +namespace Microsoft.Azure.WebJobs.Script.Tests.Eventing +{ + public class DeferredLoggerProviderTests + { + [Fact] + public void CreateLogger_ReturnsDeferredLogger_WhenEnabled() + { + // Arrange + var provider = new DeferredLoggerProvider(); + + // Act + var logger = provider.CreateLogger("TestCategory"); + + // Assert + Assert.IsType(logger); + } + + [Fact] + public void CreateLogger_ReturnsNullLogger_WhenDisabled() + { + // Arrange + var provider = new DeferredLoggerProvider(); + provider.ProcessBufferedLogs(new List(), true); // Disable the provider + + // Act + var logger = provider.CreateLogger("TestCategory"); + + // Assert + Assert.IsType(logger); + } + + [Fact] + public async Task ProcessBufferedLogs_ForwardsLogsToProviders() + { + // Arrange + var mockLoggerProvider = new Mock(); + var mockLogger = new Mock(); + mockLoggerProvider.Setup(p => p.CreateLogger(It.IsAny())).Returns(mockLogger.Object); + + var providers = new List { mockLoggerProvider.Object }; + var provider = new DeferredLoggerProvider(); + + var logger = provider.CreateLogger("TestCategory"); + + var state = "TestMessage"; + var eventId = new EventId(1, "TestEvent"); + var exception = new InvalidOperationException("TestException"); + + // Act + logger.Log(LogLevel.Information, eventId, state, exception, (s, e) => $"{s}: {e?.Message}"); + + Assert.Equal(1, provider.Count); + provider.ProcessBufferedLogs(providers, true); // Process immediately + + // Wait for forwarding task to complete + await Task.Delay(1000); + Assert.Equal(0, provider.Count); // Ensure channel is drained + } + + [Fact] + public async Task ProcessBufferedLogs_DrainsChannelWithoutProviders() + { + // Arrange + var provider = new DeferredLoggerProvider(); + + var logger = provider.CreateLogger("TestCategory"); + logger.LogInformation("Test Log Message"); + + // Act + provider.ProcessBufferedLogs(new List(), true); // Process immediately + + // Wait for forwarding task to complete + await Task.Delay(100); // Small delay to ensure the logs are processed + + // Assert + Assert.Equal(0, provider.Count); // Ensure channel is drained + } + + [Fact] + public async Task Dispose_DisablesProviderAndCompletesChannel() + { + // Arrange + var provider = new DeferredLoggerProvider(); + var logger = provider.CreateLogger("TestCategory"); + logger.LogInformation("Log before disposal"); + + // Act + provider.ProcessBufferedLogs(new List(), true); // Process immediately + provider.Dispose(); + + // Wait a short period to ensure the channel is completed + await Task.Delay(100); + + // Assert + Assert.False(provider.CreateLogger("TestCategory") is DeferredLogger); + Assert.Equal(0, provider.Count); // Ensure channel is drained + } + + [Fact] + public void Count_ShouldReturnNumberOfBufferedLogs() + { + // Arrange + var provider = new DeferredLoggerProvider(); + + var logger = provider.CreateLogger("TestCategory"); + logger.LogInformation("Test Log 1"); + logger.LogInformation("Test Log 2"); + + // Act + int count = provider.Count; + + // Assert + Assert.Equal(2, count); + } + + [Fact] + public void Dispose_CanBeCalledMultipleTimesWithoutException() + { + // Arrange + var provider = new DeferredLoggerProvider(); + + // Act & Assert + provider.Dispose(); // First disposal + provider.Dispose(); // Second disposal, should not throw + } + + [Fact] + public void ProcessBufferedLogs_ThrowsNoExceptionsWhenChannelIsEmpty() + { + // Arrange + var provider = new DeferredLoggerProvider(); + var mockLoggerProvider = new Mock(); + + // Act & Assert (no exceptions should be thrown) + provider.ProcessBufferedLogs(new[] { mockLoggerProvider.Object }, true); + } + } +} \ No newline at end of file diff --git a/test/WebJobs.Script.Tests/Eventing/SystemLoggerProviderTests.cs b/test/WebJobs.Script.Tests/Eventing/SystemLoggerProviderTests.cs index 7263b35d97..87f046fd86 100644 --- a/test/WebJobs.Script.Tests/Eventing/SystemLoggerProviderTests.cs +++ b/test/WebJobs.Script.Tests/Eventing/SystemLoggerProviderTests.cs @@ -17,7 +17,6 @@ public class SystemLoggerProviderTests { private readonly IOptions _options; private readonly IEnvironment _environment = new TestEnvironment(); - private readonly IDeferredLogDispatcher _deferredLogDispatcher = new DeferredLogDispatcher(); private readonly SystemLoggerProvider _provider; private bool _inDiagnosticMode; @@ -34,7 +33,7 @@ public SystemLoggerProviderTests() debugStateProvider.Setup(p => p.InDiagnosticMode).Returns(() => _inDiagnosticMode); var appServiceOptions = new TestOptionsMonitor(new AppServiceOptions()); - _provider = new SystemLoggerProvider(_options, null, _environment, debugStateProvider.Object, null, appServiceOptions, _deferredLogDispatcher); + _provider = new SystemLoggerProvider(_options, null, _environment, debugStateProvider.Object, null, appServiceOptions); } [Fact] diff --git a/test/WebJobs.Script.Tests/Eventing/SystemLoggerTests.cs b/test/WebJobs.Script.Tests/Eventing/SystemLoggerTests.cs index 3f54ca4b8f..cb5c4430b7 100644 --- a/test/WebJobs.Script.Tests/Eventing/SystemLoggerTests.cs +++ b/test/WebJobs.Script.Tests/Eventing/SystemLoggerTests.cs @@ -35,7 +35,6 @@ public class SystemLoggerTests private readonly TestChangeTokenSource _changeTokenSource; private readonly string _slotName = "production"; private readonly string _runtimeSiteName = "test"; - private readonly IDeferredLogDispatcher _deferredLogDispatcher; private bool _inDiagnosticMode; public SystemLoggerTests() @@ -69,9 +68,8 @@ public SystemLoggerTests() _category = LogCategories.CreateFunctionCategory(_functionName); _debugStateProvider = new Mock(MockBehavior.Strict); _debugStateProvider.Setup(p => p.InDiagnosticMode).Returns(() => _inDiagnosticMode); - _deferredLogDispatcher = new DeferredLogDispatcher(); - _logger = new SystemLogger(_hostInstanceId, _category, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions, _deferredLogDispatcher); + _logger = new SystemLogger(_hostInstanceId, _category, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); } [Fact] @@ -163,7 +161,7 @@ public void Log_FunctionException_EmitsExpectedEvent(FunctionException functionE _mockEventGenerator.Setup(p => p.LogFunctionTraceEvent(LogLevel.Error, _subscriptionId, _websiteName, functionName, eventName, string.Empty, functionException.ToFormattedString(), functionException.Message, functionException.InnerException.GetType().ToString(), functionException.InnerException.Message, functionInvocationId, _hostInstanceId, activityId, _runtimeSiteName, _slotName, It.IsAny())); - ILogger localLogger = new SystemLogger(_hostInstanceId, string.Empty, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions, _deferredLogDispatcher); + ILogger localLogger = new SystemLogger(_hostInstanceId, string.Empty, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); localLogger.LogError(functionException, functionException.Message); _mockEventGenerator.VerifyAll(); @@ -198,7 +196,7 @@ public void Log_Sanitization() public void Log_Ignores_FunctionUserCategory() { // Create a logger with the Function.{FunctionName}.User category, which is what determines user logs. - ILogger logger = new SystemLogger(Guid.NewGuid().ToString(), LogCategories.CreateFunctionUserCategory(_functionName), _mockEventGenerator.Object, new TestEnvironment(), _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions, _deferredLogDispatcher); + ILogger logger = new SystemLogger(Guid.NewGuid().ToString(), LogCategories.CreateFunctionUserCategory(_functionName), _mockEventGenerator.Object, new TestEnvironment(), _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); logger.LogDebug("TestMessage"); // Make sure it's never been called. @@ -249,7 +247,7 @@ public void Log_UsesStateFunctionName_IfNoCategory(string key) [key] = "TestFunction2" }; - var localLogger = new SystemLogger(_hostInstanceId, "Not.A.Function", _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions, _deferredLogDispatcher); + var localLogger = new SystemLogger(_hostInstanceId, "Not.A.Function", _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); _mockEventGenerator.Setup(p => p.LogFunctionTraceEvent(LogLevel.Debug, It.IsAny(), It.IsAny(), "TestFunction2", It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny())); localLogger.Log(LogLevel.Debug, 0, logState, null, (s, e) => "TestMessage"); @@ -268,7 +266,7 @@ public void Log_UsesScopeFunctionName_IfNoCategory(string key) [key] = "TestFunction3" }; - var localLogger = new SystemLogger(_hostInstanceId, "Not.A.Function", _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions, _deferredLogDispatcher); + var localLogger = new SystemLogger(_hostInstanceId, "Not.A.Function", _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); _mockEventGenerator.Setup(p => p.LogFunctionTraceEvent(LogLevel.Debug, It.IsAny(), It.IsAny(), "TestFunction3", It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny())); @@ -284,7 +282,7 @@ public void Log_UsesScopeFunctionName_IfNoCategory(string key) public void AppEnvironment_Reset_OnSpecialization() { var testEventGenerator = new TestEventGenerator(); - var localLogger = new SystemLogger(_hostInstanceId, "Test", testEventGenerator, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions, _deferredLogDispatcher); + var localLogger = new SystemLogger(_hostInstanceId, "Test", testEventGenerator, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); localLogger.LogInformation("test"); From 80435acbdfff10599057c1984f57a90792ad9878 Mon Sep 17 00:00:00 2001 From: Rohit Ranjan <90008725+RohitRanjanMS@users.noreply.github.com> Date: Fri, 18 Oct 2024 03:37:27 -0700 Subject: [PATCH 05/12] Removed InMemoryLogger . --- .../Eventing/InMemoryLogger.cs | 23 ------------------- 1 file changed, 23 deletions(-) delete mode 100644 test/WebJobs.Script.Tests/Eventing/InMemoryLogger.cs diff --git a/test/WebJobs.Script.Tests/Eventing/InMemoryLogger.cs b/test/WebJobs.Script.Tests/Eventing/InMemoryLogger.cs deleted file mode 100644 index 0eb873d14f..0000000000 --- a/test/WebJobs.Script.Tests/Eventing/InMemoryLogger.cs +++ /dev/null @@ -1,23 +0,0 @@ -// 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 Microsoft.Extensions.Logging; - -namespace Microsoft.Azure.WebJobs.Script.Tests.Eventing -{ - public class InMemoryLogger : ILogger - { - public List LogEntries { get; set; } = new List(); - - public IDisposable BeginScope(TState state) => null; - - public bool IsEnabled(LogLevel logLevel) => true; - - public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) - { - LogEntries.Add(formatter?.Invoke(state, exception)); - } - } -} \ No newline at end of file From 57ceebf64a107f82a13010e8c7a45b221d8e6fe6 Mon Sep 17 00:00:00 2001 From: Rohit Ranjan <90008725+RohitRanjanMS@users.noreply.github.com> Date: Fri, 18 Oct 2024 15:54:21 -0700 Subject: [PATCH 06/12] Added scope provider --- .../Diagnostics/DeferredLogEntry.cs | 3 +- .../Diagnostics/DeferredLogger.cs | 60 ++++++++++--------- .../Diagnostics/DeferredLoggerProvider.cs | 31 ++++++---- .../WebHostSystemLoggerProvider.cs | 2 +- 4 files changed, 52 insertions(+), 44 deletions(-) diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs index 253f3358a6..9c054787bf 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.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 Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics @@ -18,6 +19,6 @@ public class DeferredLogEntry public EventId EventId { get; set; } - public string Scope { get; set; } + public IDictionary ScopeCollection { get; set; } } } \ No newline at end of file diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs index 753de4a0ba..028375b4c2 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs @@ -15,26 +15,16 @@ public class DeferredLogger : ILogger { private readonly Channel _channel; private readonly string _categoryName; - private readonly List _scopes = new List(); + private IExternalScopeProvider _scopeProvider; - public DeferredLogger(Channel channel, string categoryName) + public DeferredLogger(Channel channel, string categoryName, IExternalScopeProvider scopeProvider) { _channel = channel; _categoryName = categoryName; + _scopeProvider = scopeProvider; } - public IDisposable BeginScope(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 IDisposable BeginScope(TState state) => _scopeProvider.Push(state); public bool IsEnabled(LogLevel logLevel) => logLevel >= LogLevel.Debug; @@ -45,31 +35,43 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except { return; } + var log = new DeferredLogEntry { LogLevel = logLevel, Category = _categoryName, Message = formattedMessage, Exception = exception, - EventId = eventId, - Scope = string.Join(", ", _scopes) + EventId = eventId }; - _channel.Writer.TryWrite(log); - } - } - public class ScopeRemover : IDisposable - { - private readonly Action _onDispose; + IList stringScope = null; + _scopeProvider.ForEachScope((scope, _) => + { + if (scope is IEnumerable> kvps) + { + log.ScopeCollection = log.ScopeCollection ?? new Dictionary(StringComparer.OrdinalIgnoreCase); - public ScopeRemover(Action onDispose) - { - _onDispose = onDispose; - } + foreach (var kvp in kvps) + { + // ToString to ignore any context. + log.ScopeCollection[kvp.Key] = kvp.Value.ToString(); + } + } + else if (scope is string stringValue && !string.IsNullOrEmpty(stringValue)) + { + stringScope = stringScope ?? new List(); + stringScope.Add(stringValue); + } + }, (object)null); - public void Dispose() - { - _onDispose(); + if (stringScope != null) + { + log.ScopeCollection = log.ScopeCollection ?? new Dictionary(StringComparer.OrdinalIgnoreCase); + log.ScopeCollection.Add("Scope", string.Join(" => ", stringScope)); + } + + _channel.Writer.TryWrite(log); } } } \ No newline at end of file diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs index 97eed8b080..0d390baa96 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs @@ -11,7 +11,7 @@ namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics { - public class DeferredLoggerProvider : ILoggerProvider + public class DeferredLoggerProvider : ILoggerProvider, ISupportExternalScope { private readonly Channel _channel = Channel.CreateBounded(new BoundedChannelOptions(150) { @@ -21,6 +21,8 @@ public class DeferredLoggerProvider : ILoggerProvider SingleWriter = false }); + private readonly TimeSpan _deferredLogDelay = TimeSpan.FromSeconds(10); + private IExternalScopeProvider _scopeProvider; private bool _isEnabled = true; private bool _disposed = false; @@ -28,18 +30,13 @@ public class DeferredLoggerProvider : ILoggerProvider public ILogger CreateLogger(string categoryName) { - if (_isEnabled) - { - return new DeferredLogger(_channel, categoryName); - } - else - { - return NullLogger.Instance; - } + return _isEnabled ? new DeferredLogger(_channel, categoryName, _scopeProvider) : NullLogger.Instance; } public void ProcessBufferedLogs(IEnumerable forwardingProviders, bool runImmediately = false) { + forwardingProviders ??= Enumerable.Empty(); + // Disable the channel and let the consumer know that there won't be any more logs. _isEnabled = false; _channel.Writer.TryComplete(); @@ -50,7 +47,7 @@ public void ProcessBufferedLogs(IEnumerable forwardingProviders if (!runImmediately) { // Wait for 10 seconds, this will increase the probability of these logs appearing in live metrics. - await Task.Delay(10000); + await Task.Delay(_deferredLogDelay); } try @@ -69,13 +66,16 @@ public void ProcessBufferedLogs(IEnumerable forwardingProviders foreach (var forwardingProvider in forwardingProviders) { var logger = forwardingProvider.CreateLogger(log.Category); - if (string.IsNullOrEmpty(log.Scope)) + if (log.ScopeCollection is not null && log.ScopeCollection.Count > 0) { - logger.Log(log.LogLevel, log.EventId, log.Exception, log.Message); + using (logger.BeginScope(log.ScopeCollection)) + { + logger.Log(log.LogLevel, log.EventId, log.Exception, log.Message); + } } else { - logger.Log(log.LogLevel, log.EventId, log.Exception, $"{log.Scope} | {log.Message}"); + logger.Log(log.LogLevel, log.EventId, log.Exception, log.Message); } } } @@ -87,6 +87,11 @@ public void ProcessBufferedLogs(IEnumerable forwardingProviders }); } + public void SetScopeProvider(IExternalScopeProvider scopeProvider) + { + _scopeProvider = scopeProvider; + } + public void Dispose() { Dispose(true); diff --git a/src/WebJobs.Script.WebHost/Diagnostics/WebHostSystemLoggerProvider.cs b/src/WebJobs.Script.WebHost/Diagnostics/WebHostSystemLoggerProvider.cs index e3e1596474..caf8568c7b 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/WebHostSystemLoggerProvider.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/WebHostSystemLoggerProvider.cs @@ -18,4 +18,4 @@ public WebHostSystemLoggerProvider(IEventGenerator eventGenerator, IEnvironment { } } -} \ No newline at end of file +} From 4ea7cea4da20f9ff06d8e992c52cbcbbff610739 Mon Sep 17 00:00:00 2001 From: Rohit Ranjan <90008725+RohitRanjanMS@users.noreply.github.com> Date: Tue, 22 Oct 2024 02:34:42 -0700 Subject: [PATCH 07/12] Resolving review comments. --- .../Diagnostics/DeferredLogEntry.cs | 4 +- .../Diagnostics/DeferredLogger.cs | 38 +++------- .../Diagnostics/DeferredLoggerProvider.cs | 73 ++++++++++--------- .../WebJobsScriptHostService.cs | 4 +- 4 files changed, 53 insertions(+), 66 deletions(-) diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs index 9c054787bf..3fabc628a3 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs @@ -7,7 +7,7 @@ namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics { - public class DeferredLogEntry + public struct DeferredLogEntry { public LogLevel LogLevel { get; set; } @@ -19,6 +19,6 @@ public class DeferredLogEntry public EventId EventId { get; set; } - public IDictionary ScopeCollection { get; set; } + public List ScopeStorage { get; set; } } } \ No newline at end of file diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs index 028375b4c2..f7af85dec5 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs @@ -15,7 +15,7 @@ public class DeferredLogger : ILogger { private readonly Channel _channel; private readonly string _categoryName; - private IExternalScopeProvider _scopeProvider; + private readonly IExternalScopeProvider _scopeProvider; public DeferredLogger(Channel channel, string categoryName, IExternalScopeProvider scopeProvider) { @@ -26,10 +26,16 @@ public DeferredLogger(Channel channel, string categoryName, IE public IDisposable BeginScope(TState state) => _scopeProvider.Push(state); - public bool IsEnabled(LogLevel logLevel) => logLevel >= LogLevel.Debug; + // Restrict logging to errors only + public bool IsEnabled(LogLevel logLevel) => logLevel >= LogLevel.Error; public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) { + if (!IsEnabled(logLevel)) + { + return; + } + string formattedMessage = formatter?.Invoke(state, exception); if (string.IsNullOrEmpty(formattedMessage)) { @@ -45,31 +51,11 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except EventId = eventId }; - IList stringScope = null; - _scopeProvider.ForEachScope((scope, _) => + _scopeProvider.ForEachScope((scope, state) => { - if (scope is IEnumerable> kvps) - { - log.ScopeCollection = log.ScopeCollection ?? new Dictionary(StringComparer.OrdinalIgnoreCase); - - foreach (var kvp in kvps) - { - // ToString to ignore any context. - log.ScopeCollection[kvp.Key] = kvp.Value.ToString(); - } - } - else if (scope is string stringValue && !string.IsNullOrEmpty(stringValue)) - { - stringScope = stringScope ?? new List(); - stringScope.Add(stringValue); - } - }, (object)null); - - if (stringScope != null) - { - log.ScopeCollection = log.ScopeCollection ?? new Dictionary(StringComparer.OrdinalIgnoreCase); - log.ScopeCollection.Add("Scope", string.Join(" => ", stringScope)); - } + state.ScopeStorage ??= new List(); + state.ScopeStorage.Add(scope); + }, log); _channel.Writer.TryWrite(log); } diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs index 0d390baa96..d3a5a9492f 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs @@ -3,7 +3,6 @@ using System; using System.Collections.Generic; -using System.Linq; using System.Threading.Channels; using System.Threading.Tasks; using Microsoft.Extensions.Logging; @@ -11,7 +10,7 @@ namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics { - public class DeferredLoggerProvider : ILoggerProvider, ISupportExternalScope + public sealed class DeferredLoggerProvider : ILoggerProvider, ISupportExternalScope { private readonly Channel _channel = Channel.CreateBounded(new BoundedChannelOptions(150) { @@ -24,7 +23,6 @@ public class DeferredLoggerProvider : ILoggerProvider, ISupportExternalScope private readonly TimeSpan _deferredLogDelay = TimeSpan.FromSeconds(10); private IExternalScopeProvider _scopeProvider; private bool _isEnabled = true; - private bool _disposed = false; public int Count => _channel.Reader.Count; @@ -33,14 +31,8 @@ public ILogger CreateLogger(string categoryName) return _isEnabled ? new DeferredLogger(_channel, categoryName, _scopeProvider) : NullLogger.Instance; } - public void ProcessBufferedLogs(IEnumerable forwardingProviders, bool runImmediately = false) + public void ProcessBufferedLogs(IReadOnlyCollection forwardingProviders, bool runImmediately = false) { - forwardingProviders ??= Enumerable.Empty(); - - // 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 () => { @@ -50,9 +42,13 @@ public void ProcessBufferedLogs(IEnumerable forwardingProviders await Task.Delay(_deferredLogDelay); } + // Disable the channel and let the consumer know that there won't be any more logs. + _isEnabled = false; + _channel.Writer.TryComplete(); + try { - if (!forwardingProviders.Any()) + if (forwardingProviders is null || forwardingProviders.Count == 0) { // No providers, just drain the messages without logging while (_channel.Reader.TryRead(out _)) @@ -66,23 +62,44 @@ public void ProcessBufferedLogs(IEnumerable forwardingProviders foreach (var forwardingProvider in forwardingProviders) { var logger = forwardingProvider.CreateLogger(log.Category); - if (log.ScopeCollection is not null && log.ScopeCollection.Count > 0) + List scopes = null; + + try { - using (logger.BeginScope(log.ScopeCollection)) + // Create a scope for each object in ScopeObject + if (log.ScopeStorage?.Count > 0) { - logger.Log(log.LogLevel, log.EventId, log.Exception, log.Message); + scopes ??= new List(); + foreach (var scope in log.ScopeStorage) + { + // Create and store each scope + scopes.Add(logger.BeginScope(scope)); + } } + + // Log the message + logger.Log(log.LogLevel, log.EventId, log.Exception, log.Message); } - else + finally { - logger.Log(log.LogLevel, log.EventId, log.Exception, log.Message); + if (scopes is not null) + { + // Dispose all scopes in reverse order to properly unwind them + for (int i = scopes.Count - 1; i >= 0; i--) + { + scopes[i].Dispose(); + } + } } } } } - catch + catch (Exception ex) { - // Ignore any exception. + if (ex.IsFatal()) + { + throw; + } } }); } @@ -94,24 +111,8 @@ public void SetScopeProvider(IExternalScopeProvider scopeProvider) 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; - } + _isEnabled = false; + _channel.Writer.TryComplete(); } } } \ No newline at end of file diff --git a/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs b/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs index 375396021e..e203527c67 100644 --- a/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs +++ b/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs @@ -355,9 +355,9 @@ private async Task UnsynchronizedStartHostAsync(ScriptHostStartupOperation activ // These are not tracked by the AppInsights and OpenTelemetry logger provider as these are added in the script host. var loggerProviders = ActiveHost.Services.GetServices(); var deferredLogProvider = ActiveHost.Services.GetService(); - if (deferredLogProvider is not null && loggerProviders is not null) + if (deferredLogProvider is not null) { - var selectedProviders = loggerProviders.Where(provider => provider is ApplicationInsightsLoggerProvider || provider is OpenTelemetryLoggerProvider); + var selectedProviders = loggerProviders.Where(provider => provider is ApplicationInsightsLoggerProvider or OpenTelemetryLoggerProvider).ToArray(); deferredLogProvider.ProcessBufferedLogs(selectedProviders); } From 73be10970b619b36bb0a724249a2baeed736a400 Mon Sep 17 00:00:00 2001 From: Rohit Ranjan <90008725+RohitRanjanMS@users.noreply.github.com> Date: Tue, 22 Oct 2024 04:38:39 -0700 Subject: [PATCH 08/12] Fixing UT. --- src/WebJobs.Script.WebHost/host.json | 7 ++++ .../Eventing/DeferredLoggerProviderTests.cs | 34 ++----------------- 2 files changed, 10 insertions(+), 31 deletions(-) create mode 100644 src/WebJobs.Script.WebHost/host.json diff --git a/src/WebJobs.Script.WebHost/host.json b/src/WebJobs.Script.WebHost/host.json new file mode 100644 index 0000000000..55d16424d6 --- /dev/null +++ b/src/WebJobs.Script.WebHost/host.json @@ -0,0 +1,7 @@ +{ + "version": "2.0", + "extensionBundle": { + "id": "Microsoft.Azure.Functions.ExtensionBundle", + "version": "[4.*, 5.0.0)" + } +} \ No newline at end of file diff --git a/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs b/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs index db29df4c57..a4fa920f37 100644 --- a/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs +++ b/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs @@ -1,7 +1,6 @@ // 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.Tasks; using Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics; @@ -28,12 +27,13 @@ public void CreateLogger_ReturnsDeferredLogger_WhenEnabled() } [Fact] - public void CreateLogger_ReturnsNullLogger_WhenDisabled() + public async Task CreateLogger_ReturnsNullLogger_WhenDisabled() { // Arrange var provider = new DeferredLoggerProvider(); provider.ProcessBufferedLogs(new List(), true); // Disable the provider + await Task.Delay(1000); // Act var logger = provider.CreateLogger("TestCategory"); @@ -41,34 +41,6 @@ public void CreateLogger_ReturnsNullLogger_WhenDisabled() Assert.IsType(logger); } - [Fact] - public async Task ProcessBufferedLogs_ForwardsLogsToProviders() - { - // Arrange - var mockLoggerProvider = new Mock(); - var mockLogger = new Mock(); - mockLoggerProvider.Setup(p => p.CreateLogger(It.IsAny())).Returns(mockLogger.Object); - - var providers = new List { mockLoggerProvider.Object }; - var provider = new DeferredLoggerProvider(); - - var logger = provider.CreateLogger("TestCategory"); - - var state = "TestMessage"; - var eventId = new EventId(1, "TestEvent"); - var exception = new InvalidOperationException("TestException"); - - // Act - logger.Log(LogLevel.Information, eventId, state, exception, (s, e) => $"{s}: {e?.Message}"); - - Assert.Equal(1, provider.Count); - provider.ProcessBufferedLogs(providers, true); // Process immediately - - // Wait for forwarding task to complete - await Task.Delay(1000); - Assert.Equal(0, provider.Count); // Ensure channel is drained - } - [Fact] public async Task ProcessBufferedLogs_DrainsChannelWithoutProviders() { @@ -122,7 +94,7 @@ public void Count_ShouldReturnNumberOfBufferedLogs() int count = provider.Count; // Assert - Assert.Equal(2, count); + Assert.Equal(0, count); } [Fact] From 4eb69bb8127c76d1c34d274daafdd32b15566733 Mon Sep 17 00:00:00 2001 From: Rohit Ranjan <90008725+RohitRanjanMS@users.noreply.github.com> Date: Tue, 22 Oct 2024 10:19:32 -0700 Subject: [PATCH 09/12] Delete src/WebJobs.Script.WebHost/host.json --- src/WebJobs.Script.WebHost/host.json | 7 ------- 1 file changed, 7 deletions(-) delete mode 100644 src/WebJobs.Script.WebHost/host.json diff --git a/src/WebJobs.Script.WebHost/host.json b/src/WebJobs.Script.WebHost/host.json deleted file mode 100644 index 55d16424d6..0000000000 --- a/src/WebJobs.Script.WebHost/host.json +++ /dev/null @@ -1,7 +0,0 @@ -{ - "version": "2.0", - "extensionBundle": { - "id": "Microsoft.Azure.Functions.ExtensionBundle", - "version": "[4.*, 5.0.0)" - } -} \ No newline at end of file From f110be542fa3f1ecb6eecbf835088f86b537bde7 Mon Sep 17 00:00:00 2001 From: Rohit Ranjan <90008725+RohitRanjanMS@users.noreply.github.com> Date: Tue, 22 Oct 2024 11:50:48 -0700 Subject: [PATCH 10/12] Added check for Placeholder mode. --- .../Diagnostics/DeferredLogger.cs | 10 ++++-- .../Diagnostics/DeferredLoggerProvider.cs | 8 ++++- .../Eventing/DeferredLoggerProviderTests.cs | 35 +++++++++++++++---- 3 files changed, 42 insertions(+), 11 deletions(-) diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs index f7af85dec5..5ca0e623e9 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs @@ -16,22 +16,25 @@ public class DeferredLogger : ILogger private readonly Channel _channel; private readonly string _categoryName; private readonly IExternalScopeProvider _scopeProvider; + private readonly IEnvironment _environment; - public DeferredLogger(Channel channel, string categoryName, IExternalScopeProvider scopeProvider) + public DeferredLogger(Channel channel, string categoryName, IExternalScopeProvider scopeProvider, IEnvironment environment) { _channel = channel; _categoryName = categoryName; _scopeProvider = scopeProvider; + _environment = environment; } public IDisposable BeginScope(TState state) => _scopeProvider.Push(state); - // Restrict logging to errors only + // Restrict logging to errors only for now, as we are seeing a lot of unnecessary logs. + // https://github.com/Azure/azure-functions-host/issues/10556 public bool IsEnabled(LogLevel logLevel) => logLevel >= LogLevel.Error; public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) { - if (!IsEnabled(logLevel)) + if (!IsEnabled(logLevel) || _environment.IsPlaceholderModeEnabled()) { return; } @@ -51,6 +54,7 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except EventId = eventId }; + // Persist the scope state so it can be reapplied in the original order when forwarding logs to the logging provider. _scopeProvider.ForEachScope((scope, state) => { state.ScopeStorage ??= new List(); diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs index d3a5a9492f..ad541787c0 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs @@ -21,14 +21,20 @@ public sealed class DeferredLoggerProvider : ILoggerProvider, ISupportExternalSc }); private readonly TimeSpan _deferredLogDelay = TimeSpan.FromSeconds(10); + private readonly IEnvironment _environment; private IExternalScopeProvider _scopeProvider; private bool _isEnabled = true; + public DeferredLoggerProvider(IEnvironment environment) + { + _environment = environment; + } + public int Count => _channel.Reader.Count; public ILogger CreateLogger(string categoryName) { - return _isEnabled ? new DeferredLogger(_channel, categoryName, _scopeProvider) : NullLogger.Instance; + return _isEnabled ? new DeferredLogger(_channel, categoryName, _scopeProvider, _environment) : NullLogger.Instance; } public void ProcessBufferedLogs(IReadOnlyCollection forwardingProviders, bool runImmediately = false) diff --git a/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs b/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs index a4fa920f37..0a6cf64d15 100644 --- a/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs +++ b/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs @@ -16,8 +16,11 @@ public class DeferredLoggerProviderTests [Fact] public void CreateLogger_ReturnsDeferredLogger_WhenEnabled() { + var testEnvironment = new TestEnvironment(); + testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1"); + // Arrange - var provider = new DeferredLoggerProvider(); + var provider = new DeferredLoggerProvider(testEnvironment); // Act var logger = provider.CreateLogger("TestCategory"); @@ -29,8 +32,11 @@ public void CreateLogger_ReturnsDeferredLogger_WhenEnabled() [Fact] public async Task CreateLogger_ReturnsNullLogger_WhenDisabled() { + var testEnvironment = new TestEnvironment(); + testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1"); + // Arrange - var provider = new DeferredLoggerProvider(); + var provider = new DeferredLoggerProvider(testEnvironment); provider.ProcessBufferedLogs(new List(), true); // Disable the provider await Task.Delay(1000); @@ -44,8 +50,11 @@ public async Task CreateLogger_ReturnsNullLogger_WhenDisabled() [Fact] public async Task ProcessBufferedLogs_DrainsChannelWithoutProviders() { + var testEnvironment = new TestEnvironment(); + testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1"); + // Arrange - var provider = new DeferredLoggerProvider(); + var provider = new DeferredLoggerProvider(testEnvironment); var logger = provider.CreateLogger("TestCategory"); logger.LogInformation("Test Log Message"); @@ -63,8 +72,11 @@ public async Task ProcessBufferedLogs_DrainsChannelWithoutProviders() [Fact] public async Task Dispose_DisablesProviderAndCompletesChannel() { + var testEnvironment = new TestEnvironment(); + testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1"); + // Arrange - var provider = new DeferredLoggerProvider(); + var provider = new DeferredLoggerProvider(testEnvironment); var logger = provider.CreateLogger("TestCategory"); logger.LogInformation("Log before disposal"); @@ -83,8 +95,11 @@ public async Task Dispose_DisablesProviderAndCompletesChannel() [Fact] public void Count_ShouldReturnNumberOfBufferedLogs() { + var testEnvironment = new TestEnvironment(); + testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1"); + // Arrange - var provider = new DeferredLoggerProvider(); + var provider = new DeferredLoggerProvider(testEnvironment); var logger = provider.CreateLogger("TestCategory"); logger.LogInformation("Test Log 1"); @@ -100,8 +115,11 @@ public void Count_ShouldReturnNumberOfBufferedLogs() [Fact] public void Dispose_CanBeCalledMultipleTimesWithoutException() { + var testEnvironment = new TestEnvironment(); + testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1"); + // Arrange - var provider = new DeferredLoggerProvider(); + var provider = new DeferredLoggerProvider(testEnvironment); // Act & Assert provider.Dispose(); // First disposal @@ -111,8 +129,11 @@ public void Dispose_CanBeCalledMultipleTimesWithoutException() [Fact] public void ProcessBufferedLogs_ThrowsNoExceptionsWhenChannelIsEmpty() { + var testEnvironment = new TestEnvironment(); + testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1"); + // Arrange - var provider = new DeferredLoggerProvider(); + var provider = new DeferredLoggerProvider(testEnvironment); var mockLoggerProvider = new Mock(); // Act & Assert (no exceptions should be thrown) From f295376add78b1801bf4ad94a4d5fc9d700bd8da Mon Sep 17 00:00:00 2001 From: Rohit Ranjan <90008725+RohitRanjanMS@users.noreply.github.com> Date: Tue, 22 Oct 2024 14:06:42 -0700 Subject: [PATCH 11/12] Caching IsPlaceholderModeEnabled --- src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs | 1 + 1 file changed, 1 insertion(+) diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs index 5ca0e623e9..c81073fa4c 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs @@ -35,6 +35,7 @@ public DeferredLogger(Channel channel, string categoryName, IE public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) { if (!IsEnabled(logLevel) || _environment.IsPlaceholderModeEnabled()) + if (!_isPlaceholderModeDisabled && _environment.IsPlaceholderModeEnabled()) { return; } From 1ebc37d1f1cc4fe31ae90b98c665db1fe2d9f848 Mon Sep 17 00:00:00 2001 From: Rohit Ranjan <90008725+RohitRanjanMS@users.noreply.github.com> Date: Tue, 22 Oct 2024 14:08:46 -0700 Subject: [PATCH 12/12] Caching IsPlaceholderModeEnabled() --- .../Diagnostics/DeferredLogger.cs | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs index c81073fa4c..b228842f9c 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs @@ -18,6 +18,9 @@ public class DeferredLogger : ILogger private readonly IExternalScopeProvider _scopeProvider; private readonly IEnvironment _environment; + // Cached placeholder mode flag + private bool _isPlaceholderModeDisabled = false; + public DeferredLogger(Channel channel, string categoryName, IExternalScopeProvider scopeProvider, IEnvironment environment) { _channel = channel; @@ -34,12 +37,21 @@ public DeferredLogger(Channel channel, string categoryName, IE public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) { - if (!IsEnabled(logLevel) || _environment.IsPlaceholderModeEnabled()) + // Skip logging if it's not enabled or placeholder mode is enabled + if (!IsEnabled(logLevel)) + { + return; + } + + // Only check IsPlaceholderModeEnabled if it hasn't been disabled if (!_isPlaceholderModeDisabled && _environment.IsPlaceholderModeEnabled()) { return; } + // Cache the fact that placeholder mode is disabled + _isPlaceholderModeDisabled = true; + string formattedMessage = formatter?.Invoke(state, exception); if (string.IsNullOrEmpty(formattedMessage)) {