[pack]Use TraceWriter to log startup errors (#5159)

Author: pragnagopa

src/WebJobs.Script.WebHost/App_Start/WebHostResolver.cs

@@ -128,69 +128,101 @@ internal void EnsureInitialized(WebHostSettings settings)
                 // Determine whether we should do normal or standby initialization
                 if (!WebScriptHostManager.InStandbyMode)
                 {
-                    // We're not in standby mode. There are two cases to consider:
-                    // 1) We _were_ in standby mode and now we're ready to specialize
-                    // 2) We're doing non-specialization normal initialization
-                    if (_activeHostManager == null && 
-                        (_standbyHostManager == null || (_settingsManager.ContainerReady && _settingsManager.ConfigurationReady)))
-                    {
-                        _specializationTimer?.Dispose();
-                        _specializationTimer = null;
+                    EncureInitializedNonStandbyMode(settings);
+                }
+                else
+                {
+                    EnsureInitializedStandbyMode(settings);
+                }
+            }
+        }
 
-                        _activeScriptHostConfig = CreateScriptHostConfiguration(settings);
-                        var defaultLoggerFactory = GetDefaultLoggerFactory(settings);
-                        _activeHostManager = new WebScriptHostManager(_activeScriptHostConfig, _secretManagerFactory, _eventManager, _settingsManager, settings, defaultLoggerFactory);
-                        _activeReceiverManager = new WebHookReceiverManager(_activeHostManager.SecretManager);
-                        InitializeFileSystem(_settingsManager.FileSystemIsReadOnly);
+        private void EnsureInitializedStandbyMode(WebHostSettings settings)
+        {
+            try
+            {
+                // We're in standby (placeholder) mode. Initialize the standby services.
+                if (_standbyHostManager == null)
+                {
+                    var standbySettings = CreateStandbySettings(settings);
+                    _standbyScriptHostConfig = CreateScriptHostConfiguration(standbySettings, true);
+                    var defaultLoggerFactory = GetDefaultLoggerFactory(settings);
+
+                    _standbyHostManager = new WebScriptHostManager(_standbyScriptHostConfig, _secretManagerFactory, _eventManager, _settingsManager, standbySettings, defaultLoggerFactory);
+                    _standbyReceiverManager = new WebHookReceiverManager(_standbyHostManager.SecretManager);
+
+                    // TraceWriter is initialized to SystemTraceWriter only after creating WebScriptHostManager
+                    _standbyScriptHostConfig.TraceWriter?.Info("In Standby Mode. Host initializing.");
+                    InitializeFileSystem(_settingsManager.FileSystemIsReadOnly);
+                    StandbyManager.Initialize(_standbyScriptHostConfig);
+
+                    // start a background timer to identify when specialization happens
+                    // specialization usually happens via an http request (e.g. scale controller
+                    // ping) but this timer is started as well to handle cases where we
+                    // might not receive a request
+                    _specializationTimer = new Timer(OnSpecializationTimerTick, settings, 1000, 1000);
+                }
+            }
+            catch (Exception standbyModeInitEx)
+            {
+                _standbyScriptHostConfig?.TraceWriter?.Error("Host failed to initialize in StandbyMode.", standbyModeInitEx);
+                throw new HostInitializationException("Host failed to initialize in StandbyMode.", standbyModeInitEx);
+            }
+        }
 
-                        if (_standbyHostManager != null)
-                        {
-                            // we're starting the one and only one
-                            // standby mode specialization
-                            _activeScriptHostConfig.TraceWriter.Info(Resources.HostSpecializationTrace);
+        private void EncureInitializedNonStandbyMode(WebHostSettings settings)
+        {
+            try
+            {
+                // We're not in standby mode. There are two cases to consider:
+                // 1) We _were_ in standby mode and now we're ready to specialize
+                // 2) We're doing non-specialization normal initialization
+                if (_activeHostManager == null &&
+                    (_standbyHostManager == null || (_settingsManager.ContainerReady && _settingsManager.ConfigurationReady)))
+                {
+                    _specializationTimer?.Dispose();
+                    _specializationTimer = null;
 
-                            // After specialization, we need to ensure that custom timezone
-                            // settings configured by the user (WEBSITE_TIME_ZONE) are honored.
-                            // DateTime caches timezone information, so we need to clear the cache.
-                            TimeZoneInfo.ClearCachedData();
+                    _activeScriptHostConfig = CreateScriptHostConfiguration(settings);
+                    var defaultLoggerFactory = GetDefaultLoggerFactory(settings);
+                    _activeHostManager = new WebScriptHostManager(_activeScriptHostConfig, _secretManagerFactory, _eventManager, _settingsManager, settings, defaultLoggerFactory);
+                    _activeReceiverManager = new WebHookReceiverManager(_activeHostManager.SecretManager);
+                    InitializeFileSystem(_settingsManager.FileSystemIsReadOnly);
 
-                            // ensure we reinitialize hostname after specialization
-                            HostNameProvider.Reset();
-                        }
+                    // TraceWriter is initialized to SystemTraceWriter only after creating WebScriptHostManager
+                    _activeScriptHostConfig.TraceWriter.Info("Host initializing.");
 
-                        if (_standbyHostManager != null)
-                        {
-                            _standbyHostManager.Stop();
-                            _standbyHostManager.Dispose();
-                        }
-                        _standbyReceiverManager?.Dispose();
-                        _standbyScriptHostConfig = null;
-                        _standbyHostManager = null;
-                        _standbyReceiverManager = null;
+                    if (_standbyHostManager != null)
+                    {
+                        // we're starting the one and only one
+                        // standby mode specialization
+                        _activeScriptHostConfig.TraceWriter.Info(Resources.HostSpecializationTrace);
+
+                        // After specialization, we need to ensure that custom timezone
+                        // settings configured by the user (WEBSITE_TIME_ZONE) are honored.
+                        // DateTime caches timezone information, so we need to clear the cache.
+                        TimeZoneInfo.ClearCachedData();
+
+                        // ensure we reinitialize hostname after specialization
+                        HostNameProvider.Reset();
                     }
-                }
-                else
-                {
-                    // We're in standby (placeholder) mode. Initialize the standby services.
-                    if (_standbyHostManager == null)
+
+                    if (_standbyHostManager != null)
                     {
-                        var standbySettings = CreateStandbySettings(settings);
-                        _standbyScriptHostConfig = CreateScriptHostConfiguration(standbySettings, true);
-                        var defaultLoggerFactory = GetDefaultLoggerFactory(settings);
-                        _standbyHostManager = new WebScriptHostManager(_standbyScriptHostConfig, _secretManagerFactory, _eventManager, _settingsManager, standbySettings, defaultLoggerFactory);
-                        _standbyReceiverManager = new WebHookReceiverManager(_standbyHostManager.SecretManager);
-
-                        InitializeFileSystem(_settingsManager.FileSystemIsReadOnly);
-                        StandbyManager.Initialize(_standbyScriptHostConfig);
-
-                        // start a background timer to identify when specialization happens
-                        // specialization usually happens via an http request (e.g. scale controller
-                        // ping) but this timer is started as well to handle cases where we
-                        // might not receive a request
-                        _specializationTimer = new Timer(OnSpecializationTimerTick, settings, 1000, 1000);
+                        _standbyHostManager.Stop();
+                        _standbyHostManager.Dispose();
                     }
+                    _standbyReceiverManager?.Dispose();
+                    _standbyScriptHostConfig = null;
+                    _standbyHostManager = null;
+                    _standbyReceiverManager = null;
                 }
             }
+            catch (Exception hostInitEx)
+            {
+                _activeScriptHostConfig?.TraceWriter?.Error("Host failed to initialize.", hostInitEx);
+                throw new HostInitializationException("Host failed to initialize.", hostInitEx);
+            }
         }
 
         internal static WebHostSettings CreateStandbySettings(WebHostSettings settings)
