Add timeout to EdgeAgent - iotedged operations, and add more logs (#1132

) * Add timeout to EdgeAgent - iotedged operations, and add more logs * Fix build
Azure · Apr 25, 2019 · f2cb600 · f2cb600
1 parent 046f75c
commit f2cb600
Show file tree

Hide file tree

Showing 8 changed files with 127 additions and 12 deletions.
diff --git a/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/Agent.cs b/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/Agent.cs
@@ -108,6 +108,7 @@ public async Task ReconcileAsync(CancellationToken token)
             {
                 try
                 {
+                    Events.StartingReconcile();
                     (ModuleSet current, DeploymentConfigInfo deploymentConfigInfo, Exception exception) = await this.GetReconcileData(token);
                     moduleSetToReport = current;
                     if (exception != null)
@@ -176,6 +177,7 @@ public async Task ReconcileAsync(CancellationToken token)
                 }
 
                 await this.reporter.ReportAsync(token, moduleSetToReport, await this.environment.GetRuntimeInfoAsync(), this.currentConfig.Version, status);
+                Events.FinishedReconcile();
             }
         }
 
@@ -328,7 +330,9 @@ enum EventIds
                 CompletedShutdown,
                 StopModulesCompleted,
                 InitiatingStopModules,
-                StopModulesFailed
+                StopModulesFailed,
+                FinishedReconcile,
+                StartingReconcile
             }
 
             public static void AgentCreated()
@@ -418,6 +422,16 @@ internal static void ErrorDeserializingConfig(Exception ex)
             {
                 Log.LogWarning((int)EventIds.ErrorDeserializingConfig, ex, "There was an error deserializing stored deployment configuration information");
             }
+
+            public static void FinishedReconcile()
+            {
+                Log.LogDebug((int)EventIds.FinishedReconcile, "Finished reconcile operation");
+            }
+
+            public static void StartingReconcile()
+            {
+                Log.LogDebug((int)EventIds.StartingReconcile, "Starting reconcile operation");
+            }
         }
     }
 }
diff --git a/...crosoft.Azure.Devices.Edge.Agent.Edgelet/version_2018_06_28/ModuleManagementHttpClient.cs b/...crosoft.Azure.Devices.Edge.Agent.Edgelet/version_2018_06_28/ModuleManagementHttpClient.cs
@@ -6,6 +6,7 @@ namespace Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2018_06_28
     using System.Collections.ObjectModel;
     using System.Linq;
     using System.Net.Http;
+    using System.Runtime.ExceptionServices;
     using System.Threading;
     using System.Threading.Tasks;
     using Microsoft.Azure.Devices.Edge.Agent.Core;
@@ -22,7 +23,12 @@ namespace Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2018_06_28
     class ModuleManagementHttpClient : ModuleManagementHttpClientVersioned
     {
         public ModuleManagementHttpClient(Uri managementUri)
-            : base(managementUri, ApiVersion.Version20180628, new ErrorDetectionStrategy())
+            : this(managementUri, Option.None<TimeSpan>())
+        {
+        }
+
+        internal ModuleManagementHttpClient(Uri managementUri, Option<TimeSpan> operationTimeout)
+            : base(managementUri, ApiVersion.Version20180628, new ErrorDetectionStrategy(), operationTimeout)
         {
         }
 
@@ -194,7 +200,8 @@ protected override void HandleException(Exception exception, string operation)
                     }
 
                 default:
-                    throw exception;
+                    ExceptionDispatchInfo.Capture(exception).Throw();
+                    break;
             }
         }
 

diff --git a/...crosoft.Azure.Devices.Edge.Agent.Edgelet/version_2019_01_30/ModuleManagementHttpClient.cs b/...crosoft.Azure.Devices.Edge.Agent.Edgelet/version_2019_01_30/ModuleManagementHttpClient.cs
@@ -6,6 +6,7 @@ namespace Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2019_01_30
     using System.Collections.ObjectModel;
     using System.Linq;
     using System.Net.Http;
+    using System.Runtime.ExceptionServices;
     using System.Threading;
     using System.Threading.Tasks;
     using Microsoft.Azure.Devices.Edge.Agent.Core;
@@ -22,7 +23,12 @@ namespace Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2019_01_30
     class ModuleManagementHttpClient : ModuleManagementHttpClientVersioned
     {
         public ModuleManagementHttpClient(Uri managementUri)
-            : base(managementUri, ApiVersion.Version20190130, new ErrorDetectionStrategy())
+            : this(managementUri, Option.None<TimeSpan>())
+        {
+        }
+
+        internal ModuleManagementHttpClient(Uri managementUri, Option<TimeSpan> operationTimeout)
+            : base(managementUri, ApiVersion.Version20190130, new ErrorDetectionStrategy(), operationTimeout)
         {
         }
 
@@ -198,7 +204,8 @@ protected override void HandleException(Exception exception, string operation)
                     }
 
                 default:
