Exception logging for EventProcessorHost background exceptions (#1705)

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<EventHubAttribute>()
-                .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<EventData> BuildFromAttribute(EventHubAttribute attribute)

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)")]
+[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)")]

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<INameResolver>(new RandomNameResolver());
+
+            TestLoggerProvider loggerProvider = new TestLoggerProvider();
+            ILoggerFactory loggerFactory = new LoggerFactory();
+            loggerFactory.AddProvider(loggerProvider);
+            config.LoggerFactory = loggerFactory;
+
+            EventHubConfiguration eventHubConfiguration = new EventHubConfiguration();
+
+            IExtensionRegistry extensions = config.GetService<IExtensionRegistry>();
+            ITriggerBindingProvider[] triggerBindingProviders = extensions.GetExtensions<ITriggerBindingProvider>().ToArray();
+            Assert.Equal(0, triggerBindingProviders.Length);
+            IBindingProvider[] bindingProviders = extensions.GetExtensions<IBindingProvider>().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<ITriggerBindingProvider>().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);
+        }
+    }
+}

test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/WebJobs.ServiceBus.UnitTests.csproj

@@ -201,6 +201,7 @@
     <Compile Include="Bindings\ServiceBusTriggerBindingTests.cs" />
     <Compile Include="BrokeredMessageToByteArrayConverterTests.cs" />
     <Compile Include="BrokeredMessageToStringConverterTests.cs" />
+    <Compile Include="Config\EventHubConfigurationTests.cs" />
     <Compile Include="Config\ServiceBusConfigurationTests.cs" />
     <Compile Include="Config\ServiceBusJobHostConfigurationExtensionsTests.cs" />
     <Compile Include="Config\ServiceBusExtensionConfigTests.cs" />