From 3542db7f49116b50fc21de82aae2ef55688f3f22 Mon Sep 17 00:00:00 2001 From: Mathew Charles Date: Tue, 22 May 2018 11:56:40 -0700 Subject: [PATCH] Exception logging for EventProcessorHost background exceptions (#1705) --- .../EventHubs/EventHubConfiguration.cs | 22 +++++- .../GlobalSuppressions.cs | 3 +- .../Config/EventHubConfigurationTests.cs | 74 +++++++++++++++++++ .../WebJobs.ServiceBus.UnitTests.csproj | 1 + 4 files changed, 98 insertions(+), 2 deletions(-) create mode 100644 test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Config/EventHubConfigurationTests.cs diff --git a/src/Microsoft.Azure.WebJobs.ServiceBus/EventHubs/EventHubConfiguration.cs b/src/Microsoft.Azure.WebJobs.ServiceBus/EventHubs/EventHubConfiguration.cs index 996ee09d6..419cba396 100644 --- a/src/Microsoft.Azure.WebJobs.ServiceBus/EventHubs/EventHubConfiguration.cs +++ b/src/Microsoft.Azure.WebJobs.ServiceBus/EventHubs/EventHubConfiguration.cs @@ -9,6 +9,8 @@ using System.Reflection; using System.Text; using Microsoft.Azure.WebJobs.Host.Config; +using Microsoft.Azure.WebJobs.Logging; +using Microsoft.Extensions.Logging; using Microsoft.ServiceBus; using Microsoft.ServiceBus.Messaging; @@ -453,7 +455,25 @@ void IExtensionConfigProvider.Initialize(ExtensionConfigContext context) // register our binding provider context.AddBindingRule() - .BindToCollector(BuildFromAttribute); + .BindToCollector(BuildFromAttribute); + + // Register an exception handler for background exceptions + // coming from the EventProcessorHost. + // + // EventProcessorOptions is a host level instance that is shared + // across all bindings, so we have to subscribe to it at the + // host level. + _options.ExceptionReceived += (s, e) => + { + if (!e.Exception.IsWrappedExceptionTransient()) + { + string message = $"EventProcessorHost error (Action={e.Action})"; + var logger = context.Config.LoggerFactory?.CreateLogger(LogCategories.Executor); + logger?.LogError(0, e.Exception, message); + + context.Trace.Error(message, e.Exception); + } + }; } private IAsyncCollector BuildFromAttribute(EventHubAttribute attribute) diff --git a/src/Microsoft.Azure.WebJobs.ServiceBus/GlobalSuppressions.cs b/src/Microsoft.Azure.WebJobs.ServiceBus/GlobalSuppressions.cs index 9d64b104d..fb22fcf5a 100644 --- a/src/Microsoft.Azure.WebJobs.ServiceBus/GlobalSuppressions.cs +++ b/src/Microsoft.Azure.WebJobs.ServiceBus/GlobalSuppressions.cs @@ -8,4 +8,5 @@ [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Design", "CA1014:MarkAssembliesWithClsCompliant")] [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Naming", "CA2204:Literals should be spelled correctly", MessageId = "EventHubClient", Scope = "member", Target = "Microsoft.Azure.WebJobs.ServiceBus.EventHubConfiguration.#GetEndpointFromEventHubClient(Microsoft.ServiceBus.Messaging.EventHubClient)")] [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Naming", "CA2204:Literals should be spelled correctly", MessageId = "MessagingFactory", Scope = "member", Target = "Microsoft.Azure.WebJobs.ServiceBus.EventHubConfiguration.#GetEndpointFromEventHubClient(Microsoft.ServiceBus.Messaging.EventHubClient)")] -[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Naming", "CA2204:Literals should be spelled correctly", MessageId = "MessageReceiver", Scope = "member", Target = "Microsoft.Azure.WebJobs.ServiceBus.Config.ServiceBusExtensionConfig.#Initialize(Microsoft.Azure.WebJobs.Host.Config.ExtensionConfigContext)")] \ No newline at end of file +[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Naming", "CA2204:Literals should be spelled correctly", MessageId = "MessageReceiver", Scope = "member", Target = "Microsoft.Azure.WebJobs.ServiceBus.Config.ServiceBusExtensionConfig.#Initialize(Microsoft.Azure.WebJobs.Host.Config.ExtensionConfigContext)")] +[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Naming", "CA2204:Literals should be spelled correctly", MessageId = "EventProcessorHost", Scope = "member", Target = "Microsoft.Azure.WebJobs.ServiceBus.EventHubConfiguration.#Microsoft.Azure.WebJobs.Host.Config.IExtensionConfigProvider.Initialize(Microsoft.Azure.WebJobs.Host.Config.ExtensionConfigContext)")] diff --git a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Config/EventHubConfigurationTests.cs b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Config/EventHubConfigurationTests.cs new file mode 100644 index 000000000..df9cb5492 --- /dev/null +++ b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Config/EventHubConfigurationTests.cs @@ -0,0 +1,74 @@ +// 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.Diagnostics; +using System.Linq; +using System.Reflection; +using Microsoft.Azure.WebJobs.Host; +using Microsoft.Azure.WebJobs.Host.Bindings; +using Microsoft.Azure.WebJobs.Host.Config; +using Microsoft.Azure.WebJobs.Host.TestCommon; +using Microsoft.Azure.WebJobs.Host.Triggers; +using Microsoft.Extensions.Logging; +using Microsoft.ServiceBus.Messaging; +using Xunit; + +namespace Microsoft.Azure.WebJobs.ServiceBus.UnitTests.Config +{ + public class EventHubConfigurationTests + { + [Fact] + public void Initialize_PerformsExpectedRegistrations() + { + JobHostConfiguration config = new JobHostConfiguration(); + config.AddService(new RandomNameResolver()); + + TestLoggerProvider loggerProvider = new TestLoggerProvider(); + ILoggerFactory loggerFactory = new LoggerFactory(); + loggerFactory.AddProvider(loggerProvider); + config.LoggerFactory = loggerFactory; + + EventHubConfiguration eventHubConfiguration = new EventHubConfiguration(); + + IExtensionRegistry extensions = config.GetService(); + ITriggerBindingProvider[] triggerBindingProviders = extensions.GetExtensions().ToArray(); + Assert.Equal(0, triggerBindingProviders.Length); + IBindingProvider[] bindingProviders = extensions.GetExtensions().ToArray(); + Assert.Equal(0, bindingProviders.Length); + + var traceWriter = new TestTraceWriter(TraceLevel.Verbose); + ExtensionConfigContext context = new ExtensionConfigContext + { + Config = config, + Trace = traceWriter + }; + ((IExtensionConfigProvider)eventHubConfiguration).Initialize(context); + + // ensure the EventHubTriggerAttributeBindingProvider was registered + triggerBindingProviders = extensions.GetExtensions().ToArray(); + Assert.Equal(1, triggerBindingProviders.Length); + EventHubTriggerAttributeBindingProvider triggerBindingProvider = (EventHubTriggerAttributeBindingProvider)triggerBindingProviders[0]; + Assert.NotNull(triggerBindingProvider); + + // ensure the EventProcessorOptions ExceptionReceived event is wired up + var eventProcessorOptions = eventHubConfiguration.GetOptions(); + var ex = new Exception("Kaboom!"); + var args = new ExceptionReceivedEventArgs(ex, "Testing"); + var eventDelegate = (MulticastDelegate)eventProcessorOptions.GetType().GetField("ExceptionReceived", BindingFlags.Instance | BindingFlags.NonPublic).GetValue(eventProcessorOptions); + Assert.Equal(1, eventDelegate.GetInvocationList().Length); + var handler = eventDelegate.GetInvocationList().Single(); + handler.Method.Invoke(handler.Target, new object[] { null, args }); + + string expectedMessage = "EventProcessorHost error (Action=Testing)"; + var trace = traceWriter.Traces.Last(); + Assert.Equal(expectedMessage, trace.Message); + Assert.Same(ex, trace.Exception); + + var logMessage = loggerProvider.GetAllLogMessages().Single(); + Assert.Equal(LogLevel.Error, logMessage.Level); + Assert.Equal(expectedMessage, logMessage.FormattedMessage); + Assert.Same(ex, logMessage.Exception); + } + } +} diff --git a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/WebJobs.ServiceBus.UnitTests.csproj b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/WebJobs.ServiceBus.UnitTests.csproj index 07971c6a4..0a141f202 100644 --- a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/WebJobs.ServiceBus.UnitTests.csproj +++ b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/WebJobs.ServiceBus.UnitTests.csproj @@ -201,6 +201,7 @@ +