-                    throw exception;
+                    ExceptionDispatchInfo.Capture(exception).Throw();
+                    break;
             }
         }
 

diff --git a/...rosoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs b/...rosoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs
@@ -14,16 +14,24 @@ namespace Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning
 
     abstract class ModuleManagementHttpClientVersioned
     {
+        static readonly TimeSpan DefaultOperationTimeout = TimeSpan.FromMinutes(5);
+
         static readonly RetryStrategy TransientRetryStrategy =
             new ExponentialBackoff(retryCount: 3, minBackoff: TimeSpan.FromSeconds(2), maxBackoff: TimeSpan.FromSeconds(30), deltaBackoff: TimeSpan.FromSeconds(3));
 
         readonly ITransientErrorDetectionStrategy transientErrorDetectionStrategy;
+        readonly TimeSpan operationTimeout;
 
-        protected ModuleManagementHttpClientVersioned(Uri managementUri, ApiVersion version, ITransientErrorDetectionStrategy transientErrorDetectionStrategy)
+        protected ModuleManagementHttpClientVersioned(
+            Uri managementUri,
+            ApiVersion version,
+            ITransientErrorDetectionStrategy transientErrorDetectionStrategy,
+            Option<TimeSpan> operationTimeout)
         {
             this.ManagementUri = Preconditions.CheckNotNull(managementUri, nameof(managementUri));
             this.Version = Preconditions.CheckNotNull(version, nameof(version));
             this.transientErrorDetectionStrategy = transientErrorDetectionStrategy;
+            this.operationTimeout = operationTimeout.GetOrElse(DefaultOperationTimeout);
         }
 
         protected Uri ManagementUri { get; }
@@ -69,19 +77,20 @@ protected Task Execute(Func<Task> func, string operation) =>
                 },
                 operation);
 
-        protected async Task<T> Execute<T>(Func<Task<T>> func, string operation)
+        protected internal async Task<T> Execute<T>(Func<Task<T>> func, string operation)
         {
             try
             {
                 Events.ExecutingOperation(operation, this.ManagementUri.ToString());
-                T result = await ExecuteWithRetry(func, r => Events.RetryingOperation(operation, this.ManagementUri.ToString(), r), this.transientErrorDetectionStrategy);
+                T result = await ExecuteWithRetry(func, r => Events.RetryingOperation(operation, this.ManagementUri.ToString(), r), this.transientErrorDetectionStrategy)
+                    .TimeoutAfter(this.operationTimeout);
                 Events.SuccessfullyExecutedOperation(operation, this.ManagementUri.ToString());
                 return result;
             }
             catch (Exception ex)
             {
+                Events.ErrorExecutingOperation(ex, operation, this.ManagementUri.ToString());
                 this.HandleException(ex, operation);
-                Events.SuccessfullyExecutedOperation(operation, this.ManagementUri.ToString());
                 return default(T);
             }
         }
@@ -102,7 +111,13 @@ enum EventIds
             {
                 ExecutingOperation = IdStart,
                 SuccessfullyExecutedOperation,
-                RetryingOperation
+                RetryingOperation,
+                ErrorExecutingOperation
+            }
+
+            public static void ErrorExecutingOperation(Exception ex, string operation, string url)
+            {
+                Log.LogDebug((int)EventIds.ErrorExecutingOperation, ex, $"Error when getting an Http response from {url} for {operation}");
             }
 
             internal static void RetryingOperation(string operation, string url, RetryingEventArgs r)

diff --git a/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Service/Program.cs b/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Service/Program.cs
@@ -21,6 +21,7 @@ public class Program
         const string EdgeAgentStorageFolder = "edgeAgent";
         const string VersionInfoFileName = "versionInfo.json";
         static readonly TimeSpan ShutdownWaitPeriod = TimeSpan.FromMinutes(1);
