From f235f94e2808ae318c89863cff2b0a89c08f8851 Mon Sep 17 00:00:00 2001 From: JoshLove-msft <54595583+JoshLove-msft@users.noreply.github.com> Date: Wed, 20 May 2020 21:46:40 -0700 Subject: [PATCH] Logging clean up (#12222) --- .../src/Amqp/AmqpConnectionScope.cs | 75 ++++++++----------- .../src/Amqp/AmqpReceiver.cs | 36 +++++++-- .../src/Diagnostics/ServiceBusEventSource.cs | 6 +- .../tests/Amqp/AmqpReceiverTests.cs | 12 --- .../tests/Diagnostics/EventSourceLiveTests.cs | 2 + 5 files changed, 68 insertions(+), 63 deletions(-) diff --git a/sdk/servicebus/Azure.Messaging.ServiceBus/src/Amqp/AmqpConnectionScope.cs b/sdk/servicebus/Azure.Messaging.ServiceBus/src/Amqp/AmqpConnectionScope.cs index c3db25b9460da..c05803d2ffc07 100644 --- a/sdk/servicebus/Azure.Messaging.ServiceBus/src/Amqp/AmqpConnectionScope.cs +++ b/sdk/servicebus/Azure.Messaging.ServiceBus/src/Amqp/AmqpConnectionScope.cs @@ -271,7 +271,6 @@ public virtual async Task OpenManagementLinkAsync( /// The used to specify how messages are received. Defaults to PeekLock mode. /// /// - /// The identifier for the receive link. /// The timeout to apply when creating the link. /// An optional instance to signal the request to cancel the operation. /// @@ -284,44 +283,34 @@ public virtual async Task OpenReceiverLinkAsync( ReceiveMode receiveMode, string sessionId, bool isSessionReceiver, - string identifier, CancellationToken cancellationToken) { - ServiceBusEventSource.Log.CreateReceiveLinkStart(identifier); - try - { - cancellationToken.ThrowIfCancellationRequested(); + cancellationToken.ThrowIfCancellationRequested(); - var stopWatch = ValueStopwatch.StartNew(); - var receiverEndpoint = new Uri(ServiceEndpoint, entityPath); + var stopWatch = ValueStopwatch.StartNew(); + var receiverEndpoint = new Uri(ServiceEndpoint, entityPath); - var connection = await ActiveConnection.GetOrCreateAsync(timeout).ConfigureAwait(false); - cancellationToken.ThrowIfCancellationRequested(); + var connection = await ActiveConnection.GetOrCreateAsync(timeout).ConfigureAwait(false); + cancellationToken.ThrowIfCancellationRequested(); - ReceivingAmqpLink link = await CreateReceivingLinkAsync( - entityPath, - connection, - receiverEndpoint, - timeout.CalculateRemaining(stopWatch.GetElapsedTime()), - prefetchCount, - receiveMode, - sessionId, - isSessionReceiver, - cancellationToken - ).ConfigureAwait(false); + ReceivingAmqpLink link = await CreateReceivingLinkAsync( + entityPath, + connection, + receiverEndpoint, + timeout.CalculateRemaining(stopWatch.GetElapsedTime()), + prefetchCount, + receiveMode, + sessionId, + isSessionReceiver, + cancellationToken + ).ConfigureAwait(false); - cancellationToken.ThrowIfCancellationRequested(); + cancellationToken.ThrowIfCancellationRequested(); + + await OpenAmqpObjectAsync(link, timeout.CalculateRemaining(stopWatch.GetElapsedTime())).ConfigureAwait(false); + cancellationToken.ThrowIfCancellationRequested(); + return link; - await OpenAmqpObjectAsync(link, timeout.CalculateRemaining(stopWatch.GetElapsedTime())).ConfigureAwait(false); - cancellationToken.ThrowIfCancellationRequested(); - ServiceBusEventSource.Log.CreateReceiveLinkComplete(identifier); - return link; - } - catch (Exception ex) - { - ServiceBusEventSource.Log.CreateReceiveLinkException(identifier, ex.ToString()); - throw; - } } /// @@ -910,28 +899,30 @@ protected virtual TimerCallback CreateAuthorizationRefreshHandler( refreshTimeout) .ConfigureAwait(false); - // Reset the timer for the next refresh. + // Reset the timer for the next refresh. - if (authExpirationUtc >= DateTimeOffset.UtcNow) + if (authExpirationUtc >= DateTimeOffset.UtcNow) { refreshTimer.Change(CalculateLinkAuthorizationRefreshInterval(authExpirationUtc), Timeout.InfiniteTimeSpan); } } catch (ObjectDisposedException) { - // This can occur if the connection is closed or the scope disposed after the factory - // is called but before the timer is updated. The callback may also fire while the timer is - // in the act of disposing. Do not consider it an error. - } + // This can occur if the connection is closed or the scope disposed after the factory + // is called but before the timer is updated. The callback may also fire while the timer is + // in the act of disposing. Do not consider it an error. + } catch (Exception ex) { ServiceBusEventSource.Log.AmqpLinkAuthorizationRefreshError(entityPath, endpoint.AbsoluteUri, ex.Message); - // Attempt to unset the timer; there's a decent chance that it has been disposed at this point or - // that the connection has been closed. Ignore potential exceptions, as they won't impact operation. - // At worse, another timer tick will occur and the operation will be retried. + // Attempt to unset the timer; there's a decent chance that it has been disposed at this point or + // that the connection has been closed. Ignore potential exceptions, as they won't impact operation. + // At worse, another timer tick will occur and the operation will be retried. - try { refreshTimer.Change(Timeout.Infinite, Timeout.Infinite); } catch {} + try + { refreshTimer.Change(Timeout.Infinite, Timeout.Infinite); } + catch { } } finally { diff --git a/sdk/servicebus/Azure.Messaging.ServiceBus/src/Amqp/AmqpReceiver.cs b/sdk/servicebus/Azure.Messaging.ServiceBus/src/Amqp/AmqpReceiver.cs index 44966e999cdb5..7270668f8a88a 100644 --- a/sdk/servicebus/Azure.Messaging.ServiceBus/src/Amqp/AmqpReceiver.cs +++ b/sdk/servicebus/Azure.Messaging.ServiceBus/src/Amqp/AmqpReceiver.cs @@ -135,15 +135,12 @@ public AmqpReceiver( _receiveLink = new FaultTolerantAmqpObject( timeout => - _connectionScope.OpenReceiverLinkAsync( - entityPath: _entityPath, + OpenReceiverLinkAsync( timeout: timeout, prefetchCount: prefetchCount, receiveMode: receiveMode, sessionId: sessionId, - isSessionReceiver: isSessionReceiver, - identifier: _identifier, - cancellationToken: CancellationToken.None), + isSessionReceiver: isSessionReceiver), link => CloseLink(link)); _managementLink = new FaultTolerantAmqpObject( @@ -155,6 +152,35 @@ public AmqpReceiver( link => CloseLink(link)); } + private async Task OpenReceiverLinkAsync( + TimeSpan timeout, + uint prefetchCount, + ReceiveMode receiveMode, + string sessionId, + bool isSessionReceiver) + { + ServiceBusEventSource.Log.CreateReceiveLinkStart(_identifier); + + try + { + ReceivingAmqpLink link = await _connectionScope.OpenReceiverLinkAsync( + entityPath: _entityPath, + timeout: timeout, + prefetchCount: prefetchCount, + receiveMode: receiveMode, + sessionId: sessionId, + isSessionReceiver: isSessionReceiver, + cancellationToken: CancellationToken.None).ConfigureAwait(false); + ServiceBusEventSource.Log.CreateReceiveLinkComplete(_identifier); + return link; + } + catch (Exception ex) + { + ServiceBusEventSource.Log.CreateReceiveLinkException(_identifier, ex.ToString()); + throw; + } + } + private void CloseLink(ReceivingAmqpLink link) { link.Session?.SafeClose(); diff --git a/sdk/servicebus/Azure.Messaging.ServiceBus/src/Diagnostics/ServiceBusEventSource.cs b/sdk/servicebus/Azure.Messaging.ServiceBus/src/Diagnostics/ServiceBusEventSource.cs index 90ea5dc71f911..80c6bfd3d7e12 100644 --- a/sdk/servicebus/Azure.Messaging.ServiceBus/src/Diagnostics/ServiceBusEventSource.cs +++ b/sdk/servicebus/Azure.Messaging.ServiceBus/src/Diagnostics/ServiceBusEventSource.cs @@ -100,6 +100,8 @@ internal ServiceBusEventSource() { } internal const int AmqpLinkRefreshStartEvent = 39; internal const int AmqpLinkRefreshCompleteEvent = 40; internal const int AmqpLinkRefreshExceptionEvent = 41; + + internal const int ManagementSerializedExceptionEvent = 42; internal const int RunOperationExceptionEvent = 43; internal const int ClientDisposeStartEvent = 44; @@ -170,8 +172,6 @@ internal ServiceBusEventSource() { } internal const int ProcessorErrorHandlerThrewExceptionEvent = 94; internal const int ScheduleTaskFailedEvent = 95; - internal const int ManagementSerializedExceptionEvent = 96; - #endregion // add new event numbers here incrementing from previous @@ -724,8 +724,6 @@ public void ProcessorErrorHandlerThrewException(string exception) } } - - #endregion region #region Rule management diff --git a/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Amqp/AmqpReceiverTests.cs b/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Amqp/AmqpReceiverTests.cs index d2deac1e96de0..05631822566f3 100644 --- a/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Amqp/AmqpReceiverTests.cs +++ b/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Amqp/AmqpReceiverTests.cs @@ -162,7 +162,6 @@ public void ReceiveAsyncAppliesTheRetryPolicy(ServiceBusRetryOptions retryOption It.IsAny(), It.IsAny(), It.IsAny(), - It.IsAny(), It.IsAny())) .Throws(retriableException); @@ -180,7 +179,6 @@ public void ReceiveAsyncAppliesTheRetryPolicy(ServiceBusRetryOptions retryOption It.IsAny(), It.IsAny(), It.IsAny(), - It.IsAny(), It.IsAny()), Times.Exactly(1 + retryOptions.MaxRetries)); } @@ -218,7 +216,6 @@ public void ReceiveAsyncConsidersOperationCanceledExceptionAsRetriable(ServiceBu It.IsAny(), It.IsAny(), It.IsAny(), - It.IsAny(), It.IsAny())) .Throws(retriableException); @@ -236,7 +233,6 @@ public void ReceiveAsyncConsidersOperationCanceledExceptionAsRetriable(ServiceBu It.IsAny(), It.IsAny(), It.IsAny(), - It.IsAny(), It.IsAny()), Times.Exactly(1 + retryOptions.MaxRetries)); } @@ -282,7 +278,6 @@ public void ReceiveAsyncAppliesTheRetryPolicyForAmqpErrors(ServiceBusRetryOption It.IsAny(), It.IsAny(), It.IsAny(), - It.IsAny(), It.IsAny())) .Throws(retriableException); @@ -300,7 +295,6 @@ public void ReceiveAsyncAppliesTheRetryPolicyForAmqpErrors(ServiceBusRetryOption It.IsAny(), It.IsAny(), It.IsAny(), - It.IsAny(), It.IsAny()), Times.Exactly(1 + retryOptions.MaxRetries)); @@ -342,7 +336,6 @@ public void ReceiveAsyncDetectsAnEmbeddedErrorForOperationCanceled() It.IsAny(), It.IsAny(), It.IsAny(), - It.IsAny(), It.IsAny())) .Throws(exception); @@ -360,7 +353,6 @@ public void ReceiveAsyncDetectsAnEmbeddedErrorForOperationCanceled() It.IsAny(), It.IsAny(), It.IsAny(), - It.IsAny(), It.IsAny()), Times.Once()); } @@ -398,7 +390,6 @@ public void ReceiveAsyncDetectsAnEmbeddedAmqpErrorForOperationCanceled() It.IsAny(), It.IsAny(), It.IsAny(), - It.IsAny(), It.IsAny())) .Throws(exception); @@ -416,7 +407,6 @@ public void ReceiveAsyncDetectsAnEmbeddedAmqpErrorForOperationCanceled() It.IsAny(), It.IsAny(), It.IsAny(), - It.IsAny(), It.IsAny()), Times.Once()); } @@ -453,7 +443,6 @@ public void ReceiveAsyncDoesntRetryOnTaskCanceled() It.IsAny(), It.IsAny(), It.IsAny(), - It.IsAny(), It.IsAny())) .Throws(exception); @@ -471,7 +460,6 @@ public void ReceiveAsyncDoesntRetryOnTaskCanceled() It.IsAny(), It.IsAny(), It.IsAny(), - It.IsAny(), It.IsAny()), Times.Once()); } diff --git a/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Diagnostics/EventSourceLiveTests.cs b/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Diagnostics/EventSourceLiveTests.cs index 1f3da362ff46c..5fd5d12ebb77e 100644 --- a/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Diagnostics/EventSourceLiveTests.cs +++ b/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Diagnostics/EventSourceLiveTests.cs @@ -199,6 +199,8 @@ public async Task LogsTransactionEvents() await sender.SendAsync(message); ts.Complete(); } + // Adding delay since transaction Commit/Rollback is an asynchronous operation. + await Task.Delay(TimeSpan.FromSeconds(2)); _listener.SingleEventById(ServiceBusEventSource.TransactionDeclaredEvent); _listener.SingleEventById(ServiceBusEventSource.TransactionDischargedEvent); };