From d3edde50c002dd0e7622dee5dc8a6faca917a989 Mon Sep 17 00:00:00 2001 From: Shyju Krishnankutty Date: Tue, 25 Jun 2024 16:07:55 -0700 Subject: [PATCH 1/5] Adding a timeout to IFunctionProvider.GetFunctionMetadataAsync so that if a provider does not return, it will not cause a deadlock state. --- .../Environment/EnvironmentSettingNames.cs | 1 + .../Host/FunctionMetadataManager.cs | 44 ++++++++++++++++--- .../FunctionMetadataManagerTests.cs | 44 +++++++++++++++++++ 3 files changed, 82 insertions(+), 7 deletions(-) diff --git a/src/WebJobs.Script/Environment/EnvironmentSettingNames.cs b/src/WebJobs.Script/Environment/EnvironmentSettingNames.cs index 041a28c4fa..d2e6b891af 100644 --- a/src/WebJobs.Script/Environment/EnvironmentSettingNames.cs +++ b/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"; diff --git a/src/WebJobs.Script/Host/FunctionMetadataManager.cs b/src/WebJobs.Script/Host/FunctionMetadataManager.cs index a95ca6831e..45325e54f8 100644 --- a/src/WebJobs.Script/Host/FunctionMetadataManager.cs +++ b/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 /// /// Forces reload from all providers. /// Apply functions allow list filter. - /// Include any metadata provided by IFunctionProvider when loading the metadata + /// Include any metadata provided by IFunctionProvider when loading the metadata. /// An Immutable array of FunctionMetadata. public ImmutableArray GetFunctionMetadata(bool forceRefresh, bool applyAllowList = true, bool includeCustomProviders = true, IList 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 private void AddMetadataFromCustomProviders(IEnumerable functionProviders, List functionMetadataList) { - _logger.ReadingFunctionMetadataFromProvider(_metadataProviderName); + _logger.ReadingFunctionMetadataFromProvider(MetadataProviderName); var functionProviderTasks = new List>>(); + + 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.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.Empty; + }); + + functionProviderTasks.Add(completedTask); } var providerFunctionMetadataResults = Task.WhenAll(functionProviderTasks).GetAwaiter().GetResult(); @@ -228,7 +258,7 @@ private void AddMetadataFromCustomProviders(IEnumerable funct // This is used to make sure no duplicates are registered var distinctFunctionNames = new HashSet(functionMetadataList.Select(m => m.Name)); - _logger.FunctionsReturnedByProvider(totalFunctionsCount, _metadataProviderName); + _logger.FunctionsReturnedByProvider(totalFunctionsCount, MetadataProviderName); foreach (var metadataArray in providerFunctionMetadataResults) { diff --git a/test/WebJobs.Script.Tests/FunctionMetadataManagerTests.cs b/test/WebJobs.Script.Tests/FunctionMetadataManagerTests.cs index e1260162c9..e6e46c84e1 100644 --- a/test/WebJobs.Script.Tests/FunctionMetadataManagerTests.cs +++ b/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(); + var mockFunctionErrors = new Dictionary>(); + var mockFunctionMetadataProvider = new Mock(); + var badFunctionMetadataProvider = new Mock(); + var goodFunctionMetadataProvider = new Mock(); + 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().ToImmutableArray())); + mockFunctionMetadataProvider.Setup(m => m.FunctionErrors).Returns(new Dictionary>().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>(); + badFunctionMetadataProvider.Setup(m => m.GetFunctionMetadataAsync()).Returns(tcs.Task); + + FunctionMetadataManager testFunctionMetadataManager = TestFunctionMetadataManager.GetFunctionMetadataManager(new OptionsWrapper(_scriptJobHostOptions), + mockFunctionMetadataProvider.Object, new List() { goodFunctionMetadataProvider.Object, badFunctionMetadataProvider.Object }, new OptionsWrapper(_defaultHttpWorkerOptions), loggerFactory, new TestOptionsMonitor(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() { From f2d7a4c855fe0fd09e956dbd2cabc61258765210 Mon Sep 17 00:00:00 2001 From: Shyju Krishnankutty Date: Tue, 25 Jun 2024 16:11:42 -0700 Subject: [PATCH 2/5] Adding release notes. --- release_notes.md | 1 + 1 file changed, 1 insertion(+) diff --git a/release_notes.md b/release_notes.md index 01dde680c4..4a120028ce 100644 --- a/release_notes.md +++ b/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) From cfc773a1382c8dd2328e78791b7061cdb200cbe0 Mon Sep 17 00:00:00 2001 From: Shyju Krishnankutty Date: Thu, 27 Jun 2024 09:44:36 -0700 Subject: [PATCH 3/5] Added a new internal property `MetadataProviderTimeoutInSeconds` which can be set to a different value than default, from the tests. --- .../Environment/EnvironmentSettingNames.cs | 1 - src/WebJobs.Script/Host/FunctionMetadataManager.cs | 9 +++------ .../WebJobs.Script.Tests/FunctionMetadataManagerTests.cs | 2 +- 3 files changed, 4 insertions(+), 8 deletions(-) diff --git a/src/WebJobs.Script/Environment/EnvironmentSettingNames.cs b/src/WebJobs.Script/Environment/EnvironmentSettingNames.cs index d2e6b891af..041a28c4fa 100644 --- a/src/WebJobs.Script/Environment/EnvironmentSettingNames.cs +++ b/src/WebJobs.Script/Environment/EnvironmentSettingNames.cs @@ -34,7 +34,6 @@ 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"; diff --git a/src/WebJobs.Script/Host/FunctionMetadataManager.cs b/src/WebJobs.Script/Host/FunctionMetadataManager.cs index 45325e54f8..4a301f4469 100644 --- a/src/WebJobs.Script/Host/FunctionMetadataManager.cs +++ b/src/WebJobs.Script/Host/FunctionMetadataManager.cs @@ -57,6 +57,8 @@ public FunctionMetadataManager(IOptions scriptOptions, IFu }; } + internal int MetadataProviderTimeoutInSeconds { get; set; } = DefaultMetadataProviderTimeoutInSeconds; + public ImmutableDictionary> Errors { get; private set; } public bool TryGetFunctionMetadata(string functionName, out FunctionMetadata functionMetadata, bool forceRefresh) @@ -219,15 +221,10 @@ private void AddMetadataFromCustomProviders(IEnumerable funct var functionProviderTasks = new List>>(); - if (!int.TryParse(_environment.GetEnvironmentVariable(EnvironmentSettingNames.MetadataProviderTimeoutInSeconds), out int metadataProviderTimeoutInSeconds)) - { - metadataProviderTimeoutInSeconds = DefaultMetadataProviderTimeoutInSeconds; - } - foreach (var functionProvider in functionProviders) { var getFunctionMetadataFromProviderTask = functionProvider.GetFunctionMetadataAsync(); - Task delayTask = Task.Delay(TimeSpan.FromSeconds(metadataProviderTimeoutInSeconds)); + var delayTask = Task.Delay(TimeSpan.FromSeconds(MetadataProviderTimeoutInSeconds)); var completedTask = Task.WhenAny(getFunctionMetadataFromProviderTask, delayTask).ContinueWith(t => { diff --git a/test/WebJobs.Script.Tests/FunctionMetadataManagerTests.cs b/test/WebJobs.Script.Tests/FunctionMetadataManagerTests.cs index e6e46c84e1..fe3916acc1 100644 --- a/test/WebJobs.Script.Tests/FunctionMetadataManagerTests.cs +++ b/test/WebJobs.Script.Tests/FunctionMetadataManagerTests.cs @@ -216,7 +216,7 @@ public void FunctionMetadataManager_HandlesTimeoutsGracefully_WhenFunctionProvid mockFunctionMetadataProvider.Object, new List() { goodFunctionMetadataProvider.Object, badFunctionMetadataProvider.Object }, new OptionsWrapper(_defaultHttpWorkerOptions), loggerFactory, new TestOptionsMonitor(TestHelpers.GetTestLanguageWorkerOptions())); // Set the timeout to 1 second for the test. - SystemEnvironment.Instance.SetEnvironmentVariable(EnvironmentSettingNames.MetadataProviderTimeoutInSeconds, "1"); + testFunctionMetadataManager.MetadataProviderTimeoutInSeconds = 1; // Run LoadFunctionMetadata in a separate Task to avoid blocking the test thread var loadFunctionMetadataTask = Task.Run(() => testFunctionMetadataManager.LoadFunctionMetadata()); From f66cd983c09bfd5ca94b17fe8bac7bc942beb1a5 Mon Sep 17 00:00:00 2001 From: Shyju Krishnankutty Date: Thu, 27 Jun 2024 10:16:49 -0700 Subject: [PATCH 4/5] Added comment about property being settable. --- src/WebJobs.Script/Host/FunctionMetadataManager.cs | 1 + 1 file changed, 1 insertion(+) diff --git a/src/WebJobs.Script/Host/FunctionMetadataManager.cs b/src/WebJobs.Script/Host/FunctionMetadataManager.cs index 4a301f4469..b20972fdf0 100644 --- a/src/WebJobs.Script/Host/FunctionMetadataManager.cs +++ b/src/WebJobs.Script/Host/FunctionMetadataManager.cs @@ -57,6 +57,7 @@ public FunctionMetadataManager(IOptions scriptOptions, IFu }; } + // Property is settable for testing purposes. internal int MetadataProviderTimeoutInSeconds { get; set; } = DefaultMetadataProviderTimeoutInSeconds; public ImmutableDictionary> Errors { get; private set; } From 8b021b32da9467eb9946c8fb3ff322d817bae03b Mon Sep 17 00:00:00 2001 From: Shyju Krishnankutty Date: Mon, 1 Jul 2024 16:10:02 -0700 Subject: [PATCH 5/5] PR feedback fixes. Throws an error when the function metadata provider method throws or when the operation timeseout. --- release_notes.md | 2 +- .../Host/FunctionMetadataManager.cs | 19 ++----- .../FunctionMetadataManagerTests.cs | 57 +++++++++++++++---- 3 files changed, 52 insertions(+), 26 deletions(-) diff --git a/release_notes.md b/release_notes.md index 4a120028ce..a89c9a097b 100644 --- a/release_notes.md +++ b/release_notes.md @@ -17,4 +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) +- Adding a timeout when retrieving function metadata from metadata providers (#10219) diff --git a/src/WebJobs.Script/Host/FunctionMetadataManager.cs b/src/WebJobs.Script/Host/FunctionMetadataManager.cs index b20972fdf0..099ad7e6b1 100644 --- a/src/WebJobs.Script/Host/FunctionMetadataManager.cs +++ b/src/WebJobs.Script/Host/FunctionMetadataManager.cs @@ -229,22 +229,13 @@ private void AddMetadataFromCustomProviders(IEnumerable funct var completedTask = Task.WhenAny(getFunctionMetadataFromProviderTask, delayTask).ContinueWith(t => { - if (t.Result == getFunctionMetadataFromProviderTask) + if (t.Result == getFunctionMetadataFromProviderTask && getFunctionMetadataFromProviderTask.IsCompletedSuccessfully) { - 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.Empty; - } - else if (getFunctionMetadataFromProviderTask.IsCompletedSuccessfully) - { - return getFunctionMetadataFromProviderTask.Result; - } + 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.Empty; + + // 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); diff --git a/test/WebJobs.Script.Tests/FunctionMetadataManagerTests.cs b/test/WebJobs.Script.Tests/FunctionMetadataManagerTests.cs index fe3916acc1..49e0d9a5e8 100644 --- a/test/WebJobs.Script.Tests/FunctionMetadataManagerTests.cs +++ b/test/WebJobs.Script.Tests/FunctionMetadataManagerTests.cs @@ -188,7 +188,43 @@ public void FunctionMetadataManager_GetsMetadata_FromMultipleFunctionProviders_S } [Fact] - public void FunctionMetadataManager_HandlesTimeoutsGracefully_WhenFunctionProvidersDoNotRespond() + public void FunctionMetadataManager_LoadFunctionMetadata_Throws_WhenFunctionProviderThrows() + { + var functionMetadataCollection = new Collection(); + var mockFunctionErrors = new Dictionary>(); + var mockFunctionMetadataProvider = new Mock(); + var badFunctionMetadataProvider = new Mock(); + var goodFunctionMetadataProvider = new Mock(); + 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().ToImmutableArray())); + mockFunctionMetadataProvider.Setup(m => m.FunctionErrors).Returns(new Dictionary>().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>(); + badFunctionMetadataProvider.Setup(m => m.GetFunctionMetadataAsync()).Throws(new IOException("There was a custom IO error")); + + FunctionMetadataManager testFunctionMetadataManager = TestFunctionMetadataManager.GetFunctionMetadataManager(new OptionsWrapper(_scriptJobHostOptions), + mockFunctionMetadataProvider.Object, new List() { goodFunctionMetadataProvider.Object, badFunctionMetadataProvider.Object }, new OptionsWrapper(_defaultHttpWorkerOptions), loggerFactory, new TestOptionsMonitor(TestHelpers.GetTestLanguageWorkerOptions())); + + var exception = Assert.Throws(() => 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(); var mockFunctionErrors = new Dictionary>(); @@ -210,7 +246,11 @@ public void FunctionMetadataManager_HandlesTimeoutsGracefully_WhenFunctionProvid // A bad provider that will never return anything. var tcs = new TaskCompletionSource>(); - badFunctionMetadataProvider.Setup(m => m.GetFunctionMetadataAsync()).Returns(tcs.Task); + badFunctionMetadataProvider.Setup(m => m.GetFunctionMetadataAsync()).Returns(async () => + { + await Task.Delay(TimeSpan.FromSeconds(2)); // Simulate a delay longer than the timeout + return ImmutableArray.Empty; + }); FunctionMetadataManager testFunctionMetadataManager = TestFunctionMetadataManager.GetFunctionMetadataManager(new OptionsWrapper(_scriptJobHostOptions), mockFunctionMetadataProvider.Object, new List() { goodFunctionMetadataProvider.Object, badFunctionMetadataProvider.Object }, new OptionsWrapper(_defaultHttpWorkerOptions), loggerFactory, new TestOptionsMonitor(TestHelpers.GetTestLanguageWorkerOptions())); @@ -218,17 +258,12 @@ public void FunctionMetadataManager_HandlesTimeoutsGracefully_WhenFunctionProvid // Set the timeout to 1 second for the test. testFunctionMetadataManager.MetadataProviderTimeoutInSeconds = 1; - // Run LoadFunctionMetadata in a separate Task to avoid blocking the test thread - var loadFunctionMetadataTask = Task.Run(() => testFunctionMetadataManager.LoadFunctionMetadata()); + var exception = Assert.Throws(() => 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); - // 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}'")); + Assert.Single(traces, t => t.FormattedMessage.Contains("Reading functions metadata (Custom)")); + Assert.DoesNotContain(traces, t => t.FormattedMessage.Contains("2 functions found (Custom)")); } [Fact]