+        static readonly TimeSpan ReconcileTimeout = TimeSpan.FromMinutes(10);
 
         public static int Main()
         {
@@ -164,7 +165,7 @@ public static async Task<int> MainAsync(IConfiguration configuration)
                     {
                         try
                         {
-                            await agent.ReconcileAsync(cts.Token);
+                            await agent.ReconcileAsync(cts.Token).TimeoutAfter(ReconcileTimeout);
                         }
                         catch (Exception ex) when (!ex.IsFatal())
                         {

diff --git a/...nt/test/Microsoft.Azure.Devices.Edge.Agent.Edgelet.Test/ModuleManagementHttpClientTest.cs b/...nt/test/Microsoft.Azure.Devices.Edge.Agent.Edgelet.Test/ModuleManagementHttpClientTest.cs
@@ -10,6 +10,7 @@ namespace Microsoft.Azure.Devices.Edge.Agent.Edgelet.Test
     using Microsoft.Azure.Devices.Edge.Agent.Core;
     using Microsoft.Azure.Devices.Edge.Agent.Core.Test;
     using Microsoft.Azure.Devices.Edge.Agent.Edgelet.Models;
+    using Microsoft.Azure.Devices.Edge.Util;
     using Microsoft.Azure.Devices.Edge.Util.Test.Common;
     using Newtonsoft.Json.Linq;
     using Xunit;
@@ -238,5 +239,45 @@ public async Task Test_PrepareUpdate_ShouldSucceed(string serverApiVersion, stri
             IModuleManager client = new ModuleManagementHttpClient(this.serverUrl, serverApiVersion, clientApiVersion);
             await client.PrepareUpdateAsync(moduleSpec);
         }
+
+        [Fact]
+        public async Task ExecuteTimeoutTest_Version_2018_06_28()
+        {
+            // Arrange
+            var client = new Version_2018_06_28.ModuleManagementHttpClient(this.serverUrl, Option.Some(TimeSpan.FromSeconds(10)));
+
+            async Task<int> LongOperation()
+            {
+                await Task.Delay(TimeSpan.FromHours(1));
+                return 10;
+            }
+
+            // Act
+            Task assertTask = Assert.ThrowsAsync<TimeoutException>(() => client.Execute<int>(LongOperation, "Dummy"));
+            Task delayTask = Task.Delay(TimeSpan.FromSeconds(20));
+
+            Task completedTask = await Task.WhenAny(assertTask, delayTask);
+            Assert.Equal(assertTask, completedTask);
+        }
+
+        [Fact]
+        public async Task ExecuteTimeoutTest_Version_2019_01_30()
+        {
+            // Arrange
+            var client = new Version_2019_01_30.ModuleManagementHttpClient(this.serverUrl, Option.Some(TimeSpan.FromSeconds(10)));
+
+            async Task<int> LongOperation()
+            {
+                await Task.Delay(TimeSpan.FromHours(1));
+                return 10;
+            }
+
+            // Act
+            Task assertTask = Assert.ThrowsAsync<TimeoutException>(() => client.Execute<int>(LongOperation, "Dummy"));
+            Task delayTask = Task.Delay(TimeSpan.FromSeconds(20));
+
+            Task completedTask = await Task.WhenAny(assertTask, delayTask);
+            Assert.Equal(assertTask, completedTask);
+        }
     }
 }
diff --git a/edge-util/src/Microsoft.Azure.Devices.Edge.Util/PeriodicTask.cs b/edge-util/src/Microsoft.Azure.Devices.Edge.Util/PeriodicTask.cs
@@ -97,7 +97,7 @@ async Task DoWork()
                     await Task.Delay(this.frequency, cancellationToken);
                 }
 
-                this.logger.LogDebug($"Periodic operation {this.operationName} cancelled");
+                this.logger.LogWarning($"Periodic operation {this.operationName} cancelled");
             }
             catch (Exception ex)
             {

diff --git a/edge-util/test/Microsoft.Azure.Devices.Edge.Util.Test/TaskExTest.cs b/edge-util/test/Microsoft.Azure.Devices.Edge.Util.Test/TaskExTest.cs
@@ -170,5 +170,35 @@ async Task<int> TestFunc(CancellationToken _)
             Func<CancellationToken, Task> testCode = c => operation.TimeoutAfter(cts.Token, TimeSpan.FromSeconds(3));
             await Assert.ThrowsAsync<TimeoutException>(() => testCode(cts.Token));
         }
+
+        [Fact]
+        [Unit]
+        public async Task TimeoutAfterTest()
+        {
+            Task longTask = Task.Delay(TimeSpan.FromHours(1));
+
+            Task assertTask = Assert.ThrowsAsync<TimeoutException>(() => longTask.TimeoutAfter(TimeSpan.FromSeconds(10)));
+            Task delayTask = Task.Delay(TimeSpan.FromSeconds(20));
+
+            Task completedTask = await Task.WhenAny(assertTask, delayTask);
+            Assert.Equal(assertTask, completedTask);
+        }
+
+        [Fact]
+        [Unit]
+        public async Task TimeoutAfterTest2()
+        {
+            Task<int> longTask = Task.Run(async () =>
+            {
+                await Task.Delay(TimeSpan.FromHours(1));
+                return 10;
+            });
+
+            Task assertTask = Assert.ThrowsAsync<TimeoutException>(() => longTask.TimeoutAfter(TimeSpan.FromSeconds(10)));
+            Task delayTask = Task.Delay(TimeSpan.FromSeconds(20));
+
+            Task completedTask = await Task.WhenAny(assertTask, delayTask);
+            Assert.Equal(assertTask, completedTask);
+        }
     }
 }