From 15abc52fc15ba0e59fdc317a9c11322bc64d08c7 Mon Sep 17 00:00:00 2001 From: Abhipsa Misra Date: Wed, 25 May 2022 17:13:48 -0700 Subject: [PATCH] refactor(iot-device): Add additional logging statement to disposal flow (#2414) --- .../AuthenticationWithTokenRefresh.cs | 33 +++++++++-- .../DeviceAuthenticationWithSakRefresh.cs | 44 +++++++++----- .../src/Pipeline/DefaultDelegatingHandler.cs | 27 ++++++--- .../src/Pipeline/RetryDelegatingHandler.cs | 37 ++++++++---- .../device/src/Pipeline/TransportHandler.cs | 27 +++++++-- .../Amqp/AmqpAuthenticationRefresher.cs | 34 +++++++---- .../Transport/Amqp/AmqpConnectionHolder.cs | 38 +++++++----- .../Transport/Amqp/AmqpTransportHandler.cs | 31 ++++++---- iothub/device/src/Transport/Amqp/AmqpUnit.cs | 59 +++++++++++-------- .../AmqpIot/AmqpIotCbsTokenProvider.cs | 29 ++++++--- .../Transport/Http/HttpTransportHandler.cs | 27 +++++++-- .../Transport/Mqtt/MqttTransportHandler.cs | 52 ++++++++++------ 12 files changed, 303 insertions(+), 135 deletions(-) diff --git a/iothub/device/src/Authentication/AuthenticationWithTokenRefresh.cs b/iothub/device/src/Authentication/AuthenticationWithTokenRefresh.cs index dcb4639a2a..fdadf99485 100644 --- a/iothub/device/src/Authentication/AuthenticationWithTokenRefresh.cs +++ b/iothub/device/src/Authentication/AuthenticationWithTokenRefresh.cs @@ -101,6 +101,14 @@ public async Task GetTokenAsync(string iotHub) { if (_isDisposed) { + if (Logging.IsEnabled) + { + Logging.Error( + this, + $"Encountered {nameof(ObjectDisposedException)} - The authentication method instance has already been disposed, so this client is no longer usable.", + nameof(GetTokenAsync)); + } + throw new ObjectDisposedException(GetType().Name, "The authentication method instance has already been disposed, so this client is no longer usable. " + "Please close and dispose your current client instance. To continue carrying out operations from your device/ module, " + "create a new authentication method instance and use it for reinitializing your client."); @@ -177,15 +185,30 @@ private void UpdateTimeBufferSeconds(int ttl) /// true to release both managed and unmanaged resources; false to release only unmanaged resources. protected virtual void Dispose(bool disposing) { - if (!_isDisposed) + try { - if (disposing) + if (Logging.IsEnabled) { - _lock?.Dispose(); - _lock = null; + Logging.Enter(this, $"Disposed={_isDisposed}; disposing={disposing}", $"{nameof(AuthenticationWithTokenRefresh)}.{nameof(Dispose)}"); } - _isDisposed = true; + if (!_isDisposed) + { + if (disposing) + { + _lock?.Dispose(); + _lock = null; + } + + _isDisposed = true; + } + } + finally + { + if (Logging.IsEnabled) + { + Logging.Exit(this, $"Disposed={_isDisposed}; disposing={disposing}", $"{nameof(AuthenticationWithTokenRefresh)}.{nameof(Dispose)}"); + } } } diff --git a/iothub/device/src/Authentication/DeviceAuthenticationWithSakRefresh.cs b/iothub/device/src/Authentication/DeviceAuthenticationWithSakRefresh.cs index 5c7ae888d7..00c6f8c533 100644 --- a/iothub/device/src/Authentication/DeviceAuthenticationWithSakRefresh.cs +++ b/iothub/device/src/Authentication/DeviceAuthenticationWithSakRefresh.cs @@ -5,6 +5,7 @@ using System.Net; using System.Threading.Tasks; using Microsoft.Azure.Devices.Client.Extensions; +using Microsoft.Azure.Devices.Shared; namespace Microsoft.Azure.Devices.Client { @@ -34,25 +35,40 @@ internal DeviceAuthenticationWithSakRefresh( /// protected override Task SafeCreateNewToken(string iotHub, int suggestedTimeToLive) { - var builder = new SharedAccessSignatureBuilder + try { - Key = _connectionString.SharedAccessKey, - TimeToLive = TimeSpan.FromSeconds(suggestedTimeToLive), - }; + if (Logging.IsEnabled) + { + Logging.Enter(this, iotHub, suggestedTimeToLive, nameof(SafeCreateNewToken)); + } - if (_connectionString.SharedAccessKeyName == null) - { - builder.Target = "{0}/devices/{1}".FormatInvariant( - iotHub, - WebUtility.UrlEncode(DeviceId)); + var builder = new SharedAccessSignatureBuilder + { + Key = _connectionString.SharedAccessKey, + TimeToLive = TimeSpan.FromSeconds(suggestedTimeToLive), + }; + + if (_connectionString.SharedAccessKeyName == null) + { + builder.Target = "{0}/devices/{1}".FormatInvariant( + iotHub, + WebUtility.UrlEncode(DeviceId)); + } + else + { + builder.KeyName = _connectionString.SharedAccessKeyName; + builder.Target = _connectionString.Audience; + } + + return Task.FromResult(builder.ToSignature()); } - else + finally { - builder.KeyName = _connectionString.SharedAccessKeyName; - builder.Target = _connectionString.Audience; + if (Logging.IsEnabled) + { + Logging.Exit(this, iotHub, suggestedTimeToLive, nameof(SafeCreateNewToken)); + } } - - return Task.FromResult(builder.ToSignature()); } } } diff --git a/iothub/device/src/Pipeline/DefaultDelegatingHandler.cs b/iothub/device/src/Pipeline/DefaultDelegatingHandler.cs index bc841eda79..6999507a99 100644 --- a/iothub/device/src/Pipeline/DefaultDelegatingHandler.cs +++ b/iothub/device/src/Pipeline/DefaultDelegatingHandler.cs @@ -215,17 +215,30 @@ protected void ThrowIfDisposed() protected virtual void Dispose(bool disposing) { - if (_disposed) + try { - return; + if (Logging.IsEnabled) + { + Logging.Enter(this, $"Disposed={_disposed}; disposing={disposing}", $"{nameof(DefaultDelegatingHandler)}.{nameof(Dispose)}"); + } + + if (!_disposed) + { + if (disposing) + { + _innerHandler?.Dispose(); + } + + _disposed = true; + } } - - if (disposing) + finally { - _innerHandler?.Dispose(); + if (Logging.IsEnabled) + { + Logging.Exit(this, $"Disposed={_disposed}; disposing={disposing}", $"{nameof(DefaultDelegatingHandler)}.{nameof(Dispose)}"); + } } - - _disposed = true; } ~DefaultDelegatingHandler() diff --git a/iothub/device/src/Pipeline/RetryDelegatingHandler.cs b/iothub/device/src/Pipeline/RetryDelegatingHandler.cs index 63a6db38bf..ef61af989e 100644 --- a/iothub/device/src/Pipeline/RetryDelegatingHandler.cs +++ b/iothub/device/src/Pipeline/RetryDelegatingHandler.cs @@ -1076,22 +1076,37 @@ private void HandleConnectionStatusExceptions(Exception exception, bool retryAtt protected override void Dispose(bool disposing) { - if (_disposed) + try { - return; - } + if (Logging.IsEnabled) + { + Logging.Enter(this, $"{nameof(DefaultDelegatingHandler)}.Disposed={_disposed}; disposing={disposing}", $"{nameof(RetryDelegatingHandler)}.{nameof(Dispose)}"); + } - base.Dispose(disposing); - if (disposing) + if (!_disposed) + { + base.Dispose(disposing); + if (disposing) + { + _handleDisconnectCts?.Cancel(); + _handleDisconnectCts?.Dispose(); + if (_handlerSemaphore != null && _handlerSemaphore.CurrentCount == 0) + { + _handlerSemaphore.Release(); + } + _handlerSemaphore?.Dispose(); + _handlerSemaphore = null; + } + + // the _disposed flag is inherited from the base class DefaultDelegatingHandler and is finally set to null there. + } + } + finally { - _handleDisconnectCts?.Cancel(); - _handleDisconnectCts?.Dispose(); - if (_handlerSemaphore != null && _handlerSemaphore.CurrentCount == 0) + if (Logging.IsEnabled) { - _handlerSemaphore.Release(); + Logging.Exit(this, $"{nameof(DefaultDelegatingHandler)}.Disposed={_disposed}; disposing={disposing}", $"{nameof(RetryDelegatingHandler)}.{nameof(Dispose)}"); } - _handlerSemaphore?.Dispose(); - _handlerSemaphore = null; } } } diff --git a/iothub/device/src/Pipeline/TransportHandler.cs b/iothub/device/src/Pipeline/TransportHandler.cs index 7f68be656a..a72eea3065 100644 --- a/iothub/device/src/Pipeline/TransportHandler.cs +++ b/iothub/device/src/Pipeline/TransportHandler.cs @@ -25,15 +25,30 @@ public override Task WaitForTransportClosedAsync() protected override void Dispose(bool disposing) { - if (_disposed) + try { - return; - } + if (Logging.IsEnabled) + { + Logging.Enter(this, $"{nameof(DefaultDelegatingHandler)}.Disposed={_disposed}; disposing={disposing}", $"{nameof(TransportHandler)}.{nameof(Dispose)}"); + } + + if (!_disposed) + { + base.Dispose(disposing); + if (disposing) + { + OnTransportClosedGracefully(); + } - base.Dispose(disposing); - if (disposing) + // the _disposed flag is inherited from the base class DefaultDelegatingHandler and is finally set to null there. + } + } + finally { - OnTransportClosedGracefully(); + if (Logging.IsEnabled) + { + Logging.Exit(this, $"{nameof(DefaultDelegatingHandler)}.Disposed={_disposed}; disposing={disposing}", $"{nameof(TransportHandler)}.{nameof(Dispose)}"); + } } } diff --git a/iothub/device/src/Transport/Amqp/AmqpAuthenticationRefresher.cs b/iothub/device/src/Transport/Amqp/AmqpAuthenticationRefresher.cs index 7315e1d51b..8a2bb83db6 100644 --- a/iothub/device/src/Transport/Amqp/AmqpAuthenticationRefresher.cs +++ b/iothub/device/src/Transport/Amqp/AmqpAuthenticationRefresher.cs @@ -102,7 +102,9 @@ private async Task RefreshLoopAsync(DateTime refreshesOn, CancellationToken canc catch (IotHubCommunicationException ex) { if (Logging.IsEnabled) - Logging.Info(this, refreshesOn, $"Refresh token failed {ex}"); + { + Logging.Error(this, refreshesOn, $"Refresh token failed {ex}"); + } } finally { @@ -129,21 +131,31 @@ public void Dispose() private void Dispose(bool disposing) { - if (_disposed) + try { - return; - } + if (Logging.IsEnabled) + { + Logging.Enter(this, $"Disposed={_disposed}; disposing={disposing}", $"{nameof(AmqpAuthenticationRefresher)}.{nameof(Dispose)}"); + } - if (Logging.IsEnabled) - Logging.Info(this, disposing, nameof(Dispose)); + if (!_disposed) + { + if (disposing) + { + StopLoop(); + _amqpIotCbsTokenProvider?.Dispose(); + } - if (disposing) + _disposed = true; + } + } + finally { - StopLoop(); - _amqpIotCbsTokenProvider?.Dispose(); + if (Logging.IsEnabled) + { + Logging.Exit(this, $"Disposed={_disposed}; disposing={disposing}", $"{nameof(AmqpAuthenticationRefresher)}.{nameof(Dispose)}"); + } } - - _disposed = true; } } } diff --git a/iothub/device/src/Transport/Amqp/AmqpConnectionHolder.cs b/iothub/device/src/Transport/Amqp/AmqpConnectionHolder.cs index 66c72af8c6..6430abb022 100644 --- a/iothub/device/src/Transport/Amqp/AmqpConnectionHolder.cs +++ b/iothub/device/src/Transport/Amqp/AmqpConnectionHolder.cs @@ -105,27 +105,37 @@ public void Dispose() private void Dispose(bool disposing) { - if (_disposed) + try { - return; - } + if (Logging.IsEnabled) + { + Logging.Enter(this, $"Disposed={_disposed}; disposing={disposing}", $"{nameof(AmqpConnectionHolder)}.{nameof(Dispose)}"); + } - if (Logging.IsEnabled) - Logging.Info(this, disposing, nameof(Dispose)); + if (!_disposed) + { + if (disposing) + { + _amqpIotConnection?.SafeClose(); + _lock?.Dispose(); + _amqpIotConnector?.Dispose(); + lock (_unitsLock) + { + _amqpUnits.Clear(); + } + _amqpAuthenticationRefresher?.Dispose(); + } - if (disposing) + _disposed = true; + } + } + finally { - _amqpIotConnection?.SafeClose(); - _lock?.Dispose(); - _amqpIotConnector?.Dispose(); - lock (_unitsLock) + if (Logging.IsEnabled) { - _amqpUnits.Clear(); + Logging.Exit(this, $"Disposed={_disposed}; disposing={disposing}", $"{nameof(AmqpConnectionHolder)}.{nameof(Dispose)}"); } - _amqpAuthenticationRefresher?.Dispose(); } - - _disposed = true; } public async Task CreateRefresherAsync(IDeviceIdentity deviceIdentity, CancellationToken cancellationToken) diff --git a/iothub/device/src/Transport/Amqp/AmqpTransportHandler.cs b/iothub/device/src/Transport/Amqp/AmqpTransportHandler.cs index 39db8f233e..846f618b05 100644 --- a/iothub/device/src/Transport/Amqp/AmqpTransportHandler.cs +++ b/iothub/device/src/Transport/Amqp/AmqpTransportHandler.cs @@ -616,23 +616,34 @@ private void TwinMessageListener(Twin twin, string correlationId, TwinCollection protected override void Dispose(bool disposing) { - lock (_lock) + try { - if (_disposed) + if (Logging.IsEnabled) { - return; + Logging.Enter(this, $"{nameof(DefaultDelegatingHandler)}.Disposed={_disposed}; disposing={disposing}", $"{nameof(AmqpTransportHandler)}.{nameof(Dispose)}"); } - base.Dispose(disposing); + lock (_lock) + { + if (!_disposed) + { + base.Dispose(disposing); + if (disposing) + { + _closed = true; + AmqpUnitManager.GetInstance()?.RemoveAmqpUnit(_amqpUnit); + _disposed = true; + } + } + // the _disposed flag is inherited from the base class DefaultDelegatingHandler and is finally set to null there. + } + } + finally + { if (Logging.IsEnabled) - Logging.Info(this, nameof(disposing)); - - if (disposing) { - _closed = true; - AmqpUnitManager.GetInstance()?.RemoveAmqpUnit(_amqpUnit); - _disposed = true; + Logging.Exit(this, $"{nameof(DefaultDelegatingHandler)}.Disposed={_disposed}; disposing={disposing}", $"{nameof(AmqpTransportHandler)}.{nameof(Dispose)}"); } } } diff --git a/iothub/device/src/Transport/Amqp/AmqpUnit.cs b/iothub/device/src/Transport/Amqp/AmqpUnit.cs index bbf47fc9bf..76c3c8ccf2 100644 --- a/iothub/device/src/Transport/Amqp/AmqpUnit.cs +++ b/iothub/device/src/Transport/Amqp/AmqpUnit.cs @@ -952,38 +952,47 @@ public void Dispose() private void Dispose(bool disposing) { - if (_disposed) - { - return; - } - - _disposed = true; - - if (disposing) + try { if (Logging.IsEnabled) - Logging.Enter(this, disposing, nameof(Dispose)); - - Cleanup(); - if (!_deviceIdentity.IsPooling()) { - _amqpConnectionHolder?.Dispose(); + Logging.Enter(this, $"Device pooling={_deviceIdentity?.IsPooling()}; disposed={_disposed}; disposing={disposing}", $"{nameof(AmqpUnit)}.{nameof(Dispose)}"); } - // For device sas authenticated clients the authentication refresher is associated with the AMQP unit itself, - // so it needs to be explicitly disposed. - _amqpAuthenticationRefresher?.StopLoop(); - _amqpAuthenticationRefresher?.Dispose(); - - _sessionSemaphore?.Dispose(); - _messageReceivingLinkSemaphore?.Dispose(); - _messageReceivingCallbackSemaphore?.Dispose(); - _eventReceivingLinkSemaphore?.Dispose(); - _methodLinkSemaphore?.Dispose(); - _twinLinksSemaphore?.Dispose(); + if (!_disposed) + { + if (disposing) + { + Cleanup(); + if (!_deviceIdentity.IsPooling()) + { + _amqpConnectionHolder?.Dispose(); + } + + // For device sas authenticated clients the authentication refresher is associated with the AMQP unit itself, + // so it needs to be explicitly disposed. + _amqpAuthenticationRefresher?.StopLoop(); + _amqpAuthenticationRefresher?.Dispose(); + + _sessionSemaphore?.Dispose(); + _messageReceivingLinkSemaphore?.Dispose(); + _messageReceivingCallbackSemaphore?.Dispose(); + _eventReceivingLinkSemaphore?.Dispose(); + _methodLinkSemaphore?.Dispose(); + _twinLinksSemaphore?.Dispose(); + + Logging.Exit(this, disposing, nameof(Dispose)); + } + } + _disposed = true; + } + finally + { if (Logging.IsEnabled) - Logging.Exit(this, disposing, nameof(Dispose)); + { + Logging.Exit(this, $"Device pooling={_deviceIdentity?.IsPooling()}; disposed={_disposed}; disposing={disposing}", $"{nameof(AmqpUnit)}.{nameof(Dispose)}"); + } } } diff --git a/iothub/device/src/Transport/AmqpIot/AmqpIotCbsTokenProvider.cs b/iothub/device/src/Transport/AmqpIot/AmqpIotCbsTokenProvider.cs index cb4160eea4..8d5224f712 100644 --- a/iothub/device/src/Transport/AmqpIot/AmqpIotCbsTokenProvider.cs +++ b/iothub/device/src/Transport/AmqpIot/AmqpIotCbsTokenProvider.cs @@ -70,18 +70,33 @@ public void Dispose() protected virtual void Dispose(bool disposing) { - if (!_isDisposed) + try { - if (disposing) + if (Logging.IsEnabled) { - if (_connectionString?.TokenRefresher != null - && _connectionString.TokenRefresher.DisposalWithClient) + Logging.Enter(this, $"Disposal with client={_connectionString?.TokenRefresher?.DisposalWithClient}; disposed={_isDisposed}" , $"{nameof(AmqpIotCbsTokenProvider)}.{nameof(Dispose)}"); + } + + if (!_isDisposed) + { + if (disposing) { - _connectionString.TokenRefresher.Dispose(); + if (_connectionString?.TokenRefresher != null + && _connectionString.TokenRefresher.DisposalWithClient) + { + _connectionString.TokenRefresher.Dispose(); + } } - } - _isDisposed = true; + _isDisposed = true; + } + } + finally + { + if (Logging.IsEnabled) + { + Logging.Exit(this, $"Disposal with client={_connectionString?.TokenRefresher?.DisposalWithClient}; disposed={_isDisposed}", $"{nameof(AmqpIotCbsTokenProvider)}.{nameof(Dispose)}"); + } } } } diff --git a/iothub/device/src/Transport/Http/HttpTransportHandler.cs b/iothub/device/src/Transport/Http/HttpTransportHandler.cs index 61b3bb87f1..87edc41110 100644 --- a/iothub/device/src/Transport/Http/HttpTransportHandler.cs +++ b/iothub/device/src/Transport/Http/HttpTransportHandler.cs @@ -151,15 +151,30 @@ public override Task SendEventAsync(IEnumerable messages, CancellationT protected override void Dispose(bool disposing) { - if (_disposed) + try { - return; - } + if (Logging.IsEnabled) + { + Logging.Enter(this, $"{nameof(DefaultDelegatingHandler)}.Disposed={_disposed}; disposing={disposing}", $"{nameof(HttpTransportHandler)}.{nameof(Dispose)}"); + } + + if (!_disposed) + { + base.Dispose(disposing); + if (disposing) + { + _httpClientHelper?.Dispose(); + } - base.Dispose(disposing); - if (disposing) + // the _disposed flag is inherited from the base class DefaultDelegatingHandler and is finally set to null there. + } + } + finally { - _httpClientHelper?.Dispose(); + if (Logging.IsEnabled) + { + Logging.Exit(this, $"{nameof(DefaultDelegatingHandler)}.Disposed={_disposed}; disposing={disposing}", $"{nameof(HttpTransportHandler)}.{nameof(Dispose)}"); + } } } diff --git a/iothub/device/src/Transport/Mqtt/MqttTransportHandler.cs b/iothub/device/src/Transport/Mqtt/MqttTransportHandler.cs index fdab4d1671..c06844b355 100644 --- a/iothub/device/src/Transport/Mqtt/MqttTransportHandler.cs +++ b/iothub/device/src/Transport/Mqtt/MqttTransportHandler.cs @@ -452,33 +452,47 @@ public override Task RejectAsync(string lockToken, CancellationToken cancellatio protected override void Dispose(bool disposing) { - if (_disposed) - { - return; - } - - base.Dispose(disposing); - - if (disposing) + try { - if (TryStop()) + if (Logging.IsEnabled) { - CleanUpAsync().GetAwaiter().GetResult(); + Logging.Enter(this, $"{nameof(DefaultDelegatingHandler)}.Disposed={_disposed}; disposing={disposing}", $"{nameof(MqttTransportHandler)}.{nameof(Dispose)}"); } - _disconnectAwaitersCancellationSource?.Dispose(); - _disconnectAwaitersCancellationSource = null; + if (!_disposed) + { + base.Dispose(disposing); + if (disposing) + { + if (TryStop()) + { + CleanUpAsync().GetAwaiter().GetResult(); + } - _receivingSemaphore?.Dispose(); - _receivingSemaphore = null; + _disconnectAwaitersCancellationSource?.Dispose(); + _disconnectAwaitersCancellationSource = null; - _deviceReceiveMessageSemaphore?.Dispose(); - _deviceReceiveMessageSemaphore = null; + _receivingSemaphore?.Dispose(); + _receivingSemaphore = null; - if (_channel is IDisposable disposableChannel) + _deviceReceiveMessageSemaphore?.Dispose(); + _deviceReceiveMessageSemaphore = null; + + if (_channel is IDisposable disposableChannel) + { + disposableChannel.Dispose(); + _channel = null; + } + } + + // the _disposed flag is inherited from the base class DefaultDelegatingHandler and is finally set to null there. + } + } + finally + { + if (Logging.IsEnabled) { - disposableChannel.Dispose(); - _channel = null; + Logging.Exit(this, $"{nameof(DefaultDelegatingHandler)}.Disposed={_disposed}; disposing={disposing}", $"{nameof(MqttTransportHandler)}.{nameof(Dispose)}"); } } }