Adding a timeout to IFunctionProvider.GetFunctionMetadataAsync

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 to `GetFunctionMetadataAsync` to prevent deadlocks (#10219)

src/WebJobs.Script/Environment/EnvironmentSettingNames.cs

@@ -34,6 +34,7 @@ public static class EnvironmentSettingNames
  public const string AppInsightsAgent = "APPLICATIONINSIGHTS_ENABLE_AGENT";
  public const string FunctionsExtensionVersion = "FUNCTIONS_EXTENSION_VERSION";
  public const string FunctionWorkerRuntime = "FUNCTIONS_WORKER_RUNTIME";
+ public const string MetadataProviderTimeoutInSeconds = "METADATA_PROVIDER_TIMEOUT_IN_SECONDS";
  public const string ContainerName = "CONTAINER_NAME";
  public const string WebsitePodName = "WEBSITE_POD_NAME";
  public const string LegionServiceHost = "LEGION_SERVICE_HOST";

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;
@@ -79,7 +80,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 +189,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 +215,41 @@ 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>>>();
+
+ if (!int.TryParse(_environment.GetEnvironmentVariable(EnvironmentSettingNames.MetadataProviderTimeoutInSeconds), out int metadataProviderTimeoutInSeconds))
+ {
+ metadataProviderTimeoutInSeconds = DefaultMetadataProviderTimeoutInSeconds;
+ }
+
  foreach (var functionProvider in functionProviders)
  {
- functionProviderTasks.Add(functionProvider.GetFunctionMetadataAsync());
+ var getFunctionMetadataFromProviderTask = functionProvider.GetFunctionMetadataAsync();
+ Task delayTask = Task.Delay(TimeSpan.FromSeconds(metadataProviderTimeoutInSeconds));
+
+ var completedTask = Task.WhenAny(getFunctionMetadataFromProviderTask, delayTask).ContinueWith(t =>
+ {
+ if (t.Result == getFunctionMetadataFromProviderTask)
+ {
+ if (getFunctionMetadataFromProviderTask.IsFaulted)
+ {
+ // Task completed but with an error
+ _logger.LogWarning($"Failure in retrieving metadata from '{functionProvider.GetType().FullName}': {getFunctionMetadataFromProviderTask.Exception?.Flatten().ToString()}");
+ return ImmutableArray<FunctionMetadata>.Empty;
+ }
+ else if (getFunctionMetadataFromProviderTask.IsCompletedSuccessfully)
+ {
+ return getFunctionMetadataFromProviderTask.Result;
+ }
+ }
+ // Timeout case. getFunctionMetadataFromProviderTask was not the one that completed
+ _logger.LogWarning($"Timeout or failure in retrieving metadata from '{functionProvider.GetType().FullName}'.");
+ return ImmutableArray<FunctionMetadata>.Empty;
+ });
+
+ functionProviderTasks.Add(completedTask);
  }
 
  var providerFunctionMetadataResults = Task.WhenAll(functionProviderTasks).GetAwaiter().GetResult();
@@ -228,7 +258,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,50 @@ public void FunctionMetadataManager_GetsMetadata_FromMultipleFunctionProviders_S
  Assert.Single(traces.Where(t => t.FormattedMessage.Contains($"{expectedTotalFunctionsCount} functions found (Custom)")));
  }
 
+ [Fact]
+ public void FunctionMetadataManager_HandlesTimeoutsGracefully_WhenFunctionProvidersDoNotRespond()
+ {
+ 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(tcs.Task);
+
+ 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.
+ SystemEnvironment.Instance.SetEnvironmentVariable(EnvironmentSettingNames.MetadataProviderTimeoutInSeconds, "1");
+
+ // Run LoadFunctionMetadata in a separate Task to avoid blocking the test thread
+ var loadFunctionMetadataTask = Task.Run(() => testFunctionMetadataManager.LoadFunctionMetadata());
+
+ // wait couple of seconds.
+ loadFunctionMetadataTask.Wait(TimeSpan.FromSeconds(3));
+ var traces = testLoggerProvider.GetAllLogMessages();
+ Assert.Equal(1, traces.Count(t => t.FormattedMessage.Contains("Reading functions metadata (Custom)")));
+ // We should see log entry for the good provider.
+ Assert.Contains(traces, t => t.FormattedMessage.Contains("2 functions found (Custom)"));
+ // We should see an error log entry for the bad provider.
+ Assert.Contains(traces, t => t.FormattedMessage.Contains($"Timeout or failure in retrieving metadata from '{badFunctionMetadataProvider.Object.GetType().FullName}'"));
+ }
+
  [Fact]
  public void FunctionMetadataManager_GetsMetadata_FromFunctionProviders()
  {