Adding exponential backoff to error/retry (#1162)

Author: mathewc

src/WebJobs.Script/Config/ScriptHostConfiguration.cs

@@ -18,7 +18,6 @@ public ScriptHostConfiguration()
             FileLoggingMode = FileLoggingMode.Never;
             RootScriptPath = Environment.CurrentDirectory;
             RootLogPath = Path.Combine(Path.GetTempPath(), "Functions");
-            RestartInterval = TimeSpan.FromSeconds(5);
         }
 
         /// <summary>
@@ -89,11 +88,5 @@ public ScriptHostConfiguration()
         /// there is no timeout duration.
         /// </summary>
         public TimeSpan? FunctionTimeout { get; set; }
-
-        /// <summary>
-        /// Gets or sets the restart interval to use between restart attempts
-        /// when the host is in an error state. The default is 5 seconds.
-        /// </summary>
-        public TimeSpan RestartInterval { get; set; }
     }
 }

src/WebJobs.Script/GlobalSuppressions.cs

@@ -126,4 +126,7 @@
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Naming", "CA1704:IdentifiersShouldBeSpelledCorrectly", MessageId = "Sku", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.ScriptConstants.#DynamicSku")]
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Naming", "CA1704:IdentifiersShouldBeSpelledCorrectly", MessageId = "Sku", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.Config.ScriptSettingsManager.#IsDynamicSku")]
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.ScriptHost.#Create(Microsoft.Azure.WebJobs.Script.ScriptHostConfiguration,Microsoft.Azure.WebJobs.Script.Config.ScriptSettingsManager)")]
+[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA2213:DisposableFieldsShouldBeDisposed", MessageId = "_restartDelayTokenSource", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.ScriptHostManager.#Dispose(System.Boolean)")]
+[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA2213:DisposableFieldsShouldBeDisposed", MessageId = "_scriptFileWatcher", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.ScriptHostManager.#Dispose(System.Boolean)")]
+[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Naming", "CA1704:IdentifiersShouldBeSpelledCorrectly", MessageId = "Backoff", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.Utility.#DelayWithBackoffAsync(System.Int32,System.Threading.CancellationToken,System.Nullable`1<System.TimeSpan>,System.Nullable`1<System.TimeSpan>,System.Nullable`1<System.TimeSpan>)")]
 

src/WebJobs.Script/Host/ScriptHostManager.cs

@@ -5,13 +5,15 @@
 using System.Collections.Generic;
 using System.Diagnostics;
 using System.Globalization;
+using System.IO;
 using System.Linq;
 using System.Text;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Azure.WebJobs.Host;
 using Microsoft.Azure.WebJobs.Script.Config;
 using Microsoft.Azure.WebJobs.Script.Diagnostics;