@@ -209,7 +241,7 @@ internal static WebHostSettings CreateStandbySettings(WebHostSettings settings)
                 TraceWriter = settings.TraceWriter,
                 IsSelfHost = settings.IsSelfHost
             };
-
+            settings.TraceWriter?.Info("Created Standby WebHostSettings.");
             return standbySettings;
         }
 

src/WebJobs.Script.WebHost/WebScriptHostManager.cs

@@ -453,6 +453,7 @@ private async void OnSyncTimerTick(object state)
 
         private void InitializeHttp()
         {
+            _logger.LogDebug("Initializing HttpRequestManager");
             // get the registered http configuration from the extension registry
             var extensions = Instance.ScriptConfig.HostConfig.GetService<IExtensionRegistry>();
             var httpConfig = extensions.GetExtensions<IExtensionConfigProvider>().OfType<HttpExtensionConfiguration>().Single();
@@ -464,10 +465,12 @@ private void InitializeHttp()
             // since the request manager is created based on configurable
             // settings, it has to be recreated when host config changes
             _httpRequestManager = new WebScriptHostRequestManager(httpConfig, PerformanceManager, _metricsLogger, _config.TraceWriter);
+            _logger.LogDebug("Initialized HttpRequestManager");
         }
 
         private void InitializeHttpFunctions(IEnumerable<FunctionDescriptor> functions, HttpExtensionConfiguration httpConfig)
         {
+            _logger.LogDebug("Initializing HttpFunctions");
             // we must initialize the route factory here AFTER full configuration
             // has been resolved so we apply any route prefix customizations
             var functionHttpRouteFactory = new HttpRouteFactory(httpConfig.RoutePrefix);
@@ -486,6 +489,7 @@ private void InitializeHttpFunctions(IEnumerable<FunctionDescriptor> functions,
                 var httpRouteFactory = function.Metadata.IsProxy ? proxyHttpRouteFactory : functionHttpRouteFactory;
                 httpRouteFactory.TryAddRoute(_httpRoutes, function);
             }
+            _logger.LogDebug("Initialized HttpFunctions");
         }
 
         public override void Shutdown(bool hard = false)

src/WebJobs.Script/HostInitializationException.cs

@@ -0,0 +1,32 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using System;
+
+namespace Microsoft.Azure.WebJobs.Script
+{
+    /// <summary>
+    /// An exception that indicates an issue initializing a ScriptHost.
+    /// </summary>
+    [Serializable]
+    public class HostInitializationException : Exception
+    {
+        public HostInitializationException()
+        {
+        }
+
+        public HostInitializationException(string message) : base(message)
+        {
+        }
+
+        public HostInitializationException(string message, Exception inner) : base(message, inner)
+        {
+        }
+
+        protected HostInitializationException(
+          System.Runtime.Serialization.SerializationInfo info,
+          System.Runtime.Serialization.StreamingContext context) : base(info, context)
+        {
+        }
+    }
+}

src/WebJobs.Script/WebJobs.Script.csproj

@@ -513,6 +513,7 @@
     <Compile Include="Description\ScriptFunctionInvokerBase.cs" />
     <Compile Include="Description\DotNet\Compilation\FSharp\FSharpCompilation.cs" />
     <Compile Include="Diagnostics\LogType.cs" />
+    <Compile Include="HostInitializationException.cs" />
     <Compile Include="Scale\ApplicationPerformanceCounters.cs" />
     <Compile Include="Diagnostics\CompositeTraceWriter.cs" />
     <Compile Include="Description\Binding\BindingDirection.cs" />