diff --git a/release_notes.md b/release_notes.md index a9f152cf4d..c9c2bc636b 100644 --- a/release_notes.md +++ b/release_notes.md @@ -8,6 +8,7 @@ - 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) - Implement host configuration property to allow configuration of the metadata provider timeout period (#10526) - The value can be set via `metadataProviderTimeout` in host.json and defaults to "00:00:30" (30 seconds). - For logic apps, unless configured via the host.json, the timeout is disabled by default. diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs new file mode 100644 index 0000000000..3fabc628a3 --- /dev/null +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs @@ -0,0 +1,24 @@ +// 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.WebHost.Diagnostics +{ + public struct 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 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 new file mode 100644 index 0000000000..b228842f9c --- /dev/null +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs @@ -0,0 +1,80 @@ +// 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 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; + _categoryName = categoryName; + _scopeProvider = scopeProvider; + _environment = environment; + } + + public IDisposable BeginScope(TState state) => _scopeProvider.Push(state); + + // 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) + { + // 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)) + { + return; + } + + var log = new DeferredLogEntry + { + LogLevel = logLevel, + Category = _categoryName, + Message = formattedMessage, + Exception = exception, + 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(); + state.ScopeStorage.Add(scope); + }, log); + + _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 new file mode 100644 index 0000000000..ad541787c0 --- /dev/null +++ b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs @@ -0,0 +1,124 @@ +// 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; +using Microsoft.Extensions.Logging.Abstractions; + +namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics +{ + public sealed class DeferredLoggerProvider : ILoggerProvider, ISupportExternalScope + { + private readonly Channel _channel = Channel.CreateBounded(new BoundedChannelOptions(150) + { + FullMode = BoundedChannelFullMode.DropOldest, + // Avoids locks and interlocked operations when reading from the channel. + SingleReader = true, + SingleWriter = false + }); + + 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, _environment) : NullLogger.Instance; + } + + public void ProcessBufferedLogs(IReadOnlyCollection forwardingProviders, bool runImmediately = false) + { + // 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(_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 is null || forwardingProviders.Count == 0) + { + // 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); + List scopes = null; + + try + { + // Create a scope for each object in ScopeObject + if (log.ScopeStorage?.Count > 0) + { + 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); + } + finally + { + 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 (Exception ex) + { + if (ex.IsFatal()) + { + throw; + } + } + }); + } + + public void SetScopeProvider(IExternalScopeProvider scopeProvider) + { + _scopeProvider = scopeProvider; + } + + public void Dispose() + { + _isEnabled = false; + _channel.Writer.TryComplete(); + } + } +} \ 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..a3cd1a484f 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; @@ -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 appServiceOptionsMonitor) { _environment = environment; @@ -181,7 +178,6 @@ 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); } } diff --git a/src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs b/src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs index cc9ee68bd0..e81a9686a9 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs @@ -61,4 +61,4 @@ public void SetScopeProvider(IExternalScopeProvider scopeProvider) _scopeProvider = scopeProvider; } } -} +} \ No newline at end of file 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/WebJobsScriptHostService.cs b/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs index 6c0f21484b..e203527c67 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,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(); + var deferredLogProvider = ActiveHost.Services.GetService(); + if (deferredLogProvider is not null) + { + var selectedProviders = loggerProviders.Where(provider => provider is ApplicationInsightsLoggerProvider or OpenTelemetryLoggerProvider).ToArray(); + deferredLogProvider.ProcessBufferedLogs(selectedProviders); + } + 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 76d3597e73..901e626711 100644 --- a/src/WebJobs.Script/WebJobs.Script.csproj +++ b/src/WebJobs.Script/WebJobs.Script.csproj @@ -93,6 +93,7 @@ + diff --git a/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs b/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs new file mode 100644 index 0000000000..0a6cf64d15 --- /dev/null +++ b/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs @@ -0,0 +1,143 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +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() + { + var testEnvironment = new TestEnvironment(); + testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1"); + + // Arrange + var provider = new DeferredLoggerProvider(testEnvironment); + + // Act + var logger = provider.CreateLogger("TestCategory"); + + // Assert + Assert.IsType(logger); + } + + [Fact] + public async Task CreateLogger_ReturnsNullLogger_WhenDisabled() + { + var testEnvironment = new TestEnvironment(); + testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1"); + + // Arrange + var provider = new DeferredLoggerProvider(testEnvironment); + provider.ProcessBufferedLogs(new List(), true); // Disable the provider + + await Task.Delay(1000); + // Act + var logger = provider.CreateLogger("TestCategory"); + + // Assert + Assert.IsType(logger); + } + + [Fact] + public async Task ProcessBufferedLogs_DrainsChannelWithoutProviders() + { + var testEnvironment = new TestEnvironment(); + testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1"); + + // Arrange + var provider = new DeferredLoggerProvider(testEnvironment); + + 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() + { + var testEnvironment = new TestEnvironment(); + testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1"); + + // Arrange + var provider = new DeferredLoggerProvider(testEnvironment); + 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() + { + var testEnvironment = new TestEnvironment(); + testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1"); + + // Arrange + var provider = new DeferredLoggerProvider(testEnvironment); + + var logger = provider.CreateLogger("TestCategory"); + logger.LogInformation("Test Log 1"); + logger.LogInformation("Test Log 2"); + + // Act + int count = provider.Count; + + // Assert + Assert.Equal(0, count); + } + + [Fact] + public void Dispose_CanBeCalledMultipleTimesWithoutException() + { + var testEnvironment = new TestEnvironment(); + testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1"); + + // Arrange + var provider = new DeferredLoggerProvider(testEnvironment); + + // Act & Assert + provider.Dispose(); // First disposal + provider.Dispose(); // Second disposal, should not throw + } + + [Fact] + public void ProcessBufferedLogs_ThrowsNoExceptionsWhenChannelIsEmpty() + { + var testEnvironment = new TestEnvironment(); + testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "1"); + + // Arrange + var provider = new DeferredLoggerProvider(testEnvironment); + var mockLoggerProvider = new Mock(); + + // Act & Assert (no exceptions should be thrown) + provider.ProcessBufferedLogs(new[] { mockLoggerProvider.Object }, true); + } + } +} \ No newline at end of file