+using Microsoft.Azure.WebJobs.Script.IO;
 
 namespace Microsoft.Azure.WebJobs.Script
 {
@@ -37,10 +39,17 @@ public class ScriptHostManager : IDisposable
         private TraceWriter _traceWriter;
 
         private ScriptSettingsManager _settingsManager;
+        private AutoRecoveringFileSystemWatcher _scriptFileWatcher;
+        private CancellationTokenSource _restartDelayTokenSource;
 
         public ScriptHostManager(ScriptHostConfiguration config)
             : this(config, ScriptSettingsManager.Instance, new ScriptHostFactory())
         {
+            if (config.FileWatchingEnabled)
+            {
+                _scriptFileWatcher = new AutoRecoveringFileSystemWatcher(config.RootScriptPath);
+                _scriptFileWatcher.Changed += OnScriptFileChanged;
+            }
         }
 
         public ScriptHostManager(ScriptHostConfiguration config, ScriptSettingsManager settingsManager, IScriptHostFactory scriptHostFactory)
@@ -83,8 +92,7 @@ public bool CanInvoke()
 
         public void RunAndBlock(CancellationToken cancellationToken = default(CancellationToken))
         {
-            // Start the host and restart it if requested. Host Restarts will happen when
-            // host level configuration files change
+            int consecutiveErrorCount = 0;
             do
             {
                 ScriptHost newInstance = null;
@@ -116,8 +124,8 @@ public bool CanInvoke()
 
                     if (_traceWriter != null)
                     {
-                        string message = string.Format("Starting Host (HostId={0}, Version={1}, ProcessId={2}, Debug={3})",
-                            newInstance.ScriptConfig.HostConfig.HostId, ScriptHost.Version, Process.GetCurrentProcess().Id, newInstance.InDebugMode.ToString());
+                        string message = string.Format("Starting Host (HostId={0}, Version={1}, ProcessId={2}, Debug={3}, Attempt={4})",
+                            newInstance.ScriptConfig.HostConfig.HostId, ScriptHost.Version, Process.GetCurrentProcess().Id, newInstance.InDebugMode.ToString(), consecutiveErrorCount);
                         _traceWriter.Info(message);
                     }
                     newInstance.StartAsync(cancellationToken).GetAwaiter().GetResult();
@@ -131,6 +139,8 @@ public bool CanInvoke()
                     // state to Running
                     State = ScriptHostState.Running;
                     LastError = null;
+                    consecutiveErrorCount = 0;
+                    _restartDelayTokenSource = null;
 
                     // Wait for a restart signal. This event will automatically reset.
                     // While we're restarting, it is possible for another restart to be
@@ -155,6 +165,7 @@ public bool CanInvoke()
                 {
                     State = ScriptHostState.Error;
                     LastError = ex;
+                    consecutiveErrorCount++;
 
                     // We need to keep the host running, so we catch and log any errors
                     // then restart the host
@@ -177,15 +188,22 @@ public bool CanInvoke()
                             }, TaskContinuationOptions.ExecuteSynchronously);
                     }
 
-                    // Wait for a short period of time before restarting to
-                    // avoid cases where a host level config error might cause
-                    // a rapid restart cycle
-                    Task.Delay(_config.RestartInterval).GetAwaiter().GetResult();
+                    // attempt restarts using an exponential backoff strategy
+                    CreateRestartBackoffDelay(consecutiveErrorCount).GetAwaiter().GetResult();
                 }
             }
             while (!_stopped && !cancellationToken.IsCancellationRequested);
         }
 
+        private Task CreateRestartBackoffDelay(int consecutiveErrorCount)
+        {
+            _restartDelayTokenSource = new CancellationTokenSource();
+
+            return Utility.DelayWithBackoffAsync(consecutiveErrorCount, _restartDelayTokenSource.Token,
+                min: TimeSpan.FromSeconds(1),
+                max: TimeSpan.FromMinutes(2));
+        }
+
         private static void LogErrors(ScriptHost host)
         {
             if (host.FunctionErrors.Count > 0)
@@ -234,6 +252,19 @@ private async Task Orphan(ScriptHost instance, bool forceStop = false)
             }
         }
 
+        /// <summary>
+        /// Handler for any file changes under the root script path
+        /// </summary>
+        private void OnScriptFileChanged(object sender, FileSystemEventArgs e)
+        {
+            if (_restartDelayTokenSource != null && !_restartDelayTokenSource.IsCancellationRequested)
+            {
+                // if we're currently awaiting an error/restart delay
+                // cancel that 
+                _restartDelayTokenSource.Cancel();
+            }
+        }
+
         public async Task StopAsync()
         {
             _stopped = true;
@@ -326,6 +357,8 @@ protected virtual void Dispose(bool disposing)
                 }
 
                 _stopEvent.Dispose();
+                _restartDelayTokenSource?.Dispose();
+                _scriptFileWatcher?.Dispose();
 
                 _disposed = true;
             }

src/WebJobs.Script/IO/AutoRecoveringFileSystemWatcher.cs

