diff --git a/src/WebJobs.Script/Description/NodeFunctionInvoker.cs b/src/WebJobs.Script/Description/NodeFunctionInvoker.cs index dd1496d2a5..1423ee9435 100644 --- a/src/WebJobs.Script/Description/NodeFunctionInvoker.cs +++ b/src/WebJobs.Script/Description/NodeFunctionInvoker.cs @@ -34,20 +34,18 @@ public class NodeFunctionInvoker : ScriptFunctionInvokerBase private Func> _scriptFunc; private Func> _clearRequireCache; + private static Func> _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 inputBindings, Collection outputBindings) @@ -63,6 +61,24 @@ internal NodeFunctionInvoker(ScriptHost host, BindingMetadata trigger, FunctionM InitializeFileWatcherIfEnabled(); } + /// + /// Event raised whenever an unhandled Node exception occurs at the + /// global level (e.g. an unhandled async exception). + /// + public static event UnhandledExceptionEventHandler UnhandledException; + + private static Func> GlobalInitializationFunc + { + get + { + if (_globalInitializationFunc == null) + { + _globalInitializationFunc = Edge.Func(_globalInitializationScript); + } + return _globalInitializationFunc; + } + } + private Func> ScriptFunc { get @@ -413,5 +429,42 @@ private bool TryDeserializeJsonObject(string json, out Dictionary + /// Performs required static initialization in the Edge context. + /// + private static void Initialize() + { + var handle = (Func>)(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(null); + }); + var context = new Dictionary() + { + { "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(); + } + } } } diff --git a/src/WebJobs.Script/Description/ScriptFunctionInvokerBase.cs b/src/WebJobs.Script/Description/ScriptFunctionInvokerBase.cs index 87853ed512..f8c7051758 100644 --- a/src/WebJobs.Script/Description/ScriptFunctionInvokerBase.cs +++ b/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() diff --git a/src/WebJobs.Script/FileTraceWriter.cs b/src/WebJobs.Script/FileTraceWriter.cs index 1fed6205a6..688c9c0628 100644 --- a/src/WebJobs.Script/FileTraceWriter.cs +++ b/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 currentBuffer = _logBuffer; - _logBuffer = new ConcurrentQueue(); + ConcurrentQueue 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(); + } + + 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() diff --git a/src/WebJobs.Script/Host/ScriptHost.cs b/src/WebJobs.Script/Host/ScriptHost.cs index f95a12148c..faca0ab6dd 100644 --- a/src/WebJobs.Script/Host/ScriptHost.cs +++ b/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 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 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 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) diff --git a/src/WebJobs.Script/WebJobs.Script.csproj b/src/WebJobs.Script/WebJobs.Script.csproj index da4e0df514..7ea5d0fb56 100644 --- a/src/WebJobs.Script/WebJobs.Script.csproj +++ b/src/WebJobs.Script/WebJobs.Script.csproj @@ -353,6 +353,7 @@ edge\edge.js PreserveNewest + diff --git a/src/WebJobs.Script/globalInitialization.js b/src/WebJobs.Script/globalInitialization.js new file mode 100644 index 0000000000..8ba3c552db --- /dev/null +++ b/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(); +}}; + diff --git a/test/WebJobs.Script.Tests/FileTraceWriterTests.cs b/test/WebJobs.Script.Tests/FileTraceWriterTests.cs index e6fb3f398a..17d0ae7e4b 100644 --- a/test/WebJobs.Script.Tests/FileTraceWriterTests.cs +++ b/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(); } } } diff --git a/test/WebJobs.Script.Tests/ScriptHostTests.cs b/test/WebJobs.Script.Tests/ScriptHostTests.cs index a68bb75bad..31b48d78fb 100644 --- a/test/WebJobs.Script.Tests/ScriptHostTests.cs +++ b/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 functions = new Collection(); + 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()); + 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()); + 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); + } } }