Adding restart reason (#11191)

* Improving logging to capture a reason for JobHost restarts.

Author: RohitRanjanMS

release_notes.md

@@ -1,11 +1,11 @@
-### Release notes
-
-<!-- Please add your release notes in the following format:
-- My change description (#PR)
--->
-- Add JitTrace Files for v4.1042
-- Updating OTel related nuget packages (#11216)
-- Moving to version 1.5.7 of Microsoft.Azure.AppService.Middleware.Functions (https://github.com/Azure/azure-functions-host/pull/11231)
-- Refactor code to move the logic to search for WorkerConfigs to a default worker configuration resolver (#11219)
-- Update Node.js Worker Version to [3.11.0](https://github.com/Azure/azure-functions-nodejs-worker/releases/tag/v3.11.0)
-
+### Release notes
+
+<!-- Please add your release notes in the following format:
+- My change description (#PR)
+-->
+- Add JitTrace Files for v4.1042
+- Updating OTel related nuget packages (#11216)
+- Moving to version 1.5.7 of Microsoft.Azure.AppService.Middleware.Functions (https://github.com/Azure/azure-functions-host/pull/11231)
+- Refactor code to move the logic to search for WorkerConfigs to a default worker configuration resolver (#11219)
+- Update Node.js Worker Version to [3.11.0](https://github.com/Azure/azure-functions-nodejs-worker/releases/tag/v3.11.0)
+- Adding restart reason to the logs (#11191)

src/WebJobs.Script.Grpc/Channel/GrpcWorkerChannel.cs

@@ -140,7 +140,7 @@ internal GrpcWorkerChannel(
             _eventSubscriptions.Add(_eventManager.OfType<FileEvent>()
                 .Where(msg => _workerConfig.Description.Extensions.Contains(Path.GetExtension(msg.FileChangeArguments.FullPath)))
                 .Throttle(TimeSpan.FromMilliseconds(300)) // debounce
-                .Subscribe(msg => _eventManager.Publish(new HostRestartEvent())));
+                .Subscribe(msg => _eventManager.Publish(new HostRestartEvent($"Worker monitored file changed: '{msg.FileChangeArguments.Name}'."))));
 
             _startLatencyMetric = metricsLogger?.LatencyEvent(string.Format(MetricEventNames.WorkerInitializeLatency, workerConfig.Description.Language, attemptCount));
 

src/WebJobs.Script.WebHost/Controllers/HostController.cs

@@ -290,7 +290,7 @@ public async Task<IActionResult> Resume([FromServices] IScriptHostManager script
                 if (drainModeManager.IsDrainModeEnabled)
                 {
                     _logger.LogDebug("Starting a new host");
-                    await scriptHostManager.RestartHostAsync();
+                    await scriptHostManager.RestartHostAsync("Resuming from drain mode.", CancellationToken.None);
                 }
 
                 var status = new ResumeStatus { State = scriptHostManager.State };
@@ -451,7 +451,7 @@ public async Task<IActionResult> GetTriggers()
         [Authorize(Policy = PolicyNames.AdminAuthLevel)]
         public IActionResult Restart([FromServices] IScriptHostManager hostManager)
         {
-            Task ignore = hostManager.RestartHostAsync();
+            Task ignore = hostManager.RestartHostAsync("Restart API called.");
 
             var hostOptionsValue = _applicationHostOptions.Value;
             var response = new HostRestartResponse()

src/WebJobs.Script.WebHost/Diagnostics/Extensions/ScriptHostServiceLoggerExtension.cs

@@ -126,11 +126,11 @@ public static class ScriptHostServiceLoggerExtension
                 new EventId(518, nameof(ActiveHostChanging)),
                 "Active host changing from '{oldHostInstanceId}' to '{newHostInstanceId}'.");
 
-        private static readonly Action<ILogger, Exception> _enteringRestart =
-            LoggerMessage.Define(
+        private static readonly Action<ILogger, string, Exception> _enteringRestart =
+            LoggerMessage.Define<string>(
                 LogLevel.Debug,
                 new EventId(519, nameof(EnteringRestart)),
-                "Restart requested.");
+                "Restart requested. Reason '{restartReason}'");
 
         private static readonly Action<ILogger, Exception> _restartBeforeStart =
             LoggerMessage.Define(
@@ -321,9 +321,9 @@ public static void ActiveHostChanging(this ILogger logger, string oldHostInstanc
             _activeHostChanging(logger, oldHostInstanceId, newHostInstanceId, null);
         }
 
-        public static void EnteringRestart(this ILogger logger)
+        public static void EnteringRestart(this ILogger logger, string reason)
         {
-            _enteringRestart(logger, null);
+            _enteringRestart(logger, reason, null);
         }
 
         public static void RestartBeforeStart(this ILogger logger)

src/WebJobs.Script.WebHost/FileMonitoringService.cs

@@ -32,7 +32,7 @@ public class FileMonitoringService : IFileMonitoringService, IDisposable
         private readonly ILogger _logger;
         private readonly ILogger<FileMonitoringService> _typedLogger;
         private readonly IList<IDisposable> _eventSubscriptions = new List<IDisposable>();
-        private readonly Func<Task> _restart;
+        private readonly Func<string, Task> _restart;
         private readonly Action _shutdown;
         private readonly ImmutableArray<string> _rootDirectorySnapshot;
         private AutoRecoveringFileSystemWatcher _debugModeFileWatcher;
@@ -112,27 +112,27 @@ private void ResumeRestartIfScheduled()
                 using (System.Threading.ExecutionContext.SuppressFlow())
                 {
                     _typedLogger.LogDebug("Resuming scheduled restart.");
-                    Task.Run(async () => await ScheduleRestartAsync());
+                    Task.Run(async () => await ScheduleRestartAsync("Resuming scheduled restart."));
                 }
             }
         }
 
-        private async Task ScheduleRestartAsync(bool shutdown)
+        private async Task ScheduleRestartAsync(string reason, bool shutdown)
         {
             _restartScheduled = true;
             if (shutdown)
             {
                 _shutdownScheduled = true;
             }
 
-            await ScheduleRestartAsync();
+            await ScheduleRestartAsync(reason);
         }
 
-        private async Task ScheduleRestartAsync()
+        private async Task ScheduleRestartAsync(string reason)
         {
             if (Interlocked.Read(ref _suspensionRequestsCount) > 0)
             {
-                _logger.LogDebug("Restart requested while currently suspended. Ignoring request.");
+                _logger.LogDebug("Restart requested while currently suspended. Reason: '{Reason}'. Ignoring request.", reason);
             }
             else
             {
@@ -142,7 +142,7 @@ private async Task ScheduleRestartAsync()
                 }
                 else
                 {
-                    await _restart();
+                    await _restart(reason);
                 }
             }
         }
@@ -164,14 +164,18 @@ private void InitializeFileWatchers()
             }
 
             _eventSubscriptions.Add(_eventManager.OfType<HostRestartEvent>()
-                    .Subscribe((msg) => ScheduleRestartAsync(false)
-                    .ContinueWith(t => _logger.LogCritical(t.Exception.Message),
-                        TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously)));
+                .Subscribe(HandleHostRestartEvent));
 
             // Delay starting up for logging and debug file watchers to avoid long start up times
             Utility.ExecuteAfterColdStartDelay(_environment, InitializeSecondaryFileWatchers);
         }
 
+        private void HandleHostRestartEvent(HostRestartEvent restartEvent)
+        {
+            ScheduleRestartAsync($"Handling {nameof(HostRestartEvent)} ('{restartEvent.Name}':'{restartEvent.Source}'). Reason: {restartEvent.Reason}", false)
+                .ContinueWith(t => _logger.LogCritical(t.Exception?.Message), TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously);
+        }
+
         /// <summary>
         /// Initializes the file and directory monitoring that does not need to happen as part of a Host startup
         /// These watchers can be started after a delay to avoid startup performance issue
@@ -293,7 +297,8 @@ private void OnFileChanged(FileSystemEventArgs e)
                 changeDescription = "File";
                 if (File.Exists(e.FullPath))
                 {
-                    TraceFileChangeRestart(changeDescription, e.ChangeType.ToString(), e.FullPath, isShutdown: true);
+                    string fileChangeMsg = string.Format(CultureInfo.InvariantCulture, "{0} change of type '{1}' detected for '{2}'", changeDescription, e.ChangeType.ToString(), e.FullPath);
+                    TraceFileChangeRestart(fileChangeMsg, isShutdown: true);
                     Shutdown();
                 }
             }
@@ -316,15 +321,16 @@ private void OnFileChanged(FileSystemEventArgs e)
                     shutdown = true;
                 }
 
-                TraceFileChangeRestart(changeDescription, e.ChangeType.ToString(), e.FullPath, shutdown);
-                ScheduleRestartAsync(shutdown).ContinueWith(t => _logger.LogError(t.Exception, $"Error restarting host (full shutdown: {shutdown})"),
-                    TaskContinuationOptions.ExecuteSynchronously | TaskContinuationOptions.OnlyOnFaulted);
+                string fileChangeMsg = string.Format(CultureInfo.InvariantCulture, "{0} change of type '{1}' detected for '{2}'", changeDescription, e.ChangeType.ToString(), e.FullPath);
+                TraceFileChangeRestart(fileChangeMsg, shutdown);
+                ScheduleRestartAsync(fileChangeMsg, shutdown)
+                    .ContinueWith(t => _logger.LogError(t.Exception, $"Error restarting host (full shutdown: {shutdown})"),
+                        TaskContinuationOptions.ExecuteSynchronously | TaskContinuationOptions.OnlyOnFaulted);
             }
         }
 
-        private void TraceFileChangeRestart(string changeDescription, string changeType, string path, bool isShutdown)
+        private void TraceFileChangeRestart(string fileChangeMsg, bool isShutdown)
         {
-            string fileChangeMsg = string.Format(CultureInfo.InvariantCulture, "{0} change of type '{1}' detected for '{2}'", changeDescription, changeType, path);
             _logger.LogInformation(fileChangeMsg);
 
             string action = isShutdown ? "shutdown" : "restart";
@@ -349,11 +355,11 @@ internal static string GetRelativeDirectory(string path, string scriptRoot)
             return string.Empty;
         }
 
-        private Task RestartAsync()
+        private Task RestartAsync(string reason)
         {
             if (!_shutdownScheduled && Interlocked.Exchange(ref _restartRequested, 1) == 0)
             {
-                return _scriptHostManager.RestartHostAsync();
+                return _scriptHostManager.RestartHostAsync(reason);
             }
 
             return Task.CompletedTask;

src/WebJobs.Script.WebHost/Middleware/HostWarmupMiddleware.cs

@@ -158,7 +158,7 @@ public async Task HostWarmupAsync(HttpRequest request)
         {
             if (request.Query.TryGetValue("restart", out StringValues value) && string.Compare("1", value) == 0)
             {
-                await _hostManager.RestartHostAsync(CancellationToken.None);
+                await _hostManager.RestartHostAsync("Host warmup call requested a restart.", CancellationToken.None);
 
                 // This call is here for sanity, but we should be fully initialized.
                 await _hostManager.DelayUntilHostReady();

src/WebJobs.Script.WebHost/Standby/StandbyManager.cs

@@ -78,7 +78,7 @@ public Task SpecializeHostAsync()
                 if (t.IsFaulted)
                 {
                     // if we fail during specialization for whatever reason
-                    // this is fatal, so we shutdown
+                    // this is fatal, so we stop the application.
                     _logger.LogError(t.Exception, "Specialization failed. Shutting down.");
                     _applicationLifetime.StopApplication();
                 }
@@ -119,7 +119,7 @@ public async Task SpecializeHostCoreAsync()
 
             using (_metricsLogger.LatencyEvent(MetricEventNames.SpecializationRestartHost))
             {
-                await _scriptHostManager.RestartHostAsync();
+                await _scriptHostManager.RestartHostAsync("Host specialization.");
             }
 
             using (_metricsLogger.LatencyEvent(MetricEventNames.SpecializationDelayUntilHostReady))

src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs

@@ -569,8 +569,10 @@ public async Task StopAsync(CancellationToken cancellationToken)
             State = ScriptHostState.Stopped;
         }
 
-        public async Task RestartHostAsync(CancellationToken cancellationToken)
+        public async Task RestartHostAsync(string reason, CancellationToken cancellationToken)
         {
+            ArgumentException.ThrowIfNullOrWhiteSpace(reason);
+
             if (ShutdownRequested)
             {
                 return;
@@ -586,7 +588,7 @@ public async Task RestartHostAsync(CancellationToken cancellationToken)
                     await _hostStarted;
                 }
 
-                _logger.EnteringRestart();
+                _logger.EnteringRestart(reason);
 
                 // If anything is mid-startup, cancel it.
                 _startupLoopTokenSource?.Cancel();
@@ -830,7 +832,7 @@ private void OnHostHealthCheckTimer(object state)
                 // fail and we'll enter a restart loop (exponentially backing off)
                 // until the host is healthy again and we can resume host processing.
                 _logger.UnhealthyRestart();
-                var tIgnore = RestartHostAsync(CancellationToken.None);
+                var tIgnore = RestartHostAsync("Host health check detected an unhealthy host.", CancellationToken.None);
             }
         }
 

src/WebJobs.Script/Description/DotNet/DotNetFunctionInvoker.cs

@@ -176,13 +176,13 @@ private async Task ReloadScriptAsync()
 
             // If the compilation succeeded, AND:
             //  - We haven't cached a function (failed to compile on load), OR
-            //  - We're referencing local function types (i.e. POCOs defined in the function) AND Our our function signature has changed
+            //  - We're referencing local function types (i.e. POCOs defined in the function) AND our function signature has changed
             // Restart our host.
             if (compilationSucceeded &&
                 (_functionSignature == null ||
                 (_functionSignature.HasLocalTypeReference || !_functionSignature.Equals(signature))))
             {
-                await Host.RestartAsync().ConfigureAwait(false);
+                await Host.RestartAsync(".NET compilation.").ConfigureAwait(false);
             }
         }
 

src/WebJobs.Script/Eventing/Host/HostRestartEvent.cs

@@ -1,13 +1,20 @@
 // 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.Eventing
 {
     public class HostRestartEvent : ScriptEvent
     {
-        public HostRestartEvent()
+        public HostRestartEvent(string reason)
             : base(nameof(HostRestartEvent), EventSources.Worker)
         {
+            ArgumentException.ThrowIfNullOrWhiteSpace(reason);
+
+            Reason = reason;
         }
+
+        public string Reason { get; }
     }
 }