Implementing Host Dynamic Debug Mode and throttled/conditional file logging

Author: mathewc

sample/QueueTrigger-Powershell/queueTrigger.ps1

@@ -1,4 +1,7 @@
 $in = Get-Content $triggerInput
 $json = $in | ConvertFrom-Json
+
+Write-Output "PowerShell script processed queue message '$json'"
+
 $entity = [string]::Format('{{ "Status": 0, "Title": "PowerShell Table Entity for message {0}" }}', $json.id)
 $entity | Out-File -Encoding Ascii $output

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

@@ -47,7 +47,7 @@ public static void Register(HttpConfiguration config, WebHostSettings settings =
             var container = builder.Build();
             config.DependencyResolver = new AutofacWebApiDependencyResolver(container);
 
-            config.MessageHandlers.Add(new EnsureHostRunningHandler(config));
+            config.MessageHandlers.Add(new WebScriptHostHandler(config));
 
             // Web API configuration and services
 

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

@@ -182,7 +182,7 @@ private static ScriptHostConfiguration GetScriptHostConfiguration(string scriptP
             {
                 RootScriptPath = scriptPath,
                 RootLogPath = logPath,
-                FileLoggingEnabled = true
+                FileLoggingMode = FileLoggingMode.DebugOnly
             };
 
             // If running on Azure Web App, derive the host ID from the site name

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

@@ -6,8 +6,10 @@
 using System.Linq;
 using System.Net;
 using System.Net.Http;
+using System.Threading;
 using System.Threading.Tasks;
 using System.Web.Http;
+using System.Web.Http.Controllers;
 using Microsoft.Azure.WebJobs.Script.Description;
 using Microsoft.Azure.WebJobs.Script.WebHost.Filters;
 using Microsoft.Azure.WebJobs.Script.WebHost.Models;
@@ -94,5 +96,15 @@ public HostStatus GetHostStatus()
 
             return status;
         }
+
+        public override Task<HttpResponseMessage> ExecuteAsync(HttpControllerContext controllerContext, CancellationToken cancellationToken)
+        {
+            // For all admin api requests, we'll update the ScriptHost debug timeout
+            // For now, we'll enable debug mode on ANY admin requests. Since the Portal interacts through
+            // the admin API this is sufficient for identifying when the Portal is connected.
+            _scriptHostManager.Instance.NotifyDebug();
+
+            return base.ExecuteAsync(controllerContext, cancellationToken);
+        }
     }
 }

…ost/Handlers/EnsureHostRunningHandler.cs …WebHost/Handlers/WebScriptHostHandler.cssrc/WebJobs.Script.WebHost/Handlers/EnsureHostRunningHandler.cs renamed to src/WebJobs.Script.WebHost/Handlers/WebScriptHostHandler.cs src/WebJobs.Script.WebHost/Handlers/EnsureHostRunningHandler.cs renamed to src/WebJobs.Script.WebHost/Handlers/WebScriptHostHandler.cs

@@ -2,6 +2,7 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Linq;
 using System.Net;
 using System.Net.Http;
 using System.Threading;
@@ -10,19 +11,20 @@
 
 namespace Microsoft.Azure.WebJobs.Script.WebHost.Handlers
 {
-    public class EnsureHostRunningHandler : DelegatingHandler
+    public class WebScriptHostHandler : DelegatingHandler
     {
-        private readonly TimeSpan _hostTimeout = new TimeSpan(0, 0, 30);
+        private readonly TimeSpan _hostTimeoutSeconds;
         private readonly int _hostRunningPollIntervalMs = 500;
         private readonly HttpConfiguration _config;
 
-        public EnsureHostRunningHandler(HttpConfiguration config)
+        public WebScriptHostHandler(HttpConfiguration config, int hostTimeoutSeconds = 30)
         {
             if (config == null)
             {
                 throw new ArgumentNullException("config");
             }
 
+            _hostTimeoutSeconds = new TimeSpan(0, 0, hostTimeoutSeconds);
             _config = config;
         }
 
@@ -46,7 +48,7 @@ protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage
                 // initialize. This might happen if http requests come in while the
                 // host is starting up for the first time, or if it is restarting.
                 TimeSpan timeWaited = TimeSpan.Zero;
-                while (!scriptHostManager.IsRunning && (timeWaited < _hostTimeout))
+                while (!scriptHostManager.IsRunning && (timeWaited < _hostTimeoutSeconds))
                 {
                     await Task.Delay(_hostRunningPollIntervalMs);
                     timeWaited += TimeSpan.FromMilliseconds(_hostRunningPollIntervalMs);

src/WebJobs.Script.WebHost/WebJobs.Script.WebHost.csproj

@@ -317,7 +317,7 @@
       <DependentUpon>Global.asax</DependentUpon>
     </Compile>
     <Compile Include="GlobalSuppressions.cs" />
-    <Compile Include="Handlers\EnsureHostRunningHandler.cs" />
+    <Compile Include="Handlers\WebScriptHostHandler.cs" />
     <Compile Include="HostSecrets.cs" />
     <Compile Include="Models\FunctionInvocation.cs" />
     <Compile Include="Models\FunctionMetrics.cs" />

src/WebJobs.Script.WebHost/WebScriptHostManager.cs

@@ -51,7 +51,7 @@ public static bool IsAzureEnvironment
 
         private IDictionary<string, FunctionDescriptor> HttpFunctions { get; set; }
 
-        public bool Initialized
+        public virtual bool Initialized
         {
             get
             {
@@ -179,7 +179,7 @@ public static void WarmUp(WebHostSettings settings)
                 ScriptHostConfiguration config = new ScriptHostConfiguration
                 {
                     RootScriptPath = rootPath,
-                    FileLoggingEnabled = false,
+                    FileLoggingMode = FileLoggingMode.Never,
                     RootLogPath = settings.LogPath,
                     TraceWriter = traceWriter,
                     FileWatchingEnabled = false

src/WebJobs.Script/Config/ScriptHostConfiguration.cs

@@ -15,6 +15,7 @@ public ScriptHostConfiguration()
         {
             HostConfig = new JobHostConfiguration();
             FileWatchingEnabled = true;
+            FileLoggingMode = FileLoggingMode.Never;
             RootScriptPath = Environment.CurrentDirectory;
             RootLogPath = Path.Combine(Path.GetTempPath(), "Functions");
         }
@@ -48,11 +49,11 @@ public ScriptHostConfiguration()
         public bool FileWatchingEnabled { get; set; }
 
         /// <summary>
-        /// Gets or sets a value indicating whether logs should be written to disk.
-        /// The default is false. When set to true, logs will be written to the directory
-        /// specified by <see cref="RootLogPath"/>.
+        /// Gets or sets a value governing when logs should be written to disk.
+        /// When enabled, logs will be written to the directory specified by 
+        /// <see cref="RootLogPath"/>.
         /// </summary>
-        public bool FileLoggingEnabled { get; set; }
+        public FileLoggingMode FileLoggingMode { get; set; }
 
         /// <summary>
         /// Gets the list of functions that should be run. This list can be used to filter

src/WebJobs.Script/Description/FunctionInvokerBase.cs

@@ -27,7 +27,9 @@ internal FunctionInvokerBase(ScriptHost host, FunctionMetadata functionMetadata,
 
             traceWriterFactory = traceWriterFactory ?? new FunctionTraceWriterFactory(functionMetadata.Name, Host.ScriptConfig);
             TraceWriter traceWriter = traceWriterFactory.Create();
-            TraceWriter = new ConditionalTraceWriter(traceWriter, t => !(t.Properties?.ContainsKey(PrimaryHostTracePropertyName) ?? false) || Host.IsPrimary);
+
+            // Function file logging is only done conditionally
+            TraceWriter = traceWriter.Conditional(t => Host.FileLoggingEnabled && (!(t.Properties?.ContainsKey(PrimaryHostTracePropertyName) ?? false) || Host.IsPrimary));
         }
 
         protected static IDictionary<string, object> PrimaryHostTraceProperties => _primaryHostTraceProperties;

src/WebJobs.Script/Diagnostics/ConditionalTraceWriter.cs

@@ -10,9 +10,8 @@ namespace Microsoft.Azure.WebJobs.Script
     public sealed class ConditionalTraceWriter : TraceWriter
     {
         private readonly Func<TraceEvent, bool> _predicate;
-        private readonly FailedConditionTraceBehavior _failedConditionBehavior;
 
-        public ConditionalTraceWriter(TraceWriter innerWriter, Func<TraceEvent, bool> predicate, FailedConditionTraceBehavior failedConditionBehavior = FailedConditionTraceBehavior.TraceAsVerbose) 
+        public ConditionalTraceWriter(TraceWriter innerWriter, Func<TraceEvent, bool> predicate) 
             : base(innerWriter?.Level ?? TraceLevel.Off)
         {
             if (innerWriter == null)
@@ -27,7 +26,6 @@ public ConditionalTraceWriter(TraceWriter innerWriter, Func<TraceEvent, bool> pr
 
             InnerWriter = innerWriter;
             _predicate = predicate;
-            _failedConditionBehavior = failedConditionBehavior;
         }
 
         public TraceWriter InnerWriter { get; }
@@ -38,33 +36,6 @@ public override void Trace(TraceEvent traceEvent)
             {
                 InnerWriter.Trace(traceEvent);
             }
-            else if (_failedConditionBehavior == FailedConditionTraceBehavior.TraceAsVerbose)
-            {
-                var eventClone = CloneEvent(traceEvent);
-
-                // To improve troubleshooting, instead of completely suppressing the event, we'll downgrade
-                // it to 'Verbose' and add a prefix to the message.
-                eventClone.Message = $"[Supressed '{traceEvent.Level}' trace] {traceEvent.Message}";
-                eventClone.Level = TraceLevel.Verbose;
-
-                InnerWriter.Trace(eventClone);
-            }
-        }
-
-        private static TraceEvent CloneEvent(TraceEvent traceEvent)
-        {
-            var result = new TraceEvent(traceEvent.Level, traceEvent.Message, 
-                traceEvent.Source, traceEvent.Exception)
-            {
-                Timestamp = traceEvent.Timestamp
-            };
-
-            foreach (var property in traceEvent.Properties)
-            {
-                result.Properties.Add(property);
-            }
-
-            return result;
         }
     }
 }