Adding a timeout to IFunctionProvider.GetFunctionMetadataAsync (#10249)

* Adding a timeout to IFunctionProvider.GetFunctionMetadataAsync so that if a provider does not return, it will not cause a deadlock state.

* Adding release notes.

* Added a new internal property `MetadataProviderTimeoutInSeconds` which can be set to a different value than default, from the tests.

* Added comment about property being settable.

* PR feedback fixes. Throws an error when the function metadata provider method throws or when the operation timeseout.

Author: kshyju

release_notes.md

@@ -17,3 +17,4 @@
 - Ordered invocations are now the default (#10201)
 - Skip worker description if none of the profile conditions are met (#9932)
 - Fixed incorrect function count in the log message.(#10220)
+- Adding a timeout when retrieving function metadata from metadata providers (#10219)

src/WebJobs.Script/Host/FunctionMetadataManager.cs

@@ -21,8 +21,9 @@ namespace Microsoft.Azure.WebJobs.Script
 {
     public class FunctionMetadataManager : IFunctionMetadataManager
     {
-        private const string _functionConfigurationErrorMessage = "Unable to determine the primary function script.Make sure atleast one script file is present.Try renaming your entry point script to 'run' or alternatively you can specify the name of the entry point script explicitly by adding a 'scriptFile' property to your function metadata.";
-        private const string _metadataProviderName = "Custom";
+        private const string FunctionConfigurationErrorMessage = "Unable to determine the primary function script.Make sure atleast one script file is present.Try renaming your entry point script to 'run' or alternatively you can specify the name of the entry point script explicitly by adding a 'scriptFile' property to your function metadata.";
+        private const string MetadataProviderName = "Custom";
+        private const int DefaultMetadataProviderTimeoutInSeconds = 30;
         private readonly IServiceProvider _serviceProvider;
         private IFunctionMetadataProvider _functionMetadataProvider;
         private bool _isHttpWorker;
@@ -56,6 +57,9 @@ public FunctionMetadataManager(IOptions<ScriptJobHostOptions> scriptOptions, IFu
             };
         }
 
+        // Property is settable for testing purposes.
+        internal int MetadataProviderTimeoutInSeconds { get; set; } = DefaultMetadataProviderTimeoutInSeconds;
+
         public ImmutableDictionary<string, ImmutableArray<string>> Errors { get; private set; }
 
         public bool TryGetFunctionMetadata(string functionName, out FunctionMetadata functionMetadata, bool forceRefresh)
@@ -79,7 +83,7 @@ public bool TryGetFunctionMetadata(string functionName, out FunctionMetadata fun
         /// </summary>
         /// <param name="forceRefresh">Forces reload from all providers.</param>
         /// <param name="applyAllowList">Apply functions allow list filter.</param>
-        /// <param name="includeCustomProviders">Include any metadata provided by IFunctionProvider when loading the metadata</param>
+        /// <param name="includeCustomProviders">Include any metadata provided by IFunctionProvider when loading the metadata.</param>
         /// <returns> An Immutable array of FunctionMetadata.</returns>
         public ImmutableArray<FunctionMetadata> GetFunctionMetadata(bool forceRefresh, bool applyAllowList = true, bool includeCustomProviders = true, IList<RpcWorkerConfig> workerConfigs = null)
         {
@@ -188,7 +192,7 @@ internal bool IsScriptFileDetermined(FunctionMetadata functionMetadata)
             {
                 if (string.IsNullOrEmpty(functionMetadata.ScriptFile) && !_isHttpWorker && !functionMetadata.IsProxy() && _servicesReset)
                 {
-                    throw new FunctionConfigurationException(_functionConfigurationErrorMessage);
+                    throw new FunctionConfigurationException(FunctionConfigurationErrorMessage);
                 }
             }
             catch (FunctionConfigurationException exc)
@@ -214,12 +218,27 @@ private void LoadCustomProviderFunctions(List<FunctionMetadata> functionMetadata
 
         private void AddMetadataFromCustomProviders(IEnumerable<IFunctionProvider> functionProviders, List<FunctionMetadata> functionMetadataList)
         {
-            _logger.ReadingFunctionMetadataFromProvider(_metadataProviderName);
+            _logger.ReadingFunctionMetadataFromProvider(MetadataProviderName);
 
             var functionProviderTasks = new List<Task<ImmutableArray<FunctionMetadata>>>();
+
             foreach (var functionProvider in functionProviders)
             {
-                functionProviderTasks.Add(functionProvider.GetFunctionMetadataAsync());
+                var getFunctionMetadataFromProviderTask = functionProvider.GetFunctionMetadataAsync();
+                var delayTask = Task.Delay(TimeSpan.FromSeconds(MetadataProviderTimeoutInSeconds));
+
+                var completedTask = Task.WhenAny(getFunctionMetadataFromProviderTask, delayTask).ContinueWith(t =>
+                {
+                    if (t.Result == getFunctionMetadataFromProviderTask && getFunctionMetadataFromProviderTask.IsCompletedSuccessfully)
+                    {
+                        return getFunctionMetadataFromProviderTask.Result;
+                    }
+
+                    // Timeout case.
+                    throw new TimeoutException($"Timeout occurred while retrieving metadata from provider '{functionProvider.GetType().FullName}'. The operation exceeded the configured timeout of {MetadataProviderTimeoutInSeconds} seconds.");
+                });
+
+                functionProviderTasks.Add(completedTask);
             }
 
             var providerFunctionMetadataResults = Task.WhenAll(functionProviderTasks).GetAwaiter().GetResult();
@@ -228,7 +247,7 @@ private void AddMetadataFromCustomProviders(IEnumerable<IFunctionProvider> funct
             // This is used to make sure no duplicates are registered
             var distinctFunctionNames = new HashSet<string>(functionMetadataList.Select(m => m.Name));
 
-            _logger.FunctionsReturnedByProvider(totalFunctionsCount, _metadataProviderName);
+            _logger.FunctionsReturnedByProvider(totalFunctionsCount, MetadataProviderName);
 
             foreach (var metadataArray in providerFunctionMetadataResults)
             {

test/WebJobs.Script.Tests/FunctionMetadataManagerTests.cs

@@ -187,6 +187,85 @@ public void FunctionMetadataManager_GetsMetadata_FromMultipleFunctionProviders_S
             Assert.Single(traces.Where(t => t.FormattedMessage.Contains($"{expectedTotalFunctionsCount} functions found (Custom)")));
         }
 
+        [Fact]
+        public void FunctionMetadataManager_LoadFunctionMetadata_Throws_WhenFunctionProviderThrows()
+        {
+            var functionMetadataCollection = new Collection<FunctionMetadata>();
+            var mockFunctionErrors = new Dictionary<string, ImmutableArray<string>>();
+            var mockFunctionMetadataProvider = new Mock<IFunctionMetadataProvider>();
+            var badFunctionMetadataProvider = new Mock<IFunctionProvider>();
+            var goodFunctionMetadataProvider = new Mock<IFunctionProvider>();
+            var workerConfigs = TestHelpers.GetTestWorkerConfigs();
+            var testLoggerProvider = new TestLoggerProvider();
+            var loggerFactory = new LoggerFactory();
+            loggerFactory.AddProvider(testLoggerProvider);
+
+            mockFunctionMetadataProvider.Setup(m => m.GetFunctionMetadataAsync(workerConfigs, SystemEnvironment.Instance, false)).Returns(Task.FromResult(new Collection<FunctionMetadata>().ToImmutableArray()));
+            mockFunctionMetadataProvider.Setup(m => m.FunctionErrors).Returns(new Dictionary<string, ICollection<string>>().ToImmutableDictionary(kvp => kvp.Key, kvp => kvp.Value.ToImmutableArray()));
+
+            // A good provider that returns 2 functions
+            functionMetadataCollection.Add(GetTestFunctionMetadata("somefile.dll", name: "Function1"));
+            functionMetadataCollection.Add(GetTestFunctionMetadata("somefile.dll", name: "Function2"));
+            goodFunctionMetadataProvider.Setup(m => m.GetFunctionMetadataAsync()).ReturnsAsync(functionMetadataCollection.ToImmutableArray());
+
+            // A bad provider that will throw an exception for .GetFunctionMetadataAsync call.
+            var tcs = new TaskCompletionSource<ImmutableArray<FunctionMetadata>>();
+            badFunctionMetadataProvider.Setup(m => m.GetFunctionMetadataAsync()).Throws(new IOException("There was a custom IO error"));
+
+            FunctionMetadataManager testFunctionMetadataManager = TestFunctionMetadataManager.GetFunctionMetadataManager(new OptionsWrapper<ScriptJobHostOptions>(_scriptJobHostOptions),
+                mockFunctionMetadataProvider.Object, new List<IFunctionProvider>() { goodFunctionMetadataProvider.Object, badFunctionMetadataProvider.Object }, new OptionsWrapper<HttpWorkerOptions>(_defaultHttpWorkerOptions), loggerFactory, new TestOptionsMonitor<LanguageWorkerOptions>(TestHelpers.GetTestLanguageWorkerOptions()));
+
+            var exception = Assert.Throws<IOException>(() => testFunctionMetadataManager.LoadFunctionMetadata());
+            Assert.Contains($"There was a custom IO error", exception.Message);
+
+            var traces = testLoggerProvider.GetAllLogMessages();
+            Assert.Single(traces, t => t.FormattedMessage.Contains("Reading functions metadata (Custom)"));
+            Assert.DoesNotContain(traces, t => t.FormattedMessage.Contains("2 functions found (Custom)"));
+        }
+
+        [Fact]
+        public void FunctionMetadataManager_LoadFunctionMetadata_Throws_WhenFunctionProvidersTimesOut()
+        {
+            var functionMetadataCollection = new Collection<FunctionMetadata>();
+            var mockFunctionErrors = new Dictionary<string, ImmutableArray<string>>();
+            var mockFunctionMetadataProvider = new Mock<IFunctionMetadataProvider>();
+            var badFunctionMetadataProvider = new Mock<IFunctionProvider>();
+            var goodFunctionMetadataProvider = new Mock<IFunctionProvider>();
+            var workerConfigs = TestHelpers.GetTestWorkerConfigs();
+            var testLoggerProvider = new TestLoggerProvider();
+            var loggerFactory = new LoggerFactory();
+            loggerFactory.AddProvider(testLoggerProvider);
+
+            mockFunctionMetadataProvider.Setup(m => m.GetFunctionMetadataAsync(workerConfigs, SystemEnvironment.Instance, false)).Returns(Task.FromResult(new Collection<FunctionMetadata>().ToImmutableArray()));
+            mockFunctionMetadataProvider.Setup(m => m.FunctionErrors).Returns(new Dictionary<string, ICollection<string>>().ToImmutableDictionary(kvp => kvp.Key, kvp => kvp.Value.ToImmutableArray()));
+
+            // A good provider that returns 2 functions
+            functionMetadataCollection.Add(GetTestFunctionMetadata("somefile.dll", name: "Function1"));
+            functionMetadataCollection.Add(GetTestFunctionMetadata("somefile.dll", name: "Function2"));
+            goodFunctionMetadataProvider.Setup(m => m.GetFunctionMetadataAsync()).ReturnsAsync(functionMetadataCollection.ToImmutableArray());
+
+            // A bad provider that will never return anything.
+            var tcs = new TaskCompletionSource<ImmutableArray<FunctionMetadata>>();
+            badFunctionMetadataProvider.Setup(m => m.GetFunctionMetadataAsync()).Returns(async () =>
+            {
+                await Task.Delay(TimeSpan.FromSeconds(2)); // Simulate a delay longer than the timeout
+                return ImmutableArray<FunctionMetadata>.Empty;
+            });
+
+            FunctionMetadataManager testFunctionMetadataManager = TestFunctionMetadataManager.GetFunctionMetadataManager(new OptionsWrapper<ScriptJobHostOptions>(_scriptJobHostOptions),
+                mockFunctionMetadataProvider.Object, new List<IFunctionProvider>() { goodFunctionMetadataProvider.Object, badFunctionMetadataProvider.Object }, new OptionsWrapper<HttpWorkerOptions>(_defaultHttpWorkerOptions), loggerFactory, new TestOptionsMonitor<LanguageWorkerOptions>(TestHelpers.GetTestLanguageWorkerOptions()));
+
+            // Set the timeout to 1 second for the test.
+            testFunctionMetadataManager.MetadataProviderTimeoutInSeconds = 1;
+
+            var exception = Assert.Throws<TimeoutException>(() => testFunctionMetadataManager.LoadFunctionMetadata());
+            Assert.Contains($"Timeout occurred while retrieving metadata from provider '{badFunctionMetadataProvider.Object.GetType().FullName}'. The operation exceeded the configured timeout of 1 seconds.", exception.Message);
+
+            var traces = testLoggerProvider.GetAllLogMessages();
+            Assert.Single(traces, t => t.FormattedMessage.Contains("Reading functions metadata (Custom)"));
+            Assert.DoesNotContain(traces, t => t.FormattedMessage.Contains("2 functions found (Custom)"));
+        }
+
         [Fact]
         public void FunctionMetadataManager_GetsMetadata_FromFunctionProviders()
         {