diff --git a/src/Microsoft.Azure.WebJobs.Host/Extensions/LogLevelExtensions.cs b/src/Microsoft.Azure.WebJobs.Host/Extensions/LogLevelExtensions.cs new file mode 100644 index 000000000..a998a4ff2 --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.Host/Extensions/LogLevelExtensions.cs @@ -0,0 +1,40 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +using System.Diagnostics; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Azure.WebJobs.Host +{ + internal static class LogLevelExtensions + { + internal static TraceLevel ToTraceLevel(this LogLevel logLevel) + { + TraceLevel level = TraceLevel.Off; + switch (logLevel) + { + case LogLevel.Critical: + case LogLevel.Error: + level = TraceLevel.Error; + break; + + case LogLevel.Trace: + case LogLevel.Debug: + level = TraceLevel.Verbose; + break; + + case LogLevel.Information: + level = TraceLevel.Info; + break; + + case LogLevel.Warning: + level = TraceLevel.Warning; + break; + + default: + break; + } + return level; + } + } +} \ No newline at end of file diff --git a/src/Microsoft.Azure.WebJobs.Host/WebJobs.Host.csproj b/src/Microsoft.Azure.WebJobs.Host/WebJobs.Host.csproj index d3d6d574e..d6de53e34 100644 --- a/src/Microsoft.Azure.WebJobs.Host/WebJobs.Host.csproj +++ b/src/Microsoft.Azure.WebJobs.Host/WebJobs.Host.csproj @@ -485,6 +485,7 @@ + diff --git a/src/Microsoft.Azure.WebJobs.ServiceBus/Config/ServiceBusExtensionConfig.cs b/src/Microsoft.Azure.WebJobs.ServiceBus/Config/ServiceBusExtensionConfig.cs index 23eb95407..d6b1ab26b 100644 --- a/src/Microsoft.Azure.WebJobs.ServiceBus/Config/ServiceBusExtensionConfig.cs +++ b/src/Microsoft.Azure.WebJobs.ServiceBus/Config/ServiceBusExtensionConfig.cs @@ -51,23 +51,15 @@ public void Initialize(ExtensionConfigContext context) throw new ArgumentNullException("context"); } - // Register an exception handler for background exceptions - // coming from MessageReceivers. - // - // The message options is a host level instance that is shared - // across all bindings, so we have to subscribe to it at the - // host level. - Config.MessageOptions.ExceptionReceived += (s, e) => - { - Utility.LogExceptionReceivedEvent(e, "MessageReceiver", context.Trace, context.Config.LoggerFactory); - }; - // get the services we need to construct our binding providers INameResolver nameResolver = context.Config.GetService(); IExtensionRegistry extensions = context.Config.GetService(); + // register the background exception handler + var exceptionHandler = MessagingExceptionHandler.Subscribe(Config.MessageOptions, context.Trace, context.Config.LoggerFactory); + // register our trigger binding provider - ServiceBusTriggerAttributeBindingProvider triggerBindingProvider = new ServiceBusTriggerAttributeBindingProvider(nameResolver, _serviceBusConfig); + ServiceBusTriggerAttributeBindingProvider triggerBindingProvider = new ServiceBusTriggerAttributeBindingProvider(nameResolver, _serviceBusConfig, exceptionHandler); extensions.RegisterExtension(triggerBindingProvider); // register our binding provider diff --git a/src/Microsoft.Azure.WebJobs.ServiceBus/EventHubs/EventHubConfiguration.cs b/src/Microsoft.Azure.WebJobs.ServiceBus/EventHubs/EventHubConfiguration.cs index 908a7dba7..cc39b08d6 100644 --- a/src/Microsoft.Azure.WebJobs.ServiceBus/EventHubs/EventHubConfiguration.cs +++ b/src/Microsoft.Azure.WebJobs.ServiceBus/EventHubs/EventHubConfiguration.cs @@ -444,6 +444,9 @@ void IExtensionConfigProvider.Initialize(ExtensionConfigContext context) .AddConverter(ConvertBytes2EventData) .AddConverter(ConvertEventData2Bytes); + // register the background exception handler + MessagingExceptionHandler.Subscribe(_options, context.Trace, context.Config.LoggerFactory); + // register our trigger binding provider INameResolver nameResolver = context.Config.NameResolver; IConverterManager cm = context.Config.GetService(); @@ -454,17 +457,6 @@ void IExtensionConfigProvider.Initialize(ExtensionConfigContext context) // register our binding provider context.AddBindingRule() .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) => - { - Utility.LogExceptionReceivedEvent(e, "EventProcessorHost", context.Trace, context.Config.LoggerFactory); - }; } private IAsyncCollector BuildFromAttribute(EventHubAttribute attribute) diff --git a/src/Microsoft.Azure.WebJobs.ServiceBus/EventHubs/EventHubTriggerAttributeBindingProvider.cs b/src/Microsoft.Azure.WebJobs.ServiceBus/EventHubs/EventHubTriggerAttributeBindingProvider.cs index 255fe5e40..808685088 100644 --- a/src/Microsoft.Azure.WebJobs.ServiceBus/EventHubs/EventHubTriggerAttributeBindingProvider.cs +++ b/src/Microsoft.Azure.WebJobs.ServiceBus/EventHubs/EventHubTriggerAttributeBindingProvider.cs @@ -23,9 +23,9 @@ public EventHubTriggerAttributeBindingProvider( IConverterManager converterManager, EventHubConfiguration eventHubConfig) { - this._nameResolver = nameResolver; - this._converterManager = converterManager; - this._eventHubConfig = eventHubConfig; + _nameResolver = nameResolver; + _converterManager = converterManager; + _eventHubConfig = eventHubConfig; } [System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope")] diff --git a/src/Microsoft.Azure.WebJobs.ServiceBus/Listeners/ServiceBusListener.cs b/src/Microsoft.Azure.WebJobs.ServiceBus/Listeners/ServiceBusListener.cs index c5e5c8b7d..372732db1 100644 --- a/src/Microsoft.Azure.WebJobs.ServiceBus/Listeners/ServiceBusListener.cs +++ b/src/Microsoft.Azure.WebJobs.ServiceBus/Listeners/ServiceBusListener.cs @@ -18,12 +18,13 @@ internal sealed class ServiceBusListener : IListener private readonly ServiceBusTriggerExecutor _triggerExecutor; private readonly CancellationTokenSource _cancellationTokenSource; private readonly MessageProcessor _messageProcessor; + private readonly MessagingExceptionHandler _exceptionHandler; private MessagingFactory _messagingFactory; private MessageReceiver _receiver; private bool _disposed; private bool _started; - public ServiceBusListener(MessagingFactory messagingFactory, string entityPath, ServiceBusTriggerExecutor triggerExecutor, ServiceBusConfiguration config) + public ServiceBusListener(MessagingFactory messagingFactory, string entityPath, ServiceBusTriggerExecutor triggerExecutor, ServiceBusConfiguration config, MessagingExceptionHandler exceptionHandler) { _messagingFactory = messagingFactory; _entityPath = entityPath; @@ -31,6 +32,7 @@ public ServiceBusListener(MessagingFactory messagingFactory, string entityPath, _cancellationTokenSource = new CancellationTokenSource(); _messagingProvider = config.MessagingProvider; _messageProcessor = config.MessagingProvider.CreateMessageProcessor(entityPath); + _exceptionHandler = exceptionHandler; } public Task StartAsync(CancellationToken cancellationToken) @@ -53,6 +55,11 @@ public Task StopAsync(CancellationToken cancellationToken) { ThrowIfDisposed(); + // important to disable the exception handler BEFORE aborting + // the messaging factory, to avoid spurious error logs due + // to receive attempts on a closed connection, etc. + _exceptionHandler.Unsubscribe(); + if (!_started) { throw new InvalidOperationException("The listener has not yet been started or has already been stopped."); diff --git a/src/Microsoft.Azure.WebJobs.ServiceBus/Listeners/ServiceBusQueueListenerFactory.cs b/src/Microsoft.Azure.WebJobs.ServiceBus/Listeners/ServiceBusQueueListenerFactory.cs index 4db646957..a8a21c8b3 100644 --- a/src/Microsoft.Azure.WebJobs.ServiceBus/Listeners/ServiceBusQueueListenerFactory.cs +++ b/src/Microsoft.Azure.WebJobs.ServiceBus/Listeners/ServiceBusQueueListenerFactory.cs @@ -18,8 +18,9 @@ internal class ServiceBusQueueListenerFactory : IListenerFactory private readonly ITriggeredFunctionExecutor _executor; private readonly AccessRights _accessRights; private readonly ServiceBusConfiguration _config; + private readonly MessagingExceptionHandler _exceptionHandler; - public ServiceBusQueueListenerFactory(ServiceBusAccount account, string queueName, ITriggeredFunctionExecutor executor, AccessRights accessRights, ServiceBusConfiguration config) + public ServiceBusQueueListenerFactory(ServiceBusAccount account, string queueName, ITriggeredFunctionExecutor executor, AccessRights accessRights, ServiceBusConfiguration config, MessagingExceptionHandler exceptionHandler) { _namespaceManager = account.NamespaceManager; _messagingFactory = account.MessagingFactory; @@ -27,6 +28,7 @@ public ServiceBusQueueListenerFactory(ServiceBusAccount account, string queueNam _executor = executor; _accessRights = accessRights; _config = config; + _exceptionHandler = exceptionHandler; } public async Task CreateAsync(CancellationToken cancellationToken) @@ -40,7 +42,7 @@ public async Task CreateAsync(CancellationToken cancellationToken) } ServiceBusTriggerExecutor triggerExecutor = new ServiceBusTriggerExecutor(_executor); - return new ServiceBusListener(_messagingFactory, _queueName, triggerExecutor, _config); + return new ServiceBusListener(_messagingFactory, _queueName, triggerExecutor, _config, _exceptionHandler); } } } diff --git a/src/Microsoft.Azure.WebJobs.ServiceBus/Listeners/ServiceBusSubscriptionListenerFactory.cs b/src/Microsoft.Azure.WebJobs.ServiceBus/Listeners/ServiceBusSubscriptionListenerFactory.cs index 566748e80..2f79ad685 100644 --- a/src/Microsoft.Azure.WebJobs.ServiceBus/Listeners/ServiceBusSubscriptionListenerFactory.cs +++ b/src/Microsoft.Azure.WebJobs.ServiceBus/Listeners/ServiceBusSubscriptionListenerFactory.cs @@ -19,8 +19,9 @@ internal class ServiceBusSubscriptionListenerFactory : IListenerFactory private readonly ITriggeredFunctionExecutor _executor; private readonly AccessRights _accessRights; private readonly ServiceBusConfiguration _config; + private readonly MessagingExceptionHandler _exceptionHandler; - public ServiceBusSubscriptionListenerFactory(ServiceBusAccount account, string topicName, string subscriptionName, ITriggeredFunctionExecutor executor, AccessRights accessRights, ServiceBusConfiguration config) + public ServiceBusSubscriptionListenerFactory(ServiceBusAccount account, string topicName, string subscriptionName, ITriggeredFunctionExecutor executor, AccessRights accessRights, ServiceBusConfiguration config, MessagingExceptionHandler exceptionHandler) { _namespaceManager = account.NamespaceManager; _messagingFactory = account.MessagingFactory; @@ -29,6 +30,7 @@ public ServiceBusSubscriptionListenerFactory(ServiceBusAccount account, string t _executor = executor; _accessRights = accessRights; _config = config; + _exceptionHandler = exceptionHandler; } public async Task CreateAsync(CancellationToken cancellationToken) @@ -45,7 +47,7 @@ public async Task CreateAsync(CancellationToken cancellationToken) string entityPath = SubscriptionClient.FormatSubscriptionPath(_topicName, _subscriptionName); ServiceBusTriggerExecutor triggerExecutor = new ServiceBusTriggerExecutor(_executor); - return new ServiceBusListener(_messagingFactory, entityPath, triggerExecutor, _config); + return new ServiceBusListener(_messagingFactory, entityPath, triggerExecutor, _config, _exceptionHandler); } } } diff --git a/src/Microsoft.Azure.WebJobs.ServiceBus/MessagingExceptionHandler.cs b/src/Microsoft.Azure.WebJobs.ServiceBus/MessagingExceptionHandler.cs new file mode 100644 index 000000000..82df2c82b --- /dev/null +++ b/src/Microsoft.Azure.WebJobs.ServiceBus/MessagingExceptionHandler.cs @@ -0,0 +1,159 @@ +// 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.WebJobs.Host; +using Microsoft.Azure.WebJobs.Logging; +using Microsoft.Extensions.Logging; +using Microsoft.ServiceBus.Messaging; + +namespace Microsoft.Azure.WebJobs.ServiceBus +{ + internal abstract class MessagingExceptionHandler + { + private readonly TraceWriter _traceWriter; + private readonly ILoggerFactory _loggerFactory; + private string _source; + + public MessagingExceptionHandler(string source, TraceWriter traceWriter, ILoggerFactory loggerFactory = null) + { + if (string.IsNullOrEmpty(source)) + { + throw new ArgumentNullException(nameof(source)); + } + if (traceWriter == null) + { + throw new ArgumentNullException(nameof(traceWriter)); + } + + _source = source; + _traceWriter = traceWriter; + _loggerFactory = loggerFactory; + } + + public static MessagingExceptionHandler Subscribe(EventProcessorOptions options, TraceWriter traceWriter, ILoggerFactory loggerFactory = null) + { + var exceptionHandler = new EventHubExceptionHandler(options, traceWriter, loggerFactory); + exceptionHandler.Subscribe(); + return exceptionHandler; + } + + public static MessagingExceptionHandler Subscribe(OnMessageOptions options, TraceWriter traceWriter, ILoggerFactory loggerFactory = null) + { + var exceptionHandler = new ServiceBusExceptionHandler(options, traceWriter, loggerFactory); + exceptionHandler.Subscribe(); + return exceptionHandler; + } + + public abstract void Subscribe(); + + public abstract void Unsubscribe(); + + protected void Handle(object sender, ExceptionReceivedEventArgs e) + { + LogExceptionReceivedEvent(e); + } + + internal void LogExceptionReceivedEvent(ExceptionReceivedEventArgs e) + { + try + { + var logger = _loggerFactory?.CreateLogger(LogCategories.Executor); + string message = $"{_source} error (Action={e.Action}) : {e.Exception.ToString()}"; + + var logLevel = GetLogLevel(e.Exception); + logger?.Log(logLevel, 0, message, e.Exception, (s, ex) => message); + + var traceEvent = new TraceEvent(logLevel.ToTraceLevel(), message, null, e.Exception); + _traceWriter.Trace(traceEvent); + } + catch + { + // best effort logging + } + } + + protected virtual LogLevel GetLogLevel(Exception ex) + { + var mex = ex as MessagingException; + if (!(ex is OperationCanceledException) && (mex == null || !mex.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 verbose so we have a record + // of them, but we don't treat them as actual errors + return LogLevel.Information; + } + } + + private class EventHubExceptionHandler : MessagingExceptionHandler + { + private readonly EventProcessorOptions _options; + + public EventHubExceptionHandler(EventProcessorOptions options, TraceWriter traceWriter, ILoggerFactory loggerFactory = null) + : base("EventProcessorHost", traceWriter, loggerFactory) + { + if (options == null) + { + throw new ArgumentNullException(nameof(options)); + } + + _options = options; + } + + public override void Subscribe() + { + _options.ExceptionReceived += Handle; + } + + public override void Unsubscribe() + { + _options.ExceptionReceived -= Handle; + } + + protected override LogLevel GetLogLevel(Exception ex) + { + if (ex is ReceiverDisconnectedException || + ex 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. + return LogLevel.Information; + } + + return base.GetLogLevel(ex); + } + } + + private class ServiceBusExceptionHandler : MessagingExceptionHandler + { + private readonly OnMessageOptions _options; + + public ServiceBusExceptionHandler(OnMessageOptions options, TraceWriter traceWriter, ILoggerFactory loggerFactory = null) + : base("MessageReceiver", traceWriter, loggerFactory) + { + if (options == null) + { + throw new ArgumentNullException(nameof(options)); + } + + _options = options; + } + + public override void Subscribe() + { + _options.ExceptionReceived += Handle; + } + + public override void Unsubscribe() + { + _options.ExceptionReceived -= Handle; + } + } + } +} diff --git a/src/Microsoft.Azure.WebJobs.ServiceBus/Triggers/ServiceBusTriggerAttributeBindingProvider.cs b/src/Microsoft.Azure.WebJobs.ServiceBus/Triggers/ServiceBusTriggerAttributeBindingProvider.cs index 4f9fcc966..6ea2cfc98 100644 --- a/src/Microsoft.Azure.WebJobs.ServiceBus/Triggers/ServiceBusTriggerAttributeBindingProvider.cs +++ b/src/Microsoft.Azure.WebJobs.ServiceBus/Triggers/ServiceBusTriggerAttributeBindingProvider.cs @@ -24,8 +24,9 @@ internal class ServiceBusTriggerAttributeBindingProvider : ITriggerBindingProvid private readonly INameResolver _nameResolver; private readonly ServiceBusConfiguration _config; + private readonly MessagingExceptionHandler _exceptionHandler; - public ServiceBusTriggerAttributeBindingProvider(INameResolver nameResolver, ServiceBusConfiguration config) + public ServiceBusTriggerAttributeBindingProvider(INameResolver nameResolver, ServiceBusConfiguration config, MessagingExceptionHandler exceptionHandler) { if (nameResolver == null) { @@ -38,6 +39,7 @@ public ServiceBusTriggerAttributeBindingProvider(INameResolver nameResolver, Ser _nameResolver = nameResolver; _config = config; + _exceptionHandler = exceptionHandler; } public Task TryCreateAsync(TriggerBindingProviderContext context) @@ -87,11 +89,11 @@ public Task TryCreateAsync(TriggerBindingProviderContext contex ITriggerBinding binding; if (queueName != null) { - binding = new ServiceBusTriggerBinding(parameter.Name, parameter.ParameterType, argumentBinding, account, attribute.Access, _config, queueName); + binding = new ServiceBusTriggerBinding(parameter.Name, parameter.ParameterType, argumentBinding, account, attribute.Access, _config, queueName, _exceptionHandler); } else { - binding = new ServiceBusTriggerBinding(parameter.Name, parameter.ParameterType, argumentBinding, account, attribute.Access, _config, topicName, subscriptionName); + binding = new ServiceBusTriggerBinding(parameter.Name, parameter.ParameterType, argumentBinding, account, attribute.Access, _config, topicName, subscriptionName, _exceptionHandler); } return Task.FromResult(binding); diff --git a/src/Microsoft.Azure.WebJobs.ServiceBus/Triggers/ServiceBusTriggerBinding.cs b/src/Microsoft.Azure.WebJobs.ServiceBus/Triggers/ServiceBusTriggerBinding.cs index 67194dac1..6995e6808 100644 --- a/src/Microsoft.Azure.WebJobs.ServiceBus/Triggers/ServiceBusTriggerBinding.cs +++ b/src/Microsoft.Azure.WebJobs.ServiceBus/Triggers/ServiceBusTriggerBinding.cs @@ -30,18 +30,19 @@ internal class ServiceBusTriggerBinding : ITriggerBinding private readonly string _entityPath; private readonly AccessRights _accessRights; private readonly ServiceBusConfiguration _config; + private readonly MessagingExceptionHandler _exceptionHandler; public ServiceBusTriggerBinding(string parameterName, Type parameterType, ITriggerDataArgumentBinding argumentBinding, ServiceBusAccount account, - AccessRights accessRights, ServiceBusConfiguration config, string queueName) - : this(parameterName, parameterType, argumentBinding, account, accessRights, config) + AccessRights accessRights, ServiceBusConfiguration config, string queueName, MessagingExceptionHandler exceptionHandler) + : this(parameterName, parameterType, argumentBinding, account, accessRights, config, exceptionHandler) { _queueName = queueName; _entityPath = queueName; } public ServiceBusTriggerBinding(string parameterName, Type parameterType, ITriggerDataArgumentBinding argumentBinding, ServiceBusAccount account, - AccessRights accessRights, ServiceBusConfiguration config, string topicName, string subscriptionName) - : this(parameterName, parameterType, argumentBinding, account, accessRights, config) + AccessRights accessRights, ServiceBusConfiguration config, string topicName, string subscriptionName, MessagingExceptionHandler exceptionHandler) + : this(parameterName, parameterType, argumentBinding, account, accessRights, config, exceptionHandler) { _topicName = topicName; _subscriptionName = subscriptionName; @@ -49,7 +50,7 @@ public ServiceBusTriggerBinding(string parameterName, Type parameterType, ITrigg } private ServiceBusTriggerBinding(string parameterName, Type parameterType, ITriggerDataArgumentBinding argumentBinding, - ServiceBusAccount account, AccessRights accessRights, ServiceBusConfiguration config) + ServiceBusAccount account, AccessRights accessRights, ServiceBusConfiguration config, MessagingExceptionHandler exceptionHandler) { _parameterName = parameterName; _converter = CreateConverter(parameterType); @@ -59,6 +60,7 @@ private ServiceBusTriggerBinding(string parameterName, Type parameterType, ITrig _namespaceName = ServiceBusClient.GetNamespaceName(account); _accessRights = accessRights; _config = config; + _exceptionHandler = exceptionHandler; } public Type TriggerValueType @@ -118,11 +120,11 @@ public Task CreateListenerAsync(ListenerFactoryContext context) IListenerFactory factory = null; if (_queueName != null) { - factory = new ServiceBusQueueListenerFactory(_account, _queueName, context.Executor, _accessRights, _config); + factory = new ServiceBusQueueListenerFactory(_account, _queueName, context.Executor, _accessRights, _config, _exceptionHandler); } else { - factory = new ServiceBusSubscriptionListenerFactory(_account, _topicName, _subscriptionName, context.Executor, _accessRights, _config); + factory = new ServiceBusSubscriptionListenerFactory(_account, _topicName, _subscriptionName, context.Executor, _accessRights, _config, _exceptionHandler); } return factory.CreateAsync(context.CancellationToken); } diff --git a/src/Microsoft.Azure.WebJobs.ServiceBus/Utility.cs b/src/Microsoft.Azure.WebJobs.ServiceBus/Utility.cs deleted file mode 100644 index 01c68ca32..000000000 --- a/src/Microsoft.Azure.WebJobs.ServiceBus/Utility.cs +++ /dev/null @@ -1,45 +0,0 @@ -// 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 Microsoft.Azure.WebJobs.Host; -using Microsoft.Azure.WebJobs.Logging; -using Microsoft.Extensions.Logging; -using Microsoft.ServiceBus.Messaging; - -namespace Microsoft.Azure.WebJobs.ServiceBus -{ - internal static class Utility - { - public static void LogExceptionReceivedEvent(ExceptionReceivedEventArgs e, string source, TraceWriter traceWriter, ILoggerFactory loggerFactory = null) - { - try - { - var logger = loggerFactory?.CreateLogger(LogCategories.Executor); - string message = $"{source} error (Action={e.Action})"; - - var mex = e.Exception as MessagingException; - if (!(e.Exception is OperationCanceledException) && (mex == null || !mex.IsTransient)) - { - // any non-transient exceptions or unknown exception types - // we want to log as errors - logger?.LogError(0, e.Exception, message); - traceWriter.Error(message, e.Exception); - } - else - { - // transient messaging errors we log as verbose so we have a record - // of them, but we don't treat them as actual errors - logger?.LogDebug(0, e.Exception, message); - var evt = new TraceEvent(TraceLevel.Verbose, $"{message} : {e.Exception.ToString()}", exception: e.Exception); - traceWriter.Trace(evt); - } - } - catch - { - // best effort logging - } - } - } -} diff --git a/src/Microsoft.Azure.WebJobs.ServiceBus/WebJobs.ServiceBus.csproj b/src/Microsoft.Azure.WebJobs.ServiceBus/WebJobs.ServiceBus.csproj index 3e86586ca..15efc7172 100644 --- a/src/Microsoft.Azure.WebJobs.ServiceBus/WebJobs.ServiceBus.csproj +++ b/src/Microsoft.Azure.WebJobs.ServiceBus/WebJobs.ServiceBus.csproj @@ -194,6 +194,9 @@ Converters\IObjectToTypeConverter.cs + + Extensions\LogLevelExtensions.cs + Listeners\IListenerFactory.cs @@ -244,6 +247,7 @@ + @@ -278,7 +282,6 @@ - diff --git a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Bindings/ServiceBusTriggerAttributeBindingProviderTests.cs b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Bindings/ServiceBusTriggerAttributeBindingProviderTests.cs index f39de9f41..47eb93b1d 100644 --- a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Bindings/ServiceBusTriggerAttributeBindingProviderTests.cs +++ b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Bindings/ServiceBusTriggerAttributeBindingProviderTests.cs @@ -1,9 +1,11 @@ // Copyright (c) .NET Foundation. All rights reserved. // Licensed under the MIT License. See License.txt in the project root for license information. +using System.Diagnostics; using System.Reflection; using System.Threading; using System.Threading.Tasks; +using Microsoft.Azure.WebJobs.Host.TestCommon; using Microsoft.Azure.WebJobs.Host.Triggers; using Microsoft.Azure.WebJobs.ServiceBus.Triggers; using Microsoft.ServiceBus; @@ -26,7 +28,8 @@ public ServiceBusTriggerAttributeBindingProviderTests() _mockMessagingProvider = new Mock(MockBehavior.Strict, config); config.MessagingProvider = _mockMessagingProvider.Object; - _provider = new ServiceBusTriggerAttributeBindingProvider(mockResolver.Object, config); + var exceptionHandler = MessagingExceptionHandler.Subscribe(config.MessageOptions, new TestTraceWriter(TraceLevel.Verbose)); + _provider = new ServiceBusTriggerAttributeBindingProvider(mockResolver.Object, config, exceptionHandler); } [Fact] diff --git a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Config/EventHubConfigurationTests.cs b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Config/EventHubConfigurationTests.cs index ad3770a45..f5268935b 100644 --- a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Config/EventHubConfigurationTests.cs +++ b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Config/EventHubConfigurationTests.cs @@ -60,7 +60,7 @@ public void Initialize_PerformsExpectedRegistrations() var handler = eventDelegate.GetInvocationList().Single(); handler.Method.Invoke(handler.Target, new object[] { null, args }); - string expectedMessage = "EventProcessorHost error (Action=Testing)"; + string expectedMessage = "EventProcessorHost error (Action=Testing) : System.Exception: Kaboom!"; var trace = traceWriter.GetTraces().Last(); Assert.Equal(expectedMessage, trace.Message); Assert.Same(ex, trace.Exception); diff --git a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Config/ServiceBusExtensionConfigTests.cs b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Config/ServiceBusExtensionConfigTests.cs index b12a00d0f..e446726b0 100644 --- a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Config/ServiceBusExtensionConfigTests.cs +++ b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Config/ServiceBusExtensionConfigTests.cs @@ -70,7 +70,7 @@ public void Initialize_PerformsExpectedRegistrations() var handler = eventDelegate.GetInvocationList().Single(); handler.Method.Invoke(handler.Target, new object[] { null, args }); - string expectedMessage = "MessageReceiver error (Action=Testing)"; + string expectedMessage = "MessageReceiver error (Action=Testing) : System.Exception: Kaboom!"; var trace = traceWriter.GetTraces().Last(); Assert.Equal(expectedMessage, trace.Message); Assert.Same(ex, trace.Exception); diff --git a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/EventHubTests.cs b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/EventHubTests.cs index d1f276d73..b739a902a 100644 --- a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/EventHubTests.cs +++ b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/EventHubTests.cs @@ -9,6 +9,8 @@ using System.Linq; using System.Reflection; using Microsoft.WindowsAzure.Storage.Blob; +using Microsoft.Azure.WebJobs.Host.TestCommon; +using System.Diagnostics; namespace Microsoft.Azure.WebJobs.ServiceBus.UnitTests { @@ -504,7 +506,8 @@ public void InitializeFromHostMetadata() } } } - } + }, + Trace = new TestTraceWriter(TraceLevel.Verbose) }; (config as IExtensionConfigProvider).Initialize(context); diff --git a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Listeners/ServiceBusListenerTests.cs b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Listeners/ServiceBusListenerTests.cs index 612ac173a..59ec65c0e 100644 --- a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Listeners/ServiceBusListenerTests.cs +++ b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Listeners/ServiceBusListenerTests.cs @@ -6,6 +6,7 @@ using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Host; using Microsoft.Azure.WebJobs.Host.Executors; +using Microsoft.Azure.WebJobs.Host.TestCommon; using Microsoft.Azure.WebJobs.ServiceBus.Listeners; using Microsoft.ServiceBus.Messaging; using Moq; @@ -42,7 +43,8 @@ public ServiceBusListenerTests() .Returns(_mockMessageProcessor.Object); ServiceBusTriggerExecutor triggerExecutor = new ServiceBusTriggerExecutor(_mockExecutor.Object); - _listener = new ServiceBusListener(_messagingFactory, _entityPath, triggerExecutor, config); + var exceptionHandler = MessagingExceptionHandler.Subscribe(messageOptions, new TestTraceWriter(TraceLevel.Verbose)); + _listener = new ServiceBusListener(_messagingFactory, _entityPath, triggerExecutor, config, exceptionHandler); } [Fact] diff --git a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Listeners/ServiceBusQueueListenerFactoryTests.cs b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Listeners/ServiceBusQueueListenerFactoryTests.cs index 6dbf6318a..111575db1 100644 --- a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Listeners/ServiceBusQueueListenerFactoryTests.cs +++ b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Listeners/ServiceBusQueueListenerFactoryTests.cs @@ -24,7 +24,9 @@ public async Task CreateAsync_AccessRightsNotManage_DoesNotCreateQueue(AccessRig { ServiceBusAccount account = new ServiceBusAccount(); Mock mockExecutor = new Mock(MockBehavior.Strict); - ServiceBusQueueListenerFactory factory = new ServiceBusQueueListenerFactory(account, "testqueue", mockExecutor.Object, accessRights, new ServiceBusConfiguration()); + ServiceBusConfiguration config = new ServiceBusConfiguration(); + var exceptionHandler = MessagingExceptionHandler.Subscribe(config.MessageOptions, new TestTraceWriter(TraceLevel.Verbose)); + ServiceBusQueueListenerFactory factory = new ServiceBusQueueListenerFactory(account, "testqueue", mockExecutor.Object, accessRights, new ServiceBusConfiguration(), exceptionHandler); IListener listener = await factory.CreateAsync(CancellationToken.None); Assert.NotNull(listener); diff --git a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/UtilityTests.cs b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/MessagingExceptionHandlerTests.cs similarity index 51% rename from test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/UtilityTests.cs rename to test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/MessagingExceptionHandlerTests.cs index 59baada86..e1873d31e 100644 --- a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/UtilityTests.cs +++ b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/MessagingExceptionHandlerTests.cs @@ -12,13 +12,13 @@ namespace Microsoft.Azure.WebJobs.ServiceBus.UnitTests { - public class UtilityTests + public class MessagingExceptionHandlerTests { private readonly ILoggerFactory _loggerFactory; private readonly TestLoggerProvider _loggerProvider; private readonly TestTraceWriter _traceWriter; - public UtilityTests() + public MessagingExceptionHandlerTests() { _loggerFactory = new LoggerFactory(); var filter = new LogCategoryFilter(); @@ -30,14 +30,16 @@ public UtilityTests() } [Fact] - public void LogExceptionReceivedEvent_NonTransientEvent_LoggedAsError() + public void ServiceBus_LogExceptionReceivedEvent_NonTransientEvent_LoggedAsError() { var ex = new MessageLockLostException("Lost the lock"); Assert.False(ex.IsTransient); ExceptionReceivedEventArgs e = new ExceptionReceivedEventArgs(ex, "Complete"); - Utility.LogExceptionReceivedEvent(e, "Test", _traceWriter, _loggerFactory); + var options = new OnMessageOptions(); + var handler = MessagingExceptionHandler.Subscribe(options, _traceWriter, _loggerFactory); + handler.LogExceptionReceivedEvent(e); - var expectedMessage = $"Test error (Action=Complete)"; + var expectedMessage = $"MessageReceiver error (Action=Complete) : {e.Exception.ToString()}"; var traceEvent = _traceWriter.GetTraces().Single(); Assert.Equal(TraceLevel.Error, traceEvent.Level); Assert.Same(ex, traceEvent.Exception); @@ -50,52 +52,58 @@ public void LogExceptionReceivedEvent_NonTransientEvent_LoggedAsError() } [Fact] - public void LogExceptionReceivedEvent_TransientEvent_LoggedAsVerbose() + public void ServiceBus_LogExceptionReceivedEvent_TransientEvent_LoggedAsVerbose() { var ex = new MessagingCommunicationException("Test Path"); Assert.True(ex.IsTransient); ExceptionReceivedEventArgs e = new ExceptionReceivedEventArgs(ex, "Connect"); - Utility.LogExceptionReceivedEvent(e, "Test", _traceWriter, _loggerFactory); + var options = new OnMessageOptions(); + var handler = MessagingExceptionHandler.Subscribe(options, _traceWriter, _loggerFactory); + handler.LogExceptionReceivedEvent(e); - var expectedMessage = $"Test error (Action=Connect)"; + var expectedMessage = $"MessageReceiver error (Action=Connect) : {ex.ToString()}"; var traceEvent = _traceWriter.GetTraces().Single(); - Assert.Equal(TraceLevel.Verbose, traceEvent.Level); - Assert.Equal($"{expectedMessage} : {ex.ToString()}", traceEvent.Message); + Assert.Equal(TraceLevel.Info, traceEvent.Level); + Assert.Equal(expectedMessage, traceEvent.Message); Assert.Same(ex, traceEvent.Exception); var logMessage = _loggerProvider.GetAllLogMessages().Single(); - Assert.Equal(LogLevel.Debug, logMessage.Level); + Assert.Equal(LogLevel.Information, logMessage.Level); Assert.Same(ex, logMessage.Exception); Assert.Equal(expectedMessage, logMessage.FormattedMessage); } [Fact] - public void LogExceptionReceivedEvent_OperationCanceledException_LoggedAsVerbose() + public void ServiceBus_LogExceptionReceivedEvent_OperationCanceledException_LoggedAsVerbose() { var ex = new OperationCanceledException("Testing"); ExceptionReceivedEventArgs e = new ExceptionReceivedEventArgs(ex, "Receive"); - Utility.LogExceptionReceivedEvent(e, "Test", _traceWriter, _loggerFactory); + var options = new OnMessageOptions(); + var handler = MessagingExceptionHandler.Subscribe(options, _traceWriter, _loggerFactory); + handler.LogExceptionReceivedEvent(e); - var expectedMessage = $"Test error (Action=Receive)"; + var expectedMessage = $"MessageReceiver error (Action=Receive) : {ex.ToString()}"; var traceEvent = _traceWriter.GetTraces().Single(); - Assert.Equal(TraceLevel.Verbose, traceEvent.Level); - Assert.Equal($"{expectedMessage} : {ex.ToString()}", traceEvent.Message); + Assert.Equal(TraceLevel.Info, traceEvent.Level); + Assert.Equal(expectedMessage, traceEvent.Message); Assert.Same(ex, traceEvent.Exception); var logMessage = _loggerProvider.GetAllLogMessages().Single(); - Assert.Equal(LogLevel.Debug, logMessage.Level); + Assert.Equal(LogLevel.Information, logMessage.Level); Assert.Same(ex, logMessage.Exception); Assert.Equal(expectedMessage, logMessage.FormattedMessage); } [Fact] - public void LogExceptionReceivedEvent_NonMessagingException_LoggedAsError() + public void ServiceBus_LogExceptionReceivedEvent_NonMessagingException_LoggedAsError() { var ex = new MissingMethodException("What method??"); ExceptionReceivedEventArgs e = new ExceptionReceivedEventArgs(ex, "Unknown"); - Utility.LogExceptionReceivedEvent(e, "Test", _traceWriter, _loggerFactory); + var options = new OnMessageOptions(); + var handler = MessagingExceptionHandler.Subscribe(options, _traceWriter, _loggerFactory); + handler.LogExceptionReceivedEvent(e); - var expectedMessage = $"Test error (Action=Unknown)"; + var expectedMessage = $"MessageReceiver error (Action=Unknown) : {e.Exception.ToString()}"; var traceEvent = _traceWriter.GetTraces().Single(); Assert.Equal(TraceLevel.Error, traceEvent.Level); Assert.Same(ex, traceEvent.Exception); @@ -106,5 +114,26 @@ public void LogExceptionReceivedEvent_NonMessagingException_LoggedAsError() Assert.Same(ex, logMessage.Exception); Assert.Equal(expectedMessage, logMessage.FormattedMessage); } + + [Fact] + public void EventHub_LogExceptionReceivedEvent_PartitionExceptions_LoggedAsTrace() + { + var ex = new ReceiverDisconnectedException("New receiver with higher epoch of '30402' is created hence current receiver with epoch '30402' is getting disconnected."); + ExceptionReceivedEventArgs e = new ExceptionReceivedEventArgs(ex, "Receive"); + var options = new EventProcessorOptions(); + var handler = MessagingExceptionHandler.Subscribe(options, _traceWriter, _loggerFactory); + handler.LogExceptionReceivedEvent(e); + + var expectedMessage = $"EventProcessorHost error (Action=Receive) : {ex.ToString()}"; + var traceEvent = _traceWriter.GetTraces().Single(); + Assert.Equal(TraceLevel.Info, traceEvent.Level); + Assert.Same(ex, traceEvent.Exception); + Assert.Equal(expectedMessage, traceEvent.Message); + + var logMessage = _loggerProvider.GetAllLogMessages().Single(); + Assert.Equal(LogLevel.Information, logMessage.Level); + Assert.Same(ex, logMessage.Exception); + Assert.Equal(expectedMessage, logMessage.FormattedMessage); + } } } diff --git a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Triggers/ServiceBusSubscriptionListenerFactoryTests.cs b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Triggers/ServiceBusSubscriptionListenerFactoryTests.cs index 3f8fdc906..fe2581a84 100644 --- a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Triggers/ServiceBusSubscriptionListenerFactoryTests.cs +++ b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Triggers/ServiceBusSubscriptionListenerFactoryTests.cs @@ -23,7 +23,9 @@ public async Task CreateAsync_AccessRightsNotManage_DoesNotCreateTopicOrSubscrip { ServiceBusAccount account = new ServiceBusAccount(); Mock mockExecutor = new Mock(MockBehavior.Strict); - ServiceBusSubscriptionListenerFactory factory = new ServiceBusSubscriptionListenerFactory(account, "testtopic", "testsubscription", mockExecutor.Object, accessRights, new ServiceBusConfiguration()); + ServiceBusConfiguration config = new ServiceBusConfiguration(); + var exceptionHandler = MessagingExceptionHandler.Subscribe(config.MessageOptions, new TestTraceWriter(TraceLevel.Verbose)); + ServiceBusSubscriptionListenerFactory factory = new ServiceBusSubscriptionListenerFactory(account, "testtopic", "testsubscription", mockExecutor.Object, accessRights, config, exceptionHandler); IListener listener = await factory.CreateAsync(CancellationToken.None); Assert.NotNull(listener); diff --git a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Triggers/ServiceBusTriggerBindingIntegrationTests.cs b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Triggers/ServiceBusTriggerBindingIntegrationTests.cs index f80c24c14..ee8d9cf74 100644 --- a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Triggers/ServiceBusTriggerBindingIntegrationTests.cs +++ b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/Triggers/ServiceBusTriggerBindingIntegrationTests.cs @@ -27,8 +27,10 @@ public ServiceBusTriggerBindingIntegrationTests() IQueueTriggerArgumentBindingProvider provider = new UserTypeArgumentBindingProvider(); ParameterInfo pi = new StubParameterInfo("parameterName", typeof(UserDataType)); var argumentBinding = provider.TryCreate(pi); - _queueBinding = new ServiceBusTriggerBinding("parameterName", typeof(UserDataType), argumentBinding, null, AccessRights.Manage, new ServiceBusConfiguration(), "queueName"); - _topicBinding = new ServiceBusTriggerBinding("parameterName", typeof(UserDataType), argumentBinding, null, AccessRights.Manage, new ServiceBusConfiguration(), "subscriptionName", "topicName"); + var config = new ServiceBusConfiguration(); + var exceptionHandler = MessagingExceptionHandler.Subscribe(config.MessageOptions, new TestTraceWriter(TraceLevel.Verbose)); + _queueBinding = new ServiceBusTriggerBinding("parameterName", typeof(UserDataType), argumentBinding, null, AccessRights.Manage, new ServiceBusConfiguration(), "queueName", exceptionHandler); + _topicBinding = new ServiceBusTriggerBinding("parameterName", typeof(UserDataType), argumentBinding, null, AccessRights.Manage, new ServiceBusConfiguration(), "subscriptionName", "topicName", exceptionHandler); } [Theory] 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 fbb71fb4c..7705ce59d 100644 --- a/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/WebJobs.ServiceBus.UnitTests.csproj +++ b/test/Microsoft.Azure.WebJobs.ServiceBus.UnitTests/WebJobs.ServiceBus.UnitTests.csproj @@ -218,7 +218,7 @@ - +