fixing startup deadlock (#11142)

Author: brettsam

release_notes.md

@@ -5,3 +5,4 @@
 -->
 - Adding activity sources for Durable and WebJobs (Kafka and RabbitMQ) (#11137)
 - Add JitTrace Files for v4.1041
+- Fix startup deadlock on transient exceptions (#11142)

src/WebJobs.Script/Host/WorkerFunctionMetadataProvider.cs

@@ -11,14 +11,16 @@
 using Microsoft.Azure.WebJobs.Script.Description;
 using Microsoft.Azure.WebJobs.Script.Diagnostics.Extensions;
 using Microsoft.Azure.WebJobs.Script.Workers.Rpc;
+using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Hosting;
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 using Newtonsoft.Json;
 using Newtonsoft.Json.Linq;
 
 namespace Microsoft.Azure.WebJobs.Script
 {
-    internal class WorkerFunctionMetadataProvider : IWorkerFunctionMetadataProvider
+    internal class WorkerFunctionMetadataProvider : IWorkerFunctionMetadataProvider, IDisposable
     {
         private const string _metadataProviderName = "Worker";
         private readonly Dictionary<string, ICollection<string>> _functionErrors = new Dictionary<string, ICollection<string>>();
@@ -30,6 +32,7 @@ internal class WorkerFunctionMetadataProvider : IWorkerFunctionMetadataProvider
         private readonly JsonSerializerSettings _dateTimeSerializerSettings;
         private string _workerRuntime;
         private ImmutableArray<FunctionMetadata> _functions;
+        private IHost _currentJobHost = null;
 
         public WorkerFunctionMetadataProvider(
             IOptionsMonitor<ScriptApplicationHostOptions> scriptOptions,
@@ -45,6 +48,8 @@ public WorkerFunctionMetadataProvider(
             _scriptHostManager = scriptHostManager;
             _workerRuntime = _environment.GetEnvironmentVariable(EnvironmentSettingNames.FunctionWorkerRuntime);
             _dateTimeSerializerSettings = new JsonSerializerSettings { DateParseHandling = DateParseHandling.None };
+
+            _scriptHostManager.ActiveHostChanged += OnHostChanged;
         }
 
         public ImmutableDictionary<string, ImmutableArray<string>> FunctionErrors
@@ -83,19 +88,14 @@ public async Task<FunctionMetadataResult> GetFunctionMetadataAsync(IEnumerable<R
                 // Start up GRPC channels if they are not already running.
                 if (channels?.Any() != true)
                 {
-                    if (_scriptHostManager.State is ScriptHostState.Default
-                        || _scriptHostManager.State is ScriptHostState.Starting
-                        || _scriptHostManager.State is ScriptHostState.Initialized)
+                    if (IsJobHostStarting())
                     {
-                        // We don't need to restart if the host hasn't even been created yet.
-                        _logger.LogDebug("Host is starting up, initializing language worker channel");
+                        _logger.LogDebug("JobHost is starting with state '{State}'. Initializing worker channel.", _scriptHostManager.State);
                         await _channelManager.InitializeChannelAsync(workerConfigs, _workerRuntime);
                     }
                     else
                     {
-                        // During the restart flow, GetFunctionMetadataAsync gets invoked
-                        // again through a new script host initialization flow.
-                        _logger.LogDebug("Host is running without any initialized channels, restarting the JobHost.");
+                        _logger.LogDebug("JobHost has started and has state '{State}' without any worker channels. Restarting host to reinitialize.", _scriptHostManager.State);
                         await _scriptHostManager.RestartHostAsync();
                     }
 
@@ -149,6 +149,38 @@ public async Task<FunctionMetadataResult> GetFunctionMetadataAsync(IEnumerable<R
             return new FunctionMetadataResult(useDefaultMetadataIndexing: false, _functions);
         }
 
+        private void OnHostChanged(object sender, ActiveHostChangedEventArgs args)
+        {
+            // Track the current host so we can get state later if needed.
+            _currentJobHost = args.NewHost;
+        }
+
+        private bool IsJobHostStarting()
+        {
+            if (_scriptHostManager.State is ScriptHostState.Default
+                || _scriptHostManager.State is ScriptHostState.Starting
+                || _scriptHostManager.State is ScriptHostState.Initialized)
+            {
+                return true;
+            }
+
+            // The Error state can occur when the host is in a "final" state after completely starting,
+            // or during a retry of a transient error. This check allows us to determine the difference. If
+            // the host has not completely started, it means that it is still in the process of starting.
+            if (_currentJobHost is not null && _scriptHostManager.State == ScriptHostState.Error)
+            {
+                var lifetime = _currentJobHost.Services?.GetService<IHostApplicationLifetime>();
+
+                if (lifetime is not null &&
+                    !lifetime.ApplicationStarted.IsCancellationRequested)
+                {
+                    return true;
+                }
+            }
+
+            return false;
+        }
+
         internal void ValidateFunctionAppFormat(string scriptPath, ILogger logger, IEnvironment environment, IFileSystem fileSystem = null)
         {
             fileSystem = fileSystem ?? FileUtility.Instance;
@@ -298,5 +330,10 @@ private bool IsNullOrEmpty(IEnumerable<RawFunctionMetadata> functions)
             }
             return false;
         }
+
+        public void Dispose()
+        {
+            _scriptHostManager.ActiveHostChanged -= OnHostChanged;
+        }
     }
 }

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

@@ -14,6 +14,7 @@
 using Microsoft.Azure.WebJobs.Description;
 using Microsoft.Azure.WebJobs.Host.Config;
 using Microsoft.Azure.WebJobs.Script.Scale;
+using Microsoft.Azure.WebJobs.Script.Tests.Integration.WebHostEndToEnd;
 using Microsoft.Azure.WebJobs.Script.WebHost;
 using Microsoft.Azure.WebJobs.Script.WebHost.Authentication;
 using Microsoft.Extensions.DependencyInjection;
@@ -354,23 +355,6 @@ public void Dispose()
             _testHost?.Dispose();
         }
 
-        private class InterceptingScriptHostBuilder : IScriptHostBuilder
-        {
-            private readonly DefaultScriptHostBuilder _builder;
-            private readonly Func<IScriptHostBuilder, bool, bool, IHost> _interceptCallback;
-
-            public InterceptingScriptHostBuilder(IOptionsMonitor<ScriptApplicationHostOptions> appHostOptions, IServiceProvider rootServiceProvider, IServiceCollection rootServices, Func<IScriptHostBuilder, bool, bool, IHost> interceptCallback)
-            {
-                _builder = new DefaultScriptHostBuilder(appHostOptions, rootServices, rootServiceProvider);
-                _interceptCallback = interceptCallback;
-            }
-
-            public IHost BuildHost(bool skipHostStartup, bool skipHostConfigurationParsing)
-            {
-                return _interceptCallback(_builder, skipHostStartup, skipHostConfigurationParsing);
-            }
-        }
-
         [Extension("TestWebHook", "TestWebHook")]
         private class TestWebHookExtension : IExtensionConfigProvider, IAsyncConverter<HttpRequestMessage, HttpResponseMessage>
         {

test/WebJobs.Script.Tests.Integration/WebHostEndToEnd/InterceptingScriptHostBuilder.cs

@@ -0,0 +1,24 @@
+using System;
+using Microsoft.Azure.WebJobs.Script.WebHost;
+using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Hosting;
+using Microsoft.Extensions.Options;
+
+namespace Microsoft.Azure.WebJobs.Script.Tests.Integration.WebHostEndToEnd;
+
+internal class InterceptingScriptHostBuilder : IScriptHostBuilder
+{
+    private readonly DefaultScriptHostBuilder _builder;
+    private readonly Func<IScriptHostBuilder, bool, bool, IHost> _interceptCallback;
+
+    public InterceptingScriptHostBuilder(IOptionsMonitor<ScriptApplicationHostOptions> appHostOptions, IServiceProvider rootServiceProvider, IServiceCollection rootServices, Func<IScriptHostBuilder, bool, bool, IHost> interceptCallback)
+    {
+        _builder = new DefaultScriptHostBuilder(appHostOptions, rootServices, rootServiceProvider);
+        _interceptCallback = interceptCallback;
+    }
+
+    public IHost BuildHost(bool skipHostStartup, bool skipHostConfigurationParsing)
+    {
+        return _interceptCallback(_builder, skipHostStartup, skipHostConfigurationParsing);
+    }
+}

test/WebJobs.Script.Tests.Integration/WebHostEndToEnd/WebHostStartupEndToEndTests.cs

@@ -0,0 +1,86 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using System;
+using System.Linq;
+using System.Threading.Tasks;
+using Microsoft.Azure.WebJobs.Script.WebHost;
+using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Hosting;
+using Microsoft.Extensions.Options;
+using Xunit;
+
+namespace Microsoft.Azure.WebJobs.Script.Tests.Integration.WebHostEndToEnd;
+
+public class WebHostStartupEndToEndTests
+{
+    [Fact]
+    public async Task TransientError_DuringHostBuild_DoesNotDeadlock()
+    {
+        bool thrownOnce = false;
+        void ThrowOnFirstBuild()
+        {
+            if (!thrownOnce)
+            {
+                // Simulate a transient error during first host build
+                thrownOnce = true;
+                throw new InvalidOperationException("Simulated transient error during host build.");
+            }
+        }
+
+        var fixture = new WebHostStartupEndToEndTestFixture(ThrowOnFirstBuild);
+
+        try
+        {
+            await fixture.InitializeAsync();
+
+            // This should recover as the second call to BuildHost should succeed
+            await TestHelpers.Await(async () =>
+            {
+                var result = await fixture.Host.HttpClient.GetAsync("/api/HttpRequestDataFunction");
+                return result.IsSuccessStatusCode && await result.Content.ReadAsStringAsync() == "Welcome to Azure Functions!";
+
+            }, 10000, userMessageCallback: fixture.Host.GetLog);
+
+            var debugMsg = fixture.Host.GetWebHostLogMessages("Microsoft.Azure.WebJobs.Script.WorkerFunctionMetadataProvider")
+                .Where(m => m.Level == Microsoft.Extensions.Logging.LogLevel.Debug)
+                .Where(m => m.FormattedMessage.StartsWith("JobHost is starting with state"));
+            Assert.Single(debugMsg);
+            Assert.Contains("'Error'", debugMsg.Single().FormattedMessage);
+        }
+        finally
+        {
+            await fixture.DisposeAsync();
+        }
+    }
+
+    private class WebHostStartupEndToEndTestFixture : EndToEndTestFixture
+    {
+        private readonly Action _scriptHostBuildInterceptor;
+
+        public WebHostStartupEndToEndTestFixture(Action scriptHostBuildInterceptor = null)
+            : base(@"..\..\DotNetIsolated60\debug", "WebHostStartupEndToEndTests", "dotnet-isolated")
+        {
+            _scriptHostBuildInterceptor = scriptHostBuildInterceptor;
+        }
+
+        protected override Task CreateTestStorageEntities() => Task.CompletedTask;
+
+        public override void ConfigureWebHost(IServiceCollection rootServices)
+        {
+            rootServices.AddSingleton<IScriptHostBuilder>(rootProvider =>
+            {
+                var appHostOptions = rootProvider.GetService<IOptionsMonitor<ScriptApplicationHostOptions>>();
+
+                IHost Intercept(IScriptHostBuilder builder, bool skipHostStartup, bool skipHostConfigurationParsing)
+                {
+                    _scriptHostBuildInterceptor?.Invoke();
+
+                    return builder.BuildHost(skipHostStartup, skipHostConfigurationParsing);
+                }
+
+                return new InterceptingScriptHostBuilder(appHostOptions, rootProvider, rootServices, Intercept);
+            });
+        }
+    }
+}