diff --git a/src/Microsoft.Azure.WebJobs.Extensions.EventHubs/Config/EventHubExtensionConfigProvider.cs b/src/Microsoft.Azure.WebJobs.Extensions.EventHubs/Config/EventHubExtensionConfigProvider.cs index 8033e28..f338cdc 100644 --- a/src/Microsoft.Azure.WebJobs.Extensions.EventHubs/Config/EventHubExtensionConfigProvider.cs +++ b/src/Microsoft.Azure.WebJobs.Extensions.EventHubs/Config/EventHubExtensionConfigProvider.cs @@ -86,18 +86,10 @@ public void Initialize(ExtensionConfigContext context) internal static void LogExceptionReceivedEvent(ExceptionReceivedEventArgs e, ILoggerFactory loggerFactory) { - try - { - var logger = loggerFactory?.CreateLogger(LogCategories.Executor); - string message = $"EventProcessorHost error (Action={e.Action}, HostName={e.Hostname}, PartitionId={e.PartitionId})"; + var logger = loggerFactory?.CreateLogger(LogCategories.Executor); + string message = $"EventProcessorHost error (Action='{e.Action}', HostName='{e.Hostname}', PartitionId='{e.PartitionId}')."; - var logLevel = GetLogLevel(e.Exception); - logger?.Log(logLevel, 0, message, e.Exception, (s, ex) => message); - } - catch - { - // best effort logging - } + Utility.LogException(e.Exception, message, logger); } private static LogLevel GetLogLevel(Exception ex) diff --git a/src/Microsoft.Azure.WebJobs.Extensions.EventHubs/Listeners/EventHubListener.cs b/src/Microsoft.Azure.WebJobs.Extensions.EventHubs/Listeners/EventHubListener.cs index 5a78573..767b341 100644 --- a/src/Microsoft.Azure.WebJobs.Extensions.EventHubs/Listeners/EventHubListener.cs +++ b/src/Microsoft.Azure.WebJobs.Extensions.EventHubs/Listeners/EventHubListener.cs @@ -145,20 +145,9 @@ public Task OpenAsync(PartitionContext context) public Task ProcessErrorAsync(PartitionContext context, Exception error) { - string errorDetails = $"Partition Id: '{context.PartitionId}', Owner: '{context.Owner}', EventHubPath: '{context.EventHubPath}'"; + string errorDetails = $"Processing error (Partition Id: '{context.PartitionId}', Owner: '{context.Owner}', EventHubPath: '{context.EventHubPath}')."; - if (error is ReceiverDisconnectedException || - error is LeaseLostException) - { - // For EventProcessorHost these exceptions can happen as part - // of normal partition balancing across instances, so we want to - // trace them, but not treat them as errors. - _logger.LogInformation($"An Event Hub exception of type '{error.GetType().Name}' was thrown from {errorDetails}. This exception type is typically a result of Event Hub processor rebalancing and can be safely ignored."); - } - else - { - _logger.LogError(error, $"Error processing event from {errorDetails}"); - } + Utility.LogException(error, errorDetails, _logger); return Task.CompletedTask; } diff --git a/src/Microsoft.Azure.WebJobs.Extensions.EventHubs/Utility.cs b/src/Microsoft.Azure.WebJobs.Extensions.EventHubs/Utility.cs new file mode 100644 index 0000000..75348c6 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Extensions.EventHubs/Utility.cs @@ -0,0 +1,63 @@ +// 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.Azure.EventHubs; +using Microsoft.Azure.EventHubs.Processor; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.EventHubs +{ + internal class Utility + { + public static void LogException(Exception ex, string message, ILogger logger) + { + try + { + // Sometimes EventHub SDK agrigates an exception + AggregateException ae = ex as AggregateException; + if (ae != null && ae.InnerExceptions != null && ae.InnerExceptions.Count == 1) + { + ex = ae.InnerExceptions[0]; + } + + LogLevel logLevel = GetLevel(ex); + if (logLevel == LogLevel.Information) + { + message = $"{message} An exception of type '{ex.GetType().Name}' was thrown. This exception type is typically a result of Event Hub processor rebalancing or a transient error and can be safely ignored."; + } + logger?.Log(logLevel, 0, message, ex, (s, exc) => message); + } + catch + { + // best effort logging + } + } + + private static LogLevel GetLevel(Exception ex) + { + if (ex is ReceiverDisconnectedException || ex is LeaseLostException + || (ex is WindowsAzure.Storage.StorageException && ex.Message == "The lease ID specified did not match the lease ID for the blob.")) + { + // For EventProcessorHost these exceptions can happen as part + // of normal partition balancing across instances, so we want to + // trace them, but not treat them as errors. + return LogLevel.Information; + } + + var ehex = ex as EventHubsException; + if (!(ex is OperationCanceledException) && (ehex == null || !ehex.IsTransient)) + { + // any non-transient exceptions or unknown exception types + // we want to log as errors + return LogLevel.Error; + } + else + { + // transient messaging errors we log as info so we have a record + // of them, but we don't treat them as actual errors + return LogLevel.Information; + } + } + } +} diff --git a/test/Microsoft.Azure.WebJobs.Extensions.EventHubs.Tests/EventHubConfigurationTests.cs b/test/Microsoft.Azure.WebJobs.Extensions.EventHubs.Tests/EventHubConfigurationTests.cs index 1c36f28..4f0e1d7 100644 --- a/test/Microsoft.Azure.WebJobs.Extensions.EventHubs.Tests/EventHubConfigurationTests.cs +++ b/test/Microsoft.Azure.WebJobs.Extensions.EventHubs.Tests/EventHubConfigurationTests.cs @@ -24,7 +24,7 @@ public class EventHubConfigurationTests { private readonly ILoggerFactory _loggerFactory; private readonly TestLoggerProvider _loggerProvider; - + private readonly string _template = " An exception of type '{0}' was thrown. This exception type is typically a result of Event Hub processor rebalancing or a transient error and can be safely ignored."; public EventHubConfigurationTests() { _loggerFactory = new LoggerFactory(); @@ -118,7 +118,7 @@ public void Initialize_PerformsExpectedRegistrations() var handler = (Action)eventProcessorOptions.GetType().GetField("exceptionHandler", BindingFlags.Instance | BindingFlags.NonPublic).GetValue(eventProcessorOptions); handler.Method.Invoke(handler.Target, new object[] { args }); - string expectedMessage = "EventProcessorHost error (Action=TestAction, HostName=TestHostName, PartitionId=TestPartitionId)"; + string expectedMessage = "EventProcessorHost error (Action='TestAction', HostName='TestHostName', PartitionId='TestPartitionId')."; var logMessage = host.GetTestLoggerProvider().GetAllLogMessages().Single(); Assert.Equal(LogLevel.Error, logMessage.Level); Assert.Equal(expectedMessage, logMessage.FormattedMessage); @@ -134,7 +134,7 @@ public void LogExceptionReceivedEvent_NonTransientEvent_LoggedAsError() var e = (ExceptionReceivedEventArgs)ctor.Invoke(new object[] { "TestHostName", "TestPartitionId", ex, "TestAction" }); EventHubExtensionConfigProvider.LogExceptionReceivedEvent(e, _loggerFactory); - string expectedMessage = "EventProcessorHost error (Action=TestAction, HostName=TestHostName, PartitionId=TestPartitionId)"; + string expectedMessage = "EventProcessorHost error (Action='TestAction', HostName='TestHostName', PartitionId='TestPartitionId')."; var logMessage = _loggerProvider.GetAllLogMessages().Single(); Assert.Equal(LogLevel.Error, logMessage.Level); Assert.Same(ex, logMessage.Exception); @@ -150,11 +150,11 @@ public void LogExceptionReceivedEvent_TransientEvent_LoggedAsVerbose() var e = (ExceptionReceivedEventArgs)ctor.Invoke(new object[] { "TestHostName", "TestPartitionId", ex, "TestAction" }); EventHubExtensionConfigProvider.LogExceptionReceivedEvent(e, _loggerFactory); - string expectedMessage = "EventProcessorHost error (Action=TestAction, HostName=TestHostName, PartitionId=TestPartitionId)"; + string expectedMessage = "EventProcessorHost error (Action='TestAction', HostName='TestHostName', PartitionId='TestPartitionId')."; var logMessage = _loggerProvider.GetAllLogMessages().Single(); Assert.Equal(LogLevel.Information, logMessage.Level); Assert.Same(ex, logMessage.Exception); - Assert.Equal(expectedMessage, logMessage.FormattedMessage); + Assert.Equal(expectedMessage + string.Format(_template, typeof(EventHubsException).Name), logMessage.FormattedMessage); } [Fact] @@ -165,11 +165,11 @@ public void LogExceptionReceivedEvent_OperationCanceledException_LoggedAsVerbose var e = (ExceptionReceivedEventArgs)ctor.Invoke(new object[] { "TestHostName", "TestPartitionId", ex, "TestAction" }); EventHubExtensionConfigProvider.LogExceptionReceivedEvent(e, _loggerFactory); - string expectedMessage = "EventProcessorHost error (Action=TestAction, HostName=TestHostName, PartitionId=TestPartitionId)"; + string expectedMessage = "EventProcessorHost error (Action='TestAction', HostName='TestHostName', PartitionId='TestPartitionId')."; var logMessage = _loggerProvider.GetAllLogMessages().Single(); Assert.Equal(LogLevel.Information, logMessage.Level); Assert.Same(ex, logMessage.Exception); - Assert.Equal(expectedMessage, logMessage.FormattedMessage); + Assert.Equal(expectedMessage + string.Format(_template, typeof(OperationCanceledException).Name), logMessage.FormattedMessage); } [Fact] @@ -180,7 +180,7 @@ public void LogExceptionReceivedEvent_NonMessagingException_LoggedAsError() var e = (ExceptionReceivedEventArgs)ctor.Invoke(new object[] { "TestHostName", "TestPartitionId", ex, "TestAction" }); EventHubExtensionConfigProvider.LogExceptionReceivedEvent(e, _loggerFactory); - string expectedMessage = "EventProcessorHost error (Action=TestAction, HostName=TestHostName, PartitionId=TestPartitionId)"; + string expectedMessage = "EventProcessorHost error (Action='TestAction', HostName='TestHostName', PartitionId='TestPartitionId')."; var logMessage = _loggerProvider.GetAllLogMessages().Single(); Assert.Equal(LogLevel.Error, logMessage.Level); Assert.Same(ex, logMessage.Exception); @@ -196,11 +196,28 @@ public void LogExceptionReceivedEvent_PartitionExceptions_LoggedAsInfo() var e = (ExceptionReceivedEventArgs)ctor.Invoke(new object[] { "TestHostName", "TestPartitionId", ex, "TestAction" }); EventHubExtensionConfigProvider.LogExceptionReceivedEvent(e, _loggerFactory); - string expectedMessage = "EventProcessorHost error (Action=TestAction, HostName=TestHostName, PartitionId=TestPartitionId)"; + string expectedMessage = "EventProcessorHost error (Action='TestAction', HostName='TestHostName', PartitionId='TestPartitionId')."; var logMessage = _loggerProvider.GetAllLogMessages().Single(); Assert.Equal(LogLevel.Information, logMessage.Level); Assert.Same(ex, logMessage.Exception); - Assert.Equal(expectedMessage, logMessage.FormattedMessage); + Assert.Equal(expectedMessage + string.Format(_template, typeof(ReceiverDisconnectedException).Name), logMessage.FormattedMessage); + } + + [Fact] + public void LogExceptionReceivedEvent_AggregateExceptions_LoggedAsInfo() + { + var ctor = typeof(AggregateException).GetConstructor(BindingFlags.Public | BindingFlags.Instance, null, new Type[] { typeof(IEnumerable) }, null); + var storageException = new WindowsAzure.Storage.StorageException("The lease ID specified did not match the lease ID for the blob."); + var ex = (AggregateException)ctor.Invoke(new object[] { new Exception[] { storageException } }); + ctor = typeof(ExceptionReceivedEventArgs).GetConstructors(BindingFlags.NonPublic | BindingFlags.Instance).Single(); + var e = (ExceptionReceivedEventArgs)ctor.Invoke(new object[] { "TestHostName", "TestPartitionId", ex, "TestAction" }); + EventHubExtensionConfigProvider.LogExceptionReceivedEvent(e, _loggerFactory); + + string expectedMessage = "EventProcessorHost error (Action='TestAction', HostName='TestHostName', PartitionId='TestPartitionId')."; + var logMessage = _loggerProvider.GetAllLogMessages().Single(); + Assert.Equal(LogLevel.Information, logMessage.Level); + Assert.Same(storageException, logMessage.Exception); + Assert.Equal(expectedMessage + string.Format(_template, typeof(WindowsAzure.Storage.StorageException).Name), logMessage.FormattedMessage); } } } \ No newline at end of file diff --git a/test/Microsoft.Azure.WebJobs.Extensions.EventHubs.Tests/EventHubListenerTests.cs b/test/Microsoft.Azure.WebJobs.Extensions.EventHubs.Tests/EventHubListenerTests.cs index ca8e16c..4075f98 100644 --- a/test/Microsoft.Azure.WebJobs.Extensions.EventHubs.Tests/EventHubListenerTests.cs +++ b/test/Microsoft.Azure.WebJobs.Extensions.EventHubs.Tests/EventHubListenerTests.cs @@ -152,7 +152,7 @@ public async Task ProcessErrorsAsync_LoggedAsError() await eventProcessor.ProcessErrorAsync(partitionContext, ex); var msg = testLogger.GetLogMessages().Single(); - Assert.Equal("Error processing event from Partition Id: '123', Owner: 'def', EventHubPath: 'abc'", msg.FormattedMessage); + Assert.Equal("Processing error (Partition Id: '123', Owner: 'def', EventHubPath: 'abc').", msg.FormattedMessage); Assert.IsType(msg.Exception); Assert.Equal(LogLevel.Error, msg.Level); } @@ -174,8 +174,8 @@ public async Task ProcessErrorsAsync_RebalancingExceptions_LoggedAsInformation() await eventProcessor.ProcessErrorAsync(partitionContext, disconnectedEx); var msg = testLogger.GetLogMessages().Single(); - Assert.Equal("An Event Hub exception of type 'ReceiverDisconnectedException' was thrown from Partition Id: '123', Owner: 'def', EventHubPath: 'abc'. This exception type is typically a result of Event Hub processor rebalancing and can be safely ignored.", msg.FormattedMessage); - Assert.Null(msg.Exception); + Assert.Equal("Processing error (Partition Id: '123', Owner: 'def', EventHubPath: 'abc'). An exception of type 'ReceiverDisconnectedException' was thrown. This exception type is typically a result of Event Hub processor rebalancing or a transient error and can be safely ignored.", msg.FormattedMessage); + Assert.NotNull(msg.Exception); Assert.Equal(LogLevel.Information, msg.Level); testLogger.ClearLogMessages(); @@ -187,8 +187,8 @@ public async Task ProcessErrorsAsync_RebalancingExceptions_LoggedAsInformation() await eventProcessor.ProcessErrorAsync(partitionContext, leaseLostEx); msg = testLogger.GetLogMessages().Single(); - Assert.Equal("An Event Hub exception of type 'LeaseLostException' was thrown from Partition Id: '123', Owner: 'def', EventHubPath: 'abc'. This exception type is typically a result of Event Hub processor rebalancing and can be safely ignored.", msg.FormattedMessage); - Assert.Null(msg.Exception); + Assert.Equal("Processing error (Partition Id: '123', Owner: 'def', EventHubPath: 'abc'). An exception of type 'LeaseLostException' was thrown. This exception type is typically a result of Event Hub processor rebalancing or a transient error and can be safely ignored.", msg.FormattedMessage); + Assert.NotNull(msg.Exception); Assert.Equal(LogLevel.Information, msg.Level); }