refactor(iot-device): Add additional logging statement to disposal fl…

…ow (#2414)
Azure · May 26, 2022 · 929a6d3 · 929a6d3
1 parent fbbde16
commit 929a6d3
Show file tree

Hide file tree

Showing 12 changed files with 303 additions and 135 deletions.
diff --git a/iothub/device/src/Authentication/AuthenticationWithTokenRefresh.cs b/iothub/device/src/Authentication/AuthenticationWithTokenRefresh.cs
@@ -101,6 +101,14 @@ public async Task<string> 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)
         /// <param name="disposing">true to release both managed and unmanaged resources; false to release only unmanaged resources.</param>
         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
@@ -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(
         ///<inheritdoc/>
         protected override Task<string> 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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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<IAmqpAuthenticationRefresher> CreateRefresherAsync(IDeviceIdentity deviceIdentity, CancellationToken cancellationToken)

diff --git 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)}");
                 }
             }
         }