Skip to content
This repository has been archived by the owner on Jul 19, 2024. It is now read-only.

Commit

Permalink
Unifying logging of exceptions. Fixes #59.
Browse files Browse the repository at this point in the history
  • Loading branch information
@alrod
alrod committed Apr 8, 2020
1 parent 41baa64 commit a9df971
Show file tree
Hide file tree
Showing 5 changed files with 100 additions and 39 deletions.
14 changes: 3 additions & 11 deletions src/Microsoft.Azure.WebJobs.Extensions.EventHubs/Config/EventHubExtensionConfigProvider.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
15 changes: 2 additions & 13 deletions src/Microsoft.Azure.WebJobs.Extensions.EventHubs/Listeners/EventHubListener.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand Down
63 changes: 63 additions & 0 deletions src/Microsoft.Azure.WebJobs.Extensions.EventHubs/Utility.cs
View file
Original file line number Diff line number Diff line change
@@ -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;
}
}
}
}
37 changes: 27 additions & 10 deletions test/Microsoft.Azure.WebJobs.Extensions.EventHubs.Tests/EventHubConfigurationTests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down Expand Up @@ -118,7 +118,7 @@ public void Initialize_PerformsExpectedRegistrations()
var handler = (Action<ExceptionReceivedEventArgs>)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);
Expand All @@ -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);
Expand All @@ -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]
Expand All @@ -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]
Expand All @@ -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);
Expand All @@ -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<Exception>) }, 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);
}
}
}
10 changes: 5 additions & 5 deletions test/Microsoft.Azure.WebJobs.Extensions.EventHubs.Tests/EventHubListenerTests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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<InvalidOperationException>(msg.Exception);
Assert.Equal(LogLevel.Error, msg.Level);
}
Expand All @@ -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();
Expand All @@ -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);
}

Expand Down

0 comments on commit a9df971

Please sign in to comment.