@@ -131,23 +131,16 @@ private void Trace(string message, TraceLevel level)
 
         private async Task Recover(int attempt = 1)
         {
-            // Exponential backoff on retries
-            long wait = Convert.ToInt64((Math.Pow(2, attempt) - 1) / 2);
-
-            // maximum wait of 5 minutes
-            wait = Math.Min(wait, 300);
-
-            if (wait > 0)
-            {
-                Trace($"Next recovery attempt in {wait} seconds...", TraceLevel.Warning);
-                await Task.Delay(TimeSpan.FromSeconds(wait)).ConfigureAwait(false);
-            }
+            // Exponential backoff on retries with
+            // a maximum wait of 5 minutes
+            await Utility.DelayWithBackoffAsync(attempt, _cancellationToken, max: TimeSpan.FromMinutes(5));
 
             // Check if cancellation was requested while we were waiting
             _cancellationToken.ThrowIfCancellationRequested();
 
             try
             {
+                Trace($"Attempting to recover...", TraceLevel.Warning);
                 ReleaseCurrentFileWatcher();
                 InitializeWatcher();
             }

src/WebJobs.Script/Utility.cs

@@ -7,6 +7,8 @@
 using System.Globalization;
 using System.Linq;
 using System.Text;
+using System.Threading;
+using System.Threading.Tasks;
 using Microsoft.Azure.WebJobs.Script.Config;
 using Newtonsoft.Json;
 using Newtonsoft.Json.Converters;
@@ -19,6 +21,59 @@ public static class Utility
         private static readonly ExpandoObjectConverter _expandoObjectJsonConverter = new ExpandoObjectConverter();
         private static readonly string UTF8ByteOrderMark = Encoding.UTF8.GetString(Encoding.UTF8.GetPreamble());
 
+        /// <summary>
+        /// Implements a configurable exponential backoff strategy.
+        /// </summary>
+        /// <param name="exponent">The backoff exponent. E.g. for backing off in a retry loop,
+        /// this would be the retry attempt count.</param>
+        /// <param name="cancellationToken">The <see cref="CancellationToken"/> to use.</param>
+        /// <param name="unit">The time unit for the backoff delay. Default is 1 second, producing a backoff sequence
+        /// of 2, 4, 8, 16, etc. seconds.</param>
+        /// <param name="min">The minimum delay.</param>
+        /// <param name="max">The maximum delay.</param>
+        /// <returns>A <see cref="Task"/> representing the computed backoff interval.</returns>
+        public async static Task DelayWithBackoffAsync(int exponent, CancellationToken cancellationToken, TimeSpan? unit = null, TimeSpan? min = null, TimeSpan? max = null)
+        {
+            TimeSpan delay = ComputeBackoff(exponent, unit, min, max);
+
+            if (delay.TotalMilliseconds > 0)
+            {
+                try
+                {
+                    await Task.Delay(delay, cancellationToken).ConfigureAwait(false);
+                }
+                catch (OperationCanceledException)
+                {
+                    // when the delay is cancelled it is not an error
+                }
+            }
+        }
+
+        internal static TimeSpan ComputeBackoff(int exponent, TimeSpan? unit = null, TimeSpan? min = null, TimeSpan? max = null)
+        {
+            // determine the exponential backoff factor
+            long backoffFactor = Convert.ToInt64((Math.Pow(2, exponent) - 1) / 2);
+
+            // compute the backoff delay
+            unit = unit ?? TimeSpan.FromSeconds(1);
+            long totalDelayTicks = backoffFactor * unit.Value.Ticks;
+            TimeSpan delay = TimeSpan.FromTicks(totalDelayTicks);
+
+            // apply minimum restriction
+            if (min.HasValue && delay < min)
+            {
+                delay = min.Value;
+            }
+
+            // apply maximum restriction
+            if (max.HasValue && delay > max)
+            {
+                delay = max.Value;
+            }
+
+            return delay;
+        }
+
         public static string GetSubscriptionId()
         {
             string ownerName = ScriptSettingsManager.Instance.GetSetting(EnvironmentSettingNames.AzureWebsiteOwnerName) ?? string.Empty;

test/WebJobs.Script.Tests.Integration/Host/ScriptHostManagerTests.cs

@@ -2,6 +2,7 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Diagnostics;
 using System.IO;
 using System.Linq;
 using System.Runtime.ExceptionServices;

test/WebJobs.Script.Tests.Integration/Host/WebScriptHostManagerTests.cs

@@ -148,7 +148,6 @@ public async Task MultipleHostRestarts()
                 RootLogPath = logDir,
                 RootScriptPath = functionTestDir,
                 FileLoggingMode = FileLoggingMode.Always,
-                RestartInterval = TimeSpan.FromMilliseconds(500)
             };
 
             ISecretsRepository repository = new FileSystemSecretsRepository(secretsDir);
@@ -357,7 +356,7 @@ public Fixture()
                     "Info Host lock lease acquired by instance ID '(.+)'",
                     "Info Function 'Excluded' is marked as excluded",
                     @"Info Generating ([0-9]+) job function\(s\)",
-                    @"Info Starting Host \(HostId=function-tests-node, Version=(.+), ProcessId=[0-9]+, Debug=False\)",
+                    @"Info Starting Host \(HostId=function-tests-node, Version=(.+), ProcessId=[0-9]+, Debug=False, Attempt=0\)",
                     "Info WebJobs.Indexing Found the following functions:",
                     "Info The next 5 occurrences of the schedule will be:",
                     "Info WebJobs.Host Job host started",

test/WebJobs.Script.Tests/IO/AutoRecoveringFileSystemWatcherTests.cs

@@ -83,8 +83,15 @@ public async Task RecoveryTest(int expectedNumberOfAttempts, bool isFailureScena
                 int expectedTracesBeforeRecovery = (expectedNumberOfAttempts * 2) - 1;
                 // Before + recovery trace
                 int expectedTracesAfterRecovery = expectedTracesBeforeRecovery + 1;
+                if (!isFailureScenario)
+                {
+                    expectedTracesAfterRecovery++;
+                }
 
-                await TestHelpers.Await(() => traceWriter.Traces.Count == expectedTracesBeforeRecovery, pollingInterval: 500);
+                await TestHelpers.Await(() => 
+                {
+                    return traceWriter.Traces.Count == expectedTracesBeforeRecovery;
+                }, pollingInterval: 500);
 
                 if (isFailureScenario)
                 {
@@ -95,14 +102,22 @@ public async Task RecoveryTest(int expectedNumberOfAttempts, bool isFailureScena
                     Directory.CreateDirectory(directory.Path);
                 }
 
-                await TestHelpers.Await(() => traceWriter.Traces.Count == expectedTracesAfterRecovery, pollingInterval: 500);
+                await TestHelpers.Await(() =>
+                {
+                    return traceWriter.Traces.Count == expectedTracesAfterRecovery;
+                }, pollingInterval: 500);
 
                 TraceEvent failureEvent = traceWriter.Traces.First();
                 var retryEvents = traceWriter.Traces.Where(t => t.Level == TraceLevel.Warning).Skip(1).ToList();
 
                 Assert.Equal(TraceLevel.Warning, failureEvent.Level);
                 Assert.Contains("Failure detected", failureEvent.Message);
-                Assert.Equal(expectedNumberOfAttempts - 1, retryEvents.Count);
+                int expectedRetryEvents = expectedNumberOfAttempts;
+                if (isFailureScenario)
+                {
+                    expectedRetryEvents--;
+                }
+                Assert.Equal(expectedRetryEvents, retryEvents.Count);
 
                 // Validate that our the events happened with the expected intervals
                 DateTime previoustTimeStamp = failureEvent.Timestamp;