Log Node.js global unhandled exceptions properly (#209)

src/WebJobs.Script/Description/NodeFunctionInvoker.cs

@@ -34,20 +34,18 @@ public class NodeFunctionInvoker : ScriptFunctionInvokerBase
 
         private Func<object, Task<object>> _scriptFunc;
         private Func<object, Task<object>> _clearRequireCache;
+        private static Func<object, Task<object>> _globalInitializationFunc;
         private static string _functionTemplate;
         private static string _clearRequireCacheScript;
+        private static string _globalInitializationScript;
 
         static NodeFunctionInvoker()
         {
-            Assembly assembly = Assembly.GetExecutingAssembly();
-            using (StreamReader reader = new StreamReader(assembly.GetManifestResourceStream("Microsoft.Azure.WebJobs.Script.functionTemplate.js")))
-            {
-                _functionTemplate = reader.ReadToEnd();
-            }
-            using (StreamReader reader = new StreamReader(assembly.GetManifestResourceStream("Microsoft.Azure.WebJobs.Script.clearRequireCache.js")))
-            {
-                _clearRequireCacheScript = reader.ReadToEnd();
-            }
+            _functionTemplate = ReadResourceString("functionTemplate.js");
+            _clearRequireCacheScript = ReadResourceString("clearRequireCache.js");
+            _globalInitializationScript = ReadResourceString("globalInitialization.js");
+
+            Initialize();
         }
 
         internal NodeFunctionInvoker(ScriptHost host, BindingMetadata trigger, FunctionMetadata functionMetadata, Collection<FunctionBinding> inputBindings, Collection<FunctionBinding> outputBindings)
@@ -63,6 +61,24 @@ internal NodeFunctionInvoker(ScriptHost host, BindingMetadata trigger, FunctionM
             InitializeFileWatcherIfEnabled();
         }
 
+        /// <summary>
+        /// Event raised whenever an unhandled Node exception occurs at the
+        /// global level (e.g. an unhandled async exception).
+        /// </summary>
+        public static event UnhandledExceptionEventHandler UnhandledException;
+
+        private static Func<object, Task<object>> GlobalInitializationFunc
+        {
+            get
+            {
+                if (_globalInitializationFunc == null)
+                {
+                    _globalInitializationFunc = Edge.Func(_globalInitializationScript);
+                }
+                return _globalInitializationFunc;
+            }
+        }
+
         private Func<object, Task<object>> ScriptFunc
         {
             get
@@ -413,5 +429,42 @@ private bool TryDeserializeJsonObject(string json, out Dictionary<string, object
                 return false;
             }
         }
+
+        /// <summary>
+        /// Performs required static initialization in the Edge context.
+        /// </summary>
+        private static void Initialize()
+        {
+            var handle = (Func<object, Task<object>>)(err =>
+            {
+                if (UnhandledException != null)
+                {
+                    // raise the event to allow subscribers to handle
+                    var ex = new InvalidOperationException((string)err);
+                    UnhandledException(null, new UnhandledExceptionEventArgs(ex, true));
+
+                    // Ensure that we allow the unhandled exception to kill the process.
+                    // unhandled Node global exceptions should never be swallowed.
+                    throw ex;
+                }
+                return Task.FromResult<object>(null);
+            });
+            var context = new Dictionary<string, object>()
+            {
+                { "handleUncaughtException", handle }
+            };
+
+            GlobalInitializationFunc(context).Wait();
+        }
+
+        private static string ReadResourceString(string fileName)
+        {
+            string resourcePath = string.Format("Microsoft.Azure.WebJobs.Script.{0}", fileName);
+            Assembly assembly = Assembly.GetExecutingAssembly();
+            using (StreamReader reader = new StreamReader(assembly.GetManifestResourceStream(resourcePath)))
+            {
+                return reader.ReadToEnd();
+            }
+        }
     }
 }

src/WebJobs.Script/Description/ScriptFunctionInvokerBase.cs

@@ -53,6 +53,9 @@ public virtual void OnError(Exception ex)
         {
             string error = Utility.FlattenException(ex);
             TraceWriter.Error(error);
+
+            // when any errors occur, we want to flush immediately
+            TraceWriter.Flush();
         }
 
         protected void InitializeFileWatcherIfEnabled()

src/WebJobs.Script/FileTraceWriter.cs

@@ -62,17 +62,30 @@ public FileTraceWriter(string logFilePath, TraceLevel level) : base(level)
             _flushTimer.Start();
         }
 
-        public void FlushToFile()
+        public override void Flush()
         {
             if (_logBuffer.Count == 0)
             {
                 return;
             }
 
-            // snapshot the current set of buffered logs
-            // and set a new bag
-            ConcurrentQueue<string> currentBuffer = _logBuffer;
-            _logBuffer = new ConcurrentQueue<string>();
+            ConcurrentQueue<string> currentBuffer = null;
+            lock (_syncLock)
+            {
+                // Snapshot the current set of buffered logs
+                // and set a new queue. This ensures that any new
+                // logs are written to the new buffer.
+                // We do this snapshot in a lock since Flush might be
+                // called by multiple threads concurrently, and we need
+                // to ensure we only log each log once.
+                currentBuffer = _logBuffer;
+                _logBuffer = new ConcurrentQueue<string>();
+            }
+
+            if (currentBuffer.Count == 0)
+            {
+                return;
+            }
 
             // concatenate all lines into one string
             StringBuilder sb = new StringBuilder();
@@ -151,7 +164,7 @@ protected virtual void Dispose(bool disposing)
                     }
 
                     // ensure any remaining logs are flushed
-                    FlushToFile();
+                    Flush();
                 }
 
                 _disposed = true;
@@ -179,7 +192,7 @@ protected virtual void AppendLine(string line)
 
         private void OnFlushLogs(object sender, ElapsedEventArgs e)
         {
-            FlushToFile();
+            Flush();
         }
 
         internal void SetNewLogFile()

src/WebJobs.Script/Host/ScriptHost.cs

@@ -203,6 +203,8 @@ protected virtual void Initialize()
                 new CSharpFunctionDescriptionProvider(this, ScriptConfig)
             };
 
+            NodeFunctionInvoker.UnhandledException += OnUnhandledException;
+
             // read all script functions and apply to JobHostConfiguration
             Collection<FunctionDescriptor> functions = ReadFunctions(ScriptConfig, descriptionProviders);
             string defaultNamespace = "Host";
@@ -219,6 +221,11 @@ protected virtual void Initialize()
             Functions = functions;
         }
 
+        private void OnUnhandledException(object sender, UnhandledExceptionEventArgs e)
+        {
+            HandleHostError((Exception)e.ExceptionObject);
+        }
+
         // Bindings may require us to update JobHostConfiguration. 
         private static void ApplyBindingConfiguration(Collection<FunctionDescriptor> functions, JobHostConfiguration hostConfig)
         {
@@ -656,28 +663,75 @@ private void HandleHostError(Microsoft.Azure.WebJobs.Extensions.TraceFilter trac
         {
             foreach (TraceEvent traceEvent in traceFilter.Events)
             {
-                if (traceEvent.Exception is FunctionInvocationException)
+                HandleHostError(traceEvent.Exception);
+            }
+        }
+
+        private void HandleHostError(Exception exception)
+        {
+            // First, ensure that we've logged to the host log
+            // Also ensure we flush immediately to ensure any buffered logs
+            // are written
+            TraceWriter.Error("An ScriptHost error has occurred", exception);
+            TraceWriter.Flush();
+
+            if (exception is FunctionInvocationException)
+            {
+                // For all function invocation errors, we notify the invoker so it can
+                // log the error as needed to its function specific logs.
+                FunctionInvocationException invocationException = exception as FunctionInvocationException;
+                NotifyInvoker(invocationException.MethodName, invocationException);
+            }
+            else if (exception is FunctionIndexingException)
+            {
+                // For all startup time indexing errors, we accumulate them per function
+                FunctionIndexingException indexingException = exception as FunctionIndexingException;
+                string formattedError = Utility.FlattenException(indexingException);
+                AddFunctionError(indexingException.MethodName, formattedError);
+
+                // Also notify the invoker so the error can also be written to the function
+                // log file
+                NotifyInvoker(indexingException.MethodName, indexingException);
+
+                // Mark the error as handled so indexing will continue
+                indexingException.Handled = true;
+            }
+            else
+            {
+                // See if we can identify which function caused the error, and if we can
+                // log the error as needed to its function specific logs.
+                FunctionDescriptor function = null;
+                if (TryGetFunctionFromException(Functions, exception, out function))
                 {
-                    // For all function invocation events, we notify the invoker so it can
-                    // log the error as needed to its function specific logs.
-                    FunctionInvocationException invocationException = traceEvent.Exception as FunctionInvocationException;
-                    NotifyInvoker(invocationException.MethodName, invocationException);
+                    NotifyInvoker(function.Name, exception);
                 }
-                else if (traceEvent.Exception is FunctionIndexingException)
-                {
-                    // For all startup time indexing errors, we accumulate them per function
-                    FunctionIndexingException indexingException = traceEvent.Exception as FunctionIndexingException;
-                    string formattedError = Utility.FlattenException(indexingException);
-                    AddFunctionError(indexingException.MethodName, formattedError);
-
-                    // Also notify the invoker so the error can also be written to the function
-                    // log file
-                    NotifyInvoker(indexingException.MethodName, indexingException);
+            }
+        }
 
-                    // Mark the error as handled so indexing will continue
-                    indexingException.Handled = true;
+        internal static bool TryGetFunctionFromException(Collection<FunctionDescriptor> functions, Exception exception, out FunctionDescriptor function)
+        {
+            function = null;
+
+            string errorStack = exception.ToString().ToLowerInvariant();
+            foreach (var currFunction in functions)
+            {
+                // For each function, we search the entire error stack trace to see if it contains
+                // the function entry/primary script path. If it does, we're virtually certain that
+                // that function caused the error (e.g. as in the case of global unhandled exceptions
+                // coming from Node.js scripts).
+                // We use the directory name for the script rather than the full script path itself to ensure
+                // that we handle cases where the error might be coming from some other script (e.g. an NPM
+                // module) that is part of the function.
+                string absoluteScriptPath = Path.GetFullPath(currFunction.Metadata.Source).ToLowerInvariant();
+                string functionDirectory = Path.GetDirectoryName(absoluteScriptPath);
+                if (errorStack.Contains(functionDirectory))
+                {
+                    function = currFunction;
+                    return true;
                 }
             }
+
+            return false;
         }
 
         private void NotifyInvoker(string functionName, Exception ex)

src/WebJobs.Script/WebJobs.Script.csproj

@@ -353,6 +353,7 @@
       <Link>edge\edge.js</Link>
       <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
     </Content>
+    <EmbeddedResource Include="globalInitialization.js" />
   </ItemGroup>
   <ItemGroup>
     <None Include="app.config">

src/WebJobs.Script/globalInitialization.js

@@ -0,0 +1,13 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+var process = require('process');
+
+return function (context, callback) {{
+    process.on('uncaughtException', function (err) {{
+        context.handleUncaughtException(err.stack);
+    }});
+
+    callback();
+}};
+

test/WebJobs.Script.Tests/FileTraceWriterTests.cs

@@ -103,7 +103,7 @@ public void SetNewLogFile_EmptyDirectory_Succeeds()
             Assert.Equal(0, files.Length);
 
             traceWriter.Verbose("Test log");
-            traceWriter.FlushToFile();
+            traceWriter.Flush();
 
             files = directory.GetFiles().OrderByDescending(p => p.LastWriteTime).ToArray();
             Assert.Equal(1, files.Length);
@@ -118,7 +118,7 @@ private void WriteLogs(string logFilePath, int numLogs)
                 traceWriter.Verbose(string.Format("Test message {0} {1}", Thread.CurrentThread.ManagedThreadId, i));
             }
 
-            traceWriter.FlushToFile();
+            traceWriter.Flush();
         }
     }
 }

test/WebJobs.Script.Tests/ScriptHostTests.cs

@@ -2,9 +2,10 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Collections.ObjectModel;
 using System.Diagnostics;
-using Microsoft.Azure.WebJobs;
 using Microsoft.Azure.WebJobs.Script;
+using Microsoft.Azure.WebJobs.Script.Description;
 using Newtonsoft.Json.Linq;
 using Xunit;
 
@@ -125,5 +126,56 @@ public void ApplyFunctionsFilter()
             Assert.Equal("Function1", scriptConfig.Functions[0]);
             Assert.Equal("Function2", scriptConfig.Functions[1]);
         }
+
+        [Fact]
+        public void TryGetFunctionFromException_FunctionMatch()
+        {
+            string stack = "TypeError: Cannot read property 'is' of undefined\n" +
+                           "at Timeout._onTimeout(D:\\home\\site\\wwwroot\\HttpTriggerNode\\index.js:7:35)\n" +
+                           "at tryOnTimeout (timers.js:224:11)\n" +
+                           "at Timer.listOnTimeout(timers.js:198:5)";
+            Collection<FunctionDescriptor> functions = new Collection<FunctionDescriptor>();
+            var exception = new InvalidOperationException(stack);
+
+            // no match - empty functions
+            FunctionDescriptor functionResult = null;
+            bool result = ScriptHost.TryGetFunctionFromException(functions, exception, out functionResult);
+            Assert.False(result);
+            Assert.Null(functionResult);
+
+            // no match - one non-matching function
+            FunctionMetadata metadata = new FunctionMetadata
+            {
+                Name = "SomeFunction",
+                Source = "D:\\home\\site\\wwwroot\\SomeFunction\\index.js"
+            };
+            FunctionDescriptor function = new FunctionDescriptor("TimerFunction", new TestInvoker(), metadata, new Collection<ParameterDescriptor>());
+            functions.Add(function);
+            result = ScriptHost.TryGetFunctionFromException(functions, exception, out functionResult);
+            Assert.False(result);
+            Assert.Null(functionResult);
+
+            // match - exact
+            metadata = new FunctionMetadata
+            {
+                Name = "HttpTriggerNode",
+                Source = "D:\\home\\site\\wwwroot\\HttpTriggerNode\\index.js"
+            };
+            function = new FunctionDescriptor("TimerFunction", new TestInvoker(), metadata, new Collection<ParameterDescriptor>());
+            functions.Add(function);
+            result = ScriptHost.TryGetFunctionFromException(functions, exception, out functionResult);
+            Assert.True(result);
+            Assert.Same(function, functionResult);
+
+            // match - different file from the same function
+            stack = "TypeError: Cannot read property 'is' of undefined\n" +
+                           "at Timeout._onTimeout(D:\\home\\site\\wwwroot\\HttpTriggerNode\\npm\\lib\\foo.js:7:35)\n" +
+                           "at tryOnTimeout (timers.js:224:11)\n" +
+                           "at Timer.listOnTimeout(timers.js:198:5)";
+            exception = new InvalidOperationException(stack);
+            result = ScriptHost.TryGetFunctionFromException(functions, exception, out functionResult);
+            Assert.True(result);
+            Assert.Same(function, functionResult);
+        }
     }
 }