diff --git a/release_notes.md b/release_notes.md index 99bd2089df..2c0894880a 100644 --- a/release_notes.md +++ b/release_notes.md @@ -2,4 +2,6 @@ \ No newline at end of file +--> + +- Suppress Storage queue and blob listener polling noise from telemetry by event name, preserving listener lifecycle and diagnostic logs (#11947) \ 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 bc49530caa..76391485da 100644 --- a/src/WebJobs.Script.WebHost/Diagnostics/SystemLogger.cs +++ b/src/WebJobs.Script.WebHost/Diagnostics/SystemLogger.cs @@ -16,11 +16,27 @@ namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics { public class SystemLogger : ILogger { + // High-volume logs that are suppressed from system telemetry (FunctionsLogs) below Information. + // An empty event name list suppresses the whole category; otherwise only the listed EventNames + // are suppressed, so other diagnostics in that category are still reported. + // To suppress more logs, add a category here - no other changes are required. + private static readonly Dictionary _suppressedLogs = new(StringComparer.Ordinal) + { + ["Host.Executor"] = [], // An empty list suppresses every event in the category. + ["Microsoft.Azure.WebJobs.EventHubs.EventHubProducerClientImpl"] = [], + ["Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener"] = ["GetMessages", "BackoffDelay"], + ["Microsoft.Azure.WebJobs.Host.Queues.Listeners.QueueListener"] = ["GetMessages", "BackoffDelay"], + ["Microsoft.Azure.WebJobs.Extensions.Storage.Blobs.Listeners.BlobListener"] = ["PollBlobContainer", "BlobAlreadyProcessed", "BlobDoesNotMatchPattern"] + }; + private readonly string _categoryName; private readonly string _functionName; private readonly string _hostInstanceId; private readonly bool _isUserFunction; private readonly LogLevel _logLevel; + + // Null when nothing is suppressed for this category. Resolved once so the per-log check stays cheap. + private readonly string[] _suppressedEventNames; private readonly IEnvironment _environment; private readonly IEventGenerator _eventGenerator; private readonly IDebugStateProvider _debugStateProvider; @@ -35,6 +51,7 @@ public SystemLogger(string hostInstanceId, string categoryName, IEventGenerator _eventGenerator = eventGenerator; _categoryName = categoryName ?? string.Empty; _logLevel = LogLevel.Debug; + _suppressedLogs.TryGetValue(_categoryName, out _suppressedEventNames); _functionName = LogCategories.IsFunctionCategory(_categoryName) ? _categoryName.Split('.')[1] : null; _isUserFunction = LogCategories.IsFunctionUserCategory(_categoryName); _hostInstanceId = hostInstanceId; @@ -114,6 +131,14 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except _eventManager.Publish(new FunctionIndexingEvent(nameof(FunctionIndexingException), source, exception)); } + string eventName = !string.IsNullOrEmpty(eventId.Name) ? eventId.Name : stateEventName ?? string.Empty; + eventName = isDiagnosticEvent ? $"DiagnosticEvent-{diagnosticEventErrorCode}" : eventName; + + if (_suppressedEventNames is not null && ShouldSuppress(eventName, logLevel)) + { + return; + } + // If we don't have a message, there's nothing to log. string formattedMessage = formatter?.Invoke(state, exception); if (string.IsNullOrEmpty(formattedMessage)) @@ -152,9 +177,6 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except // Apply standard event properties. // Note: we must be sure to default any null values to empty string // otherwise the ETW event will fail to be persisted (silently). - string eventName = !string.IsNullOrEmpty(eventId.Name) ? eventId.Name : stateEventName ?? string.Empty; - eventName = isDiagnosticEvent ? $"DiagnosticEvent-{diagnosticEventErrorCode}" : eventName; - string activityId = stateActivityId ?? scopeActivityId ?? string.Empty; var options = _appServiceOptions; string subscriptionId = options.SubscriptionId ?? string.Empty; @@ -178,5 +200,23 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except _eventGenerator.LogFunctionTraceEvent(logLevel, subscriptionId, appName, functionName, eventName, source, details, formattedMessage, innerExceptionType, innerExceptionMessage, invocationId, _hostInstanceId, activityId, runtimeSiteName, slotName, DateTime.UtcNow); } + + // Only called when _suppressedEventNames is not null, so the category has suppression configured. + private bool ShouldSuppress(string eventName, LogLevel logLevel) + { + if (logLevel >= LogLevel.Information) + { + return false; + } + + // An empty list suppresses the entire category. + if (_suppressedEventNames.Length > 0 && Array.IndexOf(_suppressedEventNames, eventName) < 0) + { + return false; + } + + // Diagnostic mode logs everything. + return !_debugStateProvider.InDiagnosticMode; + } } } \ No newline at end of file diff --git a/src/WebJobs.Script/Extensions/ScriptLoggingBuilderExtensions.cs b/src/WebJobs.Script/Extensions/ScriptLoggingBuilderExtensions.cs index eca26e5b06..44096cd5b2 100644 --- a/src/WebJobs.Script/Extensions/ScriptLoggingBuilderExtensions.cs +++ b/src/WebJobs.Script/Extensions/ScriptLoggingBuilderExtensions.cs @@ -3,7 +3,6 @@ using System; using System.Collections.Concurrent; -using System.Collections.Generic; using System.Linq; using Microsoft.AspNetCore.Hosting; using Microsoft.Azure.WebJobs.Script; @@ -19,15 +18,6 @@ public static class ScriptLoggingBuilderExtensions { private static readonly ConcurrentDictionary _filteredCategoryCache = new(); - // High-volume extension categories whose Debug/Trace logs are - // suppressed to reduce noise in the FunctionsLogs table. - private static readonly HashSet _suppressedCategories = new(StringComparer.Ordinal) - { - "Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener", - "Microsoft.Azure.WebJobs.EventHubs.EventHubProducerClientImpl", - "Host.Executor" - }; - public static ILoggingBuilder AddForwardingLogger(this ILoggingBuilder builder) { ArgumentNullException.ThrowIfNull(builder); @@ -61,20 +51,9 @@ internal static bool Filter(string category, LogLevel actualLevel, LogLevel minL return false; } - // Suppress Debug/ Trace from high-volume extension categories. - if (actualLevel < LogLevel.Information && IsSuppressedCategory(category)) - { - return false; - } - return true; } - private static bool IsSuppressedCategory(string category) - { - return _suppressedCategories.Contains(category); - } - private static bool IsFiltered(string category) { return _filteredCategoryCache.GetOrAdd( diff --git a/test/WebJobs.Script.Tests/Eventing/SystemLoggerTests.cs b/test/WebJobs.Script.Tests/Eventing/SystemLoggerTests.cs index ee90c33548..61aee63f17 100644 --- a/test/WebJobs.Script.Tests/Eventing/SystemLoggerTests.cs +++ b/test/WebJobs.Script.Tests/Eventing/SystemLoggerTests.cs @@ -108,6 +108,295 @@ public void Log_Verbose_EmitsExpectedEvent() _mockEventGenerator.VerifyAll(); } + [Theory] + [InlineData("Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener", "GetMessages")] + [InlineData("Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener", "BackoffDelay")] + [InlineData("Microsoft.Azure.WebJobs.Host.Queues.Listeners.QueueListener", "GetMessages")] + [InlineData("Microsoft.Azure.WebJobs.Host.Queues.Listeners.QueueListener", "BackoffDelay")] + [InlineData("Microsoft.Azure.WebJobs.Extensions.Storage.Blobs.Listeners.BlobListener", "PollBlobContainer")] + [InlineData("Microsoft.Azure.WebJobs.Extensions.Storage.Blobs.Listeners.BlobListener", "BlobAlreadyProcessed")] + [InlineData("Microsoft.Azure.WebJobs.Extensions.Storage.Blobs.Listeners.BlobListener", "BlobDoesNotMatchPattern")] + public void Log_SuppressedEvent_DoesNotEmitEvent(string category, string eventName) + { + bool formatterInvoked = false; + var localLogger = new SystemLogger(_hostInstanceId, category, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + + localLogger.Log( + LogLevel.Debug, + new EventId(1, eventName), + state: string.Empty, + exception: null, + (state, exception) => + { + formatterInvoked = true; + return "TestMessage"; + }); + + Assert.False(formatterInvoked); + _mockEventGenerator.Verify( + p => p.LogFunctionTraceEvent( + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny()), + Times.Never); + } + + [Theory] + [InlineData(null)] + [InlineData("")] + public void Log_NullOrEmptyCategory_DoesNotThrow(string category) + { + _mockEventGenerator.Setup(p => p.LogFunctionTraceEvent( + It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), + It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), + It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), + It.IsAny())); + + var localLogger = new SystemLogger(_hostInstanceId, category, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + + localLogger.LogDebug("TestMessage"); + + _mockEventGenerator.VerifyAll(); + } + + [Fact] + public void Log_SuppressedCategory_UnnamedEvent_IsEmitted() + { + // Listener lifecycle logs carry no EventName and must survive named-event suppression. + const string category = "Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener"; + var localLogger = new SystemLogger(_hostInstanceId, category, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + + _mockEventGenerator.Setup(p => p.LogFunctionTraceEvent( + LogLevel.Debug, _subscriptionId, _websiteName, string.Empty, string.Empty, category, string.Empty, + "Storage queue listener started", string.Empty, string.Empty, string.Empty, _hostInstanceId, + string.Empty, _runtimeSiteName, _slotName, It.IsAny())); + + localLogger.LogDebug("Storage queue listener started"); + + _mockEventGenerator.VerifyAll(); + } + + [Fact] + public void Log_SuppressedCategory_NullStateEventName_DoesNotThrow() + { + const string category = "Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener"; + var localLogger = new SystemLogger(_hostInstanceId, category, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + var state = new Dictionary + { + [ScriptConstants.LogPropertyEventNameKey] = null + }; + + _mockEventGenerator.Setup(p => p.LogFunctionTraceEvent( + LogLevel.Debug, _subscriptionId, _websiteName, string.Empty, string.Empty, category, string.Empty, + "TestMessage", string.Empty, string.Empty, string.Empty, _hostInstanceId, + string.Empty, _runtimeSiteName, _slotName, It.IsAny())); + + localLogger.Log(LogLevel.Debug, eventId: 0, state, null, (s, e) => "TestMessage"); + + _mockEventGenerator.VerifyAll(); + } + + [Fact] + public void Log_SuppressedEvent_TraceLevel_DoesNotThrow() + { + // Trace only passes IsEnabled in diagnostic mode, where suppression is bypassed. + const string category = "Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener"; + var localLogger = new SystemLogger(_hostInstanceId, category, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + + localLogger.Log(LogLevel.Trace, new EventId(1, "GetMessages"), string.Empty, null, (s, e) => "TestMessage"); + + _mockEventGenerator.Verify( + p => p.LogFunctionTraceEvent( + It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), + It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), + It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), + It.IsAny()), + Times.Never); + + _inDiagnosticMode = true; + _mockEventGenerator.Setup(p => p.LogFunctionTraceEvent( + LogLevel.Trace, _subscriptionId, _websiteName, string.Empty, "GetMessages", category, string.Empty, + "TestMessage", string.Empty, string.Empty, string.Empty, _hostInstanceId, + string.Empty, _runtimeSiteName, _slotName, It.IsAny())); + + localLogger.Log(LogLevel.Trace, new EventId(1, "GetMessages"), string.Empty, null, (s, e) => "TestMessage"); + + _mockEventGenerator.VerifyAll(); + } + + [Theory] + [InlineData("Host.Executor")] + [InlineData("Microsoft.Azure.WebJobs.EventHubs.EventHubProducerClientImpl")] + public void Log_SuppressedCategory_DoesNotEmitEvent(string category) + { + var localLogger = new SystemLogger(_hostInstanceId, category, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + + localLogger.LogDebug("TestMessage"); + + _mockEventGenerator.Verify( + p => p.LogFunctionTraceEvent( + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny()), + Times.Never); + } + + [Fact] + public void Log_SuppressedStateEventName_DoesNotEmitEvent() + { + const string category = "Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener"; + var localLogger = new SystemLogger(_hostInstanceId, category, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + var state = new Dictionary + { + [ScriptConstants.LogPropertyEventNameKey] = "GetMessages" + }; + + localLogger.Log(LogLevel.Debug, eventId: 0, state, null, (logState, exception) => "TestMessage"); + + _mockEventGenerator.Verify( + p => p.LogFunctionTraceEvent( + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny()), + Times.Never); + } + + [Theory] + [InlineData("Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener", "HandlingStorageException", LogLevel.Debug)] + [InlineData("Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener", "GetMessages", LogLevel.Information)] + [InlineData("Microsoft.Azure.WebJobs.Extensions.Storage.Blobs.Listeners.BlobListener", "BlobMessageEnqueued", LogLevel.Debug)] + [InlineData("Microsoft.Azure.WebJobs.EventHubs.Listeners.EventHubListener.PartitionProcessor", "", LogLevel.Debug)] + [InlineData("Host.Triggers.Kafka", "", LogLevel.Debug)] + [InlineData("Host.Executor", "", LogLevel.Information)] + [InlineData("Microsoft.Azure.WebJobs.EventHubs.EventHubProducerClientImpl", "", LogLevel.Error)] + public void Log_NonSuppressedEvent_EmitsEvent(string category, string eventName, LogLevel logLevel) + { + var localLogger = new SystemLogger(_hostInstanceId, category, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + + _mockEventGenerator.Setup(p => p.LogFunctionTraceEvent( + logLevel, + _subscriptionId, + _websiteName, + string.Empty, + eventName, + category, + string.Empty, + "TestMessage", + string.Empty, + string.Empty, + string.Empty, + _hostInstanceId, + string.Empty, + _runtimeSiteName, + _slotName, + It.IsAny())); + + localLogger.Log(logLevel, new EventId(1, eventName), string.Empty, null, (state, exception) => "TestMessage"); + + _mockEventGenerator.VerifyAll(); + _debugStateProvider.VerifyGet(p => p.InDiagnosticMode, Times.Never); + } + + [Fact] + public void Log_SuppressedEventInDiagnosticMode_EmitsEvent() + { + const string category = "Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener"; + const string eventName = "GetMessages"; + var localLogger = new SystemLogger(_hostInstanceId, category, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + _inDiagnosticMode = true; + + _mockEventGenerator.Setup(p => p.LogFunctionTraceEvent( + LogLevel.Debug, + _subscriptionId, + _websiteName, + string.Empty, + eventName, + category, + string.Empty, + "TestMessage", + string.Empty, + string.Empty, + string.Empty, + _hostInstanceId, + string.Empty, + _runtimeSiteName, + _slotName, + It.IsAny())); + + localLogger.Log(LogLevel.Debug, new EventId(1, eventName), string.Empty, null, (state, exception) => "TestMessage"); + + _mockEventGenerator.VerifyAll(); + } + + [Fact] + public void Log_SuppressedCategoryInDiagnosticMode_EmitsEvent() + { + const string category = "Host.Executor"; + var localLogger = new SystemLogger(_hostInstanceId, category, _mockEventGenerator.Object, _environment, _debugStateProvider.Object, null, new LoggerExternalScopeProvider(), _appServiceOptions); + _inDiagnosticMode = true; + + _mockEventGenerator.Setup(p => p.LogFunctionTraceEvent( + LogLevel.Debug, + _subscriptionId, + _websiteName, + string.Empty, + string.Empty, + category, + string.Empty, + "TestMessage", + string.Empty, + string.Empty, + string.Empty, + _hostInstanceId, + string.Empty, + _runtimeSiteName, + _slotName, + It.IsAny())); + + localLogger.LogDebug("TestMessage"); + + _mockEventGenerator.VerifyAll(); + } + [Fact] public void Log_Verbose_LogData_EmitsExpectedEvent() { diff --git a/test/WebJobs.Script.Tests/Extensions/ScriptLoggingBuilderExtensionsTests.cs b/test/WebJobs.Script.Tests/Extensions/ScriptLoggingBuilderExtensionsTests.cs index 26cc2054a9..969778fa12 100644 --- a/test/WebJobs.Script.Tests/Extensions/ScriptLoggingBuilderExtensionsTests.cs +++ b/test/WebJobs.Script.Tests/Extensions/ScriptLoggingBuilderExtensionsTests.cs @@ -55,35 +55,15 @@ public void Filter_RespectsMinLevelAndCategory(string category, LogLevel actualL Assert.Equal(expected, ScriptLoggingBuilderExtensions.Filter(category, actualLevel, minLevel)); } - [Theory] - [InlineData("Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener", LogLevel.Debug)] - [InlineData("Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener", LogLevel.Trace)] - [InlineData("Microsoft.Azure.WebJobs.EventHubs.EventHubProducerClientImpl", LogLevel.Debug)] - [InlineData("Microsoft.Azure.WebJobs.EventHubs.EventHubProducerClientImpl", LogLevel.Trace)] - [InlineData("Host.Executor", LogLevel.Debug)] - [InlineData("Host.Executor", LogLevel.Trace)] - public void Filter_SuppressedCategory_DebugAndTrace_ReturnsFalse(string category, LogLevel level) - { - Assert.False(ScriptLoggingBuilderExtensions.Filter(category, level, LogLevel.Trace)); - } - - [Theory] - [InlineData("Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener", LogLevel.Information)] - [InlineData("Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener", LogLevel.Warning)] - [InlineData("Microsoft.Azure.WebJobs.EventHubs.EventHubProducerClientImpl", LogLevel.Information)] - [InlineData("Microsoft.Azure.WebJobs.EventHubs.EventHubProducerClientImpl", LogLevel.Error)] - [InlineData("Host.Executor", LogLevel.Information)] - [InlineData("Host.Executor", LogLevel.Critical)] - public void Filter_SuppressedCategory_InformationAndAbove_ReturnsTrue(string category, LogLevel level) - { - Assert.True(ScriptLoggingBuilderExtensions.Filter(category, level, LogLevel.Trace)); - } - [Theory] [InlineData("Microsoft.Azure.WebJobs.Host", LogLevel.Debug)] [InlineData("Microsoft.Azure.WebJobs.Host", LogLevel.Trace)] [InlineData("Host.Startup", LogLevel.Debug)] [InlineData("Function.MyFunc", LogLevel.Trace)] + [InlineData("Microsoft.Azure.WebJobs.Extensions.Storage.Common.Listeners.QueueListener", LogLevel.Debug)] + [InlineData("Microsoft.Azure.WebJobs.Extensions.Storage.Blobs.Listeners.BlobListener", LogLevel.Debug)] + [InlineData("Microsoft.Azure.WebJobs.EventHubs.Listeners.EventHubListener.PartitionProcessor", LogLevel.Debug)] + [InlineData("Host.Triggers.Kafka", LogLevel.Debug)] public void Filter_NonSuppressedCategory_DebugAndTrace_ReturnsTrue(string category, LogLevel level) { Assert.True(ScriptLoggingBuilderExtensions.Filter(category, level, LogLevel.Trace));