public void Call_WhenMethodThrows_PreservesStackTrace()
{
try
{
// Arrange
InvalidOperationException expectedException = new InvalidOperationException();
ExceptionDispatchInfo expectedExceptionInfo = CreateExceptionInfo(expectedException);
string expectedStackTrace = expectedExceptionInfo.SourceException.StackTrace;
ThrowingProgram.ExceptionInfo = expectedExceptionInfo;
var host = JobHostFactory.Create <ThrowingProgram>(null);
MethodInfo methodInfo = typeof(ThrowingProgram).GetMethod("Throw");
// Act & Assert
FunctionInvocationException exception = Assert.Throws <FunctionInvocationException>(
() => host.Call(methodInfo));
Assert.Same(exception.InnerException, expectedException);
Assert.NotNull(exception.InnerException.StackTrace);
Assert.True(exception.InnerException.StackTrace.StartsWith(expectedStackTrace));
}
finally
{
ThrowingProgram.ExceptionInfo = null;
}
}
public void FunctionFailures_LogsExpectedTraceEvent()
{
TestTraceWriter trace = new TestTraceWriter(TraceLevel.Verbose);
_hostConfig.Tracing.Tracers.Add(trace);
JobHost host = new JobHost(_hostConfig);
MethodInfo methodInfo = GetType().GetMethod("AlwaysFailJob");
try
{
host.Call(methodInfo);
}
catch {}
// We expect 3 error messages total
TraceEvent[] traceErrors = trace.Traces.Where(p => p.Level == TraceLevel.Error).ToArray();
Assert.Equal(3, traceErrors.Length);
// Ensure that all errors include the same exception, with function
// invocation details
FunctionInvocationException functionException = traceErrors.First().Exception as FunctionInvocationException;
Assert.NotNull(functionException);
Assert.NotEqual(Guid.Empty, functionException.InstanceId);
Assert.Equal(string.Format("{0}.{1}", methodInfo.DeclaringType.FullName, methodInfo.Name), functionException.MethodName);
Assert.True(traceErrors.All(p => functionException == p.Exception));
}
public void CreateTraceMonitor_FunctionErrorHandler()
{
ParameterInfo parameter = typeof(Functions).GetMethod("TestErrorHandler").GetParameters()[0];
TraceMonitor traceMonitor = ErrorTriggerListener.CreateTraceMonitor(parameter, _mockExecutor.Object);
TraceFilter.AnonymousTraceFilter traceFilter = (TraceFilter.AnonymousTraceFilter)traceMonitor.Filters.Single();
Assert.Equal("Function 'Functions.Test' failed.", traceFilter.Message);
// first log a function exception for a *different* function
// don't expect it to pass filter
FunctionInvocationException functionException = new FunctionInvocationException("Function failed", new Exception("Kaboom!"))
{
MethodName = "Microsoft.Azure.WebJobs.Extensions.Tests.Core.ErrorTriggerListenerTests+Functions.Foo"
};
TraceEvent traceEvent = new TraceEvent(TraceLevel.Error, "Kaboom!", null, functionException);
traceMonitor.Trace(traceEvent);
Assert.Equal(0, traceFilter.GetEvents().Count());
functionException = new FunctionInvocationException("Function failed", new Exception("Kaboom!"))
{
MethodName = "Microsoft.Azure.WebJobs.Extensions.Tests.Core.ErrorTriggerListenerTests+Functions.Test"
};
traceEvent = new TraceEvent(TraceLevel.Error, "Kaboom!", null, functionException);
traceMonitor.Trace(traceEvent);
Assert.Equal(1, traceFilter.GetEvents().Count());
Assert.Same(functionException, traceFilter.GetEvents().Single().Exception);
}
public void LogFunctionResult_Failed_SendsCorrectTelemetry()
{
var result = CreateDefaultInstanceLogEntry();
FunctionInvocationException fex = new FunctionInvocationException("Failed");
ILogger logger = CreateLogger(LogCategories.Results);
using (logger.BeginFunctionScope(CreateFunctionInstance(_invocationId)))
{
logger.LogFunctionResult(_functionShortName, result, TimeSpan.FromMilliseconds(durationMs), fex);
}
// Errors log an associated Exception
RequestTelemetry requestTelemetry = _channel.Telemetries.OfType <RequestTelemetry>().Single();
ExceptionTelemetry exceptionTelemetry = _channel.Telemetries.OfType <ExceptionTelemetry>().Single();
Assert.Equal(2, _channel.Telemetries.Count);
Assert.Equal(_invocationId.ToString(), requestTelemetry.Id);
Assert.Equal(_invocationId.ToString(), requestTelemetry.Context.Operation.Id);
Assert.Equal(_functionShortName, requestTelemetry.Name);
Assert.Equal(_functionShortName, requestTelemetry.Context.Operation.Name);
Assert.Equal(defaultIp, requestTelemetry.Context.Location.Ip);
// TODO: Beef up validation to include properties
// Exception needs to have associated id
Assert.Equal(_invocationId.ToString(), exceptionTelemetry.Context.Operation.Id);
Assert.Equal(_functionShortName, exceptionTelemetry.Context.Operation.Name);
Assert.Same(fex, exceptionTelemetry.Exception);
// TODO: Beef up validation to include properties
}
public void CreateTraceMonitor_FunctionErrorHandler_CustomFilterType()
{
ParameterInfo parameter = typeof(Functions).GetMethod("Test2ErrorHandler").GetParameters()[0];
TraceMonitor traceMonitor = ErrorTriggerListener.CreateTraceMonitor(parameter, _mockExecutor.Object);
ErrorTriggerListener.CompositeTraceFilter traceFilter = (ErrorTriggerListener.CompositeTraceFilter)traceMonitor.Filters.Single();
Assert.NotNull(traceFilter);
Assert.Equal(typeof(Functions.CustomTraceFilter), traceFilter.InnerTraceFilter.GetType());
// first log a function exception for a *different* function
// don't expect it to pass filter
FunctionInvocationException functionException = new FunctionInvocationException("Function failed", Guid.Empty,
"Microsoft.Azure.WebJobs.Extensions.Tests.Core.ErrorTriggerListenerTests+Functions.Foo", new Exception("Kaboom!"));
TraceEvent traceEvent = new TraceEvent(TraceLevel.Error, "Kaboom!", null, functionException);
traceMonitor.Trace(traceEvent);
Assert.Equal(0, traceFilter.GetEvents().Count());
functionException = new FunctionInvocationException("Function failed", Guid.Empty,
"Microsoft.Azure.WebJobs.Extensions.Tests.Core.ErrorTriggerListenerTests+Functions.Test2", new Exception("Kaboom!"));
traceEvent = new TraceEvent(TraceLevel.Error, "Kaboom!", null, functionException);
traceMonitor.Trace(traceEvent);
Assert.Equal(1, traceFilter.GetEvents().Count());
Assert.Same(functionException, traceFilter.GetEvents().Single().Exception);
}
public void LogFunctionResult_Failed_CreatesCorrectState()
{
int logCount = 0;
ILogger logger = CreateMockLogger <FormattedLogValuesCollection>((l, e, o, ex, f) =>
{
logCount++;
Assert.Equal(LogLevel.Error, l);
Assert.Equal(0, e);
Assert.NotNull(ex);
Assert.IsType <FunctionInvocationException>(ex);
Assert.Equal($"Executed '{_functionFullName}' (Failed, Id={_invocationId})", f(o, ex));
var payload = VerifyResultDefaultsAndConvert(o);
Assert.False((bool)payload[LoggingKeys.Succeeded]);
Assert.Equal("Executed '{FullName}' (Failed, Id={InvocationId})", payload[LoggingKeys.OriginalFormat]);
});
var result = CreateDefaultInstanceLogEntry();
var fex = new FunctionInvocationException("Failed");
logger.LogFunctionResult(_functionShortName, result, TimeSpan.FromMilliseconds(450), fex);
Assert.Equal(1, logCount);
}
public async Task GlobalErrorHandler_SlidingWindow_InvokedAsExpected()
{
ErrorTriggerProgram_GlobalSlidingWindowHandler instance = new ErrorTriggerProgram_GlobalSlidingWindowHandler();
JobHostConfiguration config = new JobHostConfiguration()
{
TypeLocator = new ExplicitTypeLocator(instance.GetType()),
JobActivator = new ExplicitJobActivator(instance)
};
config.UseCore();
JobHost host = new JobHost(config);
await host.StartAsync();
MethodInfo method = instance.GetType().GetMethod("Throw");
await CallSafe(host, method);
await CallSafe(host, method);
Assert.Null(instance.TraceFilter);
await CallSafe(host, method);
Assert.NotNull(instance.TraceFilter);
Assert.Equal("3 events at level 'Error' or lower have occurred within time window 00:05:00.", instance.TraceFilter.Message);
Assert.Equal(3, instance.TraceFilter.Events.Count);
foreach (TraceEvent traceEvent in instance.TraceFilter.Events)
{
FunctionInvocationException functionException = (FunctionInvocationException)traceEvent.Exception;
Assert.Equal("Kaboom!", functionException.InnerException.Message);
Assert.Equal("Microsoft.Azure.WebJobs.Extensions.Tests.Core.ErrorTriggerEndToEndTests+ErrorTriggerProgram_GlobalSlidingWindowHandler.Throw", functionException.MethodName);
}
}
public void QueueTrigger_WithNonTextualByteArrayMessageUsingQueueTriggerBindingData_Throws()
{
try
{
// Arrange
var host = JobHostFactory.Create <QueueTriggerBindingDataProgram>(
CloudStorageAccount.DevelopmentStorageAccount);
MethodInfo methodInfo = typeof(QueueTriggerBindingDataProgram).GetMethod("OnQueue");
byte[] contents = new byte[] { 0x00, 0xFF }; // Not valid UTF-8
CloudQueueMessage message = new CloudQueueMessage(contents);
// Act & Assert
FunctionInvocationException exception = Assert.Throws <FunctionInvocationException>(
() => host.Call(methodInfo, new { message = message }));
// This exeption shape/message could be better, but it's meets a minimum acceptibility threshold.
Assert.Equal("Exception binding parameter 'queueTrigger'", exception.InnerException.Message);
Exception innerException = exception.InnerException.InnerException;
Assert.IsType <InvalidOperationException>(innerException);
Assert.Equal("Binding data does not contain expected value 'queueTrigger'.", innerException.Message);
}
finally
{
QueueTriggerBindingDataProgram.QueueTrigger = null;
}
}
private void HandleHostError(Microsoft.Azure.WebJobs.Extensions.TraceFilter traceFilter)
{
foreach (TraceEvent traceEvent in traceFilter.Events)
{
if (traceEvent.Exception is FunctionInvocationException)
{
// 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);
}
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;
}
}
}
private bool ShouldIgnore(TraceEvent traceEvent)
{
if (traceEvent.Exception != null)
{
FunctionInvocationException functionException = traceEvent.Exception as FunctionInvocationException;
if (functionException != null && ErrorTriggerListener.ErrorHandlers.Contains(functionException.MethodName))
{
// We ignore any errors coming from error handlers themselves to prevent
// infinite recursion
return(true);
}
// often we may see multiple sequential error messages for the same
// exception, so we want to skip the duplicates
bool isDuplicate = object.ReferenceEquals(_lastException, traceEvent.Exception);
if (isDuplicate)
{
return(true);
}
_lastException = traceEvent.Exception;
}
return(false);
}
public async Task QueueTrigger_WithNonTextualByteArrayMessageUsingQueueTriggerBindingData_Throws()
{
try
{
// Arrange
var host = new HostBuilder()
.ConfigureDefaultTestHost <QueueTriggerBindingDataProgram>(c =>
{
c.AddAzureStorage();
})
.Build()
.GetJobHost();
using (host)
{
MethodInfo methodInfo = typeof(QueueTriggerBindingDataProgram).GetMethod(nameof(QueueTriggerBindingDataProgram.OnQueue));
byte[] contents = new byte[] { 0x00, 0xFF }; // Not valid UTF-8
CloudQueueMessage message = CloudQueueMessage.CreateCloudQueueMessageFromByteArray(contents);
// Act & Assert
FunctionInvocationException exception = await Assert.ThrowsAsync <FunctionInvocationException>(
() => host.CallAsync(methodInfo, new { message = message }));
// This exeption shape/message could be better, but it's meets a minimum acceptibility threshold.
Assert.Equal("Exception binding parameter 'queueTrigger'", exception.InnerException.Message);
Exception innerException = exception.InnerException.InnerException;
Assert.IsType <InvalidOperationException>(innerException);
Assert.Equal("Binding data does not contain expected value 'queueTrigger'.", innerException.Message);
}
}
finally
{
QueueTriggerBindingDataProgram.QueueTrigger = null;
}
}
public void FileLogger_LogsFunctionInvocationException()
{
var logger = new FileLogger(_category, _fileWriter, () => true, isPrimary: () => true, logType: LogType.Host);
// throw an exception so we have a stack
try
{
var innerEx = new InvalidOperationException("boom!");
var ex = new FunctionInvocationException("Error executing function.", innerEx);
throw ex;
}
catch (Exception ex)
{
logger.LogError(ex, "Test Message");
}
_fileWriter.Flush();
string logFile = Directory.EnumerateFiles(_logFilePath).Single();
string[] lines = File.ReadAllLines(logFile);
// A FunctionInvocationException only logs the message.
Assert.Collection(lines,
t => Assert.EndsWith("[Error] Test Message", t),
t => Assert.Equal("boom!", t));
}
public async Task Invoke_HandlesFunctionInvocationExceptions()
{
var ex = new FunctionInvocationException("Kaboom!");
using (var server = GetTestServer(_ => throw ex))
{
var client = server.CreateClient();
HttpResponseMessage response = await client.GetAsync(string.Empty);
Assert.Equal(StatusCodes.Status500InternalServerError, (int)response.StatusCode);
Assert.Null(_loggerProvider.GetAllLogMessages().SingleOrDefault(p => p.Category.Contains(nameof(ExceptionMiddleware))));
}
}
public async Task Publish_NoTopicSpecified()
{
// No topic is specified
var input = new DaprPubSubEvent("Hello, world!");
FunctionInvocationException error = await Assert.ThrowsAsync <FunctionInvocationException>(() =>
this.CallFunctionAsync(nameof(Functions.DaprPubSubEventReturnValueAnyTopic), "input", input));
// The exception message should reflect the fact that no topic was specified
ArgumentException innerError = Assert.IsType <ArgumentException>(error.GetBaseException());
Assert.Contains("No topic", innerError.Message);
// No requests should have been sent
Assert.Empty(this.GetDaprRequests());
}
public async Task Invoke_HandlesFunctionInvocationExceptions()
{
var ex = new FunctionInvocationException("Kaboom!");
RequestDelegate next = (ctxt) =>
{
throw ex;
};
var middleware = new ExceptionMiddleware(next, _logger);
var context = new DefaultHttpContext();
await middleware.Invoke(context);
Assert.Equal(StatusCodes.Status500InternalServerError, context.Response.StatusCode);
Assert.Empty(_loggerProvider.GetAllLogMessages());
}
public async Task SendMessage_NoOperationSpecified()
{
// No operation is specified in the attribute or in the message
var input = new DaprBindingMessage("Hello, world!", new Dictionary <string, object> {
{ "key", "myKey" }
}, binding: "bindingName");
FunctionInvocationException error = await Assert.ThrowsAsync <FunctionInvocationException>(() =>
this.CallFunctionAsync(nameof(Functions.DaprConnectorReturnValueAnyMessage), "input", input));
// The exception message should reflect the fact that no operation was specified
ArgumentException innerError = Assert.IsType <ArgumentException>(error.GetBaseException());
Assert.Contains("A non-null operation must be specified", innerError.Message);
// No requests should have been sent
Assert.Empty(this.GetDaprRequests());
}
/// <summary>
/// Set up monitoring + notifications for WebJob errors. This shows how to set things up
/// manually on startup. You can also use <see cref="ErrorTriggerAttribute"/> to designate
/// error handler functions.
/// </summary>
private static void ConfigureTraceMonitor(JobHostConfiguration config, SendGridConfiguration sendGridConfiguration)
{
var notifier = new ErrorNotifier(sendGridConfiguration);
var traceMonitor = new TraceMonitor()
.Filter(new SlidingWindowTraceFilter(TimeSpan.FromMinutes(5), 3))
.Filter(p =>
{
FunctionInvocationException functionException = p.Exception as FunctionInvocationException;
return(p.Level == TraceLevel.Error && functionException != null &&
functionException.MethodName == "ExtensionsSample.FileSamples.ImportFile");
}, "ImportFile Job Failed")
.Subscribe(notifier.WebNotify, notifier.EmailNotify)
.Throttle(TimeSpan.FromMinutes(30));
config.Tracing.Tracers.Add(traceMonitor);
}
private void HandleHostError(Exception exception)
{
if (exception == null)
{
throw new ArgumentNullException("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("A 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))
{
NotifyInvoker(function.Name, exception);
}
}
}
public void LogFunctionResult_Failed_SendsCorrectTelemetry()
{
FunctionInvocationException fex = new FunctionInvocationException("Failed");
var result = CreateDefaultInstanceLogEntry(fex);
ILogger logger = CreateLogger(LogCategories.Results);
string expectedOperationId, expectedRequestId;
using (logger.BeginFunctionScope(CreateFunctionInstance(_invocationId), _hostInstanceId))
{
expectedRequestId = Activity.Current.Id;
expectedOperationId = Activity.Current.RootId;
logger.LogFunctionResult(result);
}
// Errors log an associated Exception
RequestTelemetry requestTelemetry = _channel.Telemetries.OfType <RequestTelemetry>().Single();
ExceptionTelemetry exceptionTelemetry = _channel.Telemetries.OfType <ExceptionTelemetry>().Single();
Assert.Equal(2, _channel.Telemetries.Count);
Assert.Equal(expectedRequestId, requestTelemetry.Id);
Assert.Equal(expectedOperationId, requestTelemetry.Context.Operation.Id);
Assert.Null(requestTelemetry.Context.Operation.ParentId);
Assert.Equal(_functionShortName, requestTelemetry.Name);
Assert.Equal(_functionShortName, requestTelemetry.Context.Operation.Name);
Assert.Equal(defaultIp, requestTelemetry.Context.Location.Ip);
Assert.Contains(LogConstants.InvocationIdKey, requestTelemetry.Properties.Keys);
Assert.Equal(_invocationId.ToString(), requestTelemetry.Properties[LogConstants.InvocationIdKey]);
Assert.Equal(LogCategories.Results, requestTelemetry.Properties[LogConstants.CategoryNameKey]);
Assert.Equal(LogLevel.Error.ToString(), requestTelemetry.Properties[LogConstants.LogLevelKey]);
// TODO: Beef up validation to include properties
// Exception needs to have associated id
Assert.Equal(expectedOperationId, exceptionTelemetry.Context.Operation.Id);
Assert.Equal(expectedRequestId, exceptionTelemetry.Context.Operation.ParentId);
Assert.Equal(_functionShortName, exceptionTelemetry.Context.Operation.Name);
Assert.Same(fex, exceptionTelemetry.Exception);
Assert.Equal(LogCategories.Results, exceptionTelemetry.Properties[LogConstants.CategoryNameKey]);
Assert.Equal(LogLevel.Error.ToString(), exceptionTelemetry.Properties[LogConstants.LogLevelKey]);
// TODO: Beef up validation to include properties
}
private void HandleHostError(Exception exception)
{
if (exception == null)
{
throw new ArgumentNullException("exception");
}
// Note: We do not log to ILogger here as any error has already been logged.
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 || exception is FunctionListenerException)
{
// For all startup time indexing/listener errors, we accumulate them per function
FunctionException functionException = exception as FunctionException;
string formattedError = Utility.FlattenException(functionException);
Utility.AddFunctionError(FunctionErrors, functionException.MethodName, formattedError);
// Also notify the invoker so the error can also be written to the function
// log file
NotifyInvoker(functionException.MethodName, functionException);
}
else if (exception is LanguageWorkerChannelException)
{
AddLanguageWorkerChannelErrors(_functionDispatcher, FunctionErrors);
}
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.
if (TryGetFunctionFromException(Functions, exception, out FunctionDescriptor function))
{
NotifyInvoker(function.Name, exception);
}
}
}
public void FunctionFailures_LogsExpectedTraceEvent()
{
TestTraceWriter trace = new TestTraceWriter(TraceLevel.Verbose);
_hostConfig.Tracing.Tracers.Add(trace);
JobHost host = new JobHost(_hostConfig);
MethodInfo methodInfo = GetType().GetMethod("AlwaysFailJob");
try
{
host.Call(methodInfo);
}
catch { }
string expectedName = $"{methodInfo.DeclaringType.FullName}.{methodInfo.Name}";
// Validate TraceWriter
// We expect 3 error messages total
TraceEvent[] traceErrors = trace.Traces.Where(p => p.Level == TraceLevel.Error).ToArray();
Assert.Equal(3, traceErrors.Length);
// Ensure that all errors include the same exception, with function
// invocation details
FunctionInvocationException functionException = traceErrors.First().Exception as FunctionInvocationException;
Assert.NotNull(functionException);
Assert.NotEqual(Guid.Empty, functionException.InstanceId);
Assert.Equal(expectedName, functionException.MethodName);
Assert.True(traceErrors.All(p => functionException == p.Exception));
// Validate Logger
// Logger only writes out a single log message (which includes the Exception).
var logger = _loggerProvider.CreatedLoggers.Where(l => l.Category == LogCategories.Results).Single();
var logMessage = logger.LogMessages.Single();
var loggerException = logMessage.Exception as FunctionException;
Assert.NotNull(loggerException);
Assert.Equal(expectedName, loggerException.MethodName);
}
public void LogFunctionResult_Failed_CreatesCorrectState()
{
int logCount = 0;
ILogger logger = CreateMockLogger <IDictionary <string, object> >((l, e, o, ex, f) =>
{
logCount++;
Assert.Equal(LogLevel.Error, l);
Assert.Equal(0, e);
Assert.NotNull(ex);
Assert.IsType <FunctionInvocationException>(ex);
Assert.Null(f(o, ex));
var payload = VerifyResultDefaultsAndConvert(o);
Assert.False((bool)payload[LogConstants.SucceededKey]);
});
var fex = new FunctionInvocationException("Failed");
var result = CreateDefaultInstanceLogEntry(fex);
logger.LogFunctionResult(result);
Assert.Equal(1, logCount);
}
public void LogFunctionResult_Failed_SendsCorrectTelemetry()
{
FunctionInvocationException fex = new FunctionInvocationException("Failed");
var result = CreateDefaultInstanceLogEntry(fex);
ILogger logger = CreateLogger(LogCategories.Results);
using (logger.BeginFunctionScope(CreateFunctionInstance(_invocationId), _hostInstanceId))
{
logger.LogFunctionResult(result);
}
// Errors log an associated Exception
RequestTelemetry requestTelemetry = _channel.Telemetries.OfType <RequestTelemetry>().Single();
ExceptionTelemetry exceptionTelemetry = _channel.Telemetries.OfType <ExceptionTelemetry>().Single();
Assert.Equal(2, _channel.Telemetries.Count);
Assert.Equal(_invocationId.ToString(), requestTelemetry.Id);
Assert.Equal(_invocationId.ToString(), requestTelemetry.Context.Operation.Id);
Assert.Equal(_functionShortName, requestTelemetry.Name);
Assert.Equal(_functionShortName, requestTelemetry.Context.Operation.Name);
Assert.Equal(defaultIp, requestTelemetry.Context.Location.Ip);
Assert.Equal(LogCategories.Results, requestTelemetry.Properties[LogConstants.CategoryNameKey]);
Assert.Equal(LogLevel.Error.ToString(), requestTelemetry.Properties[LogConstants.LogLevelKey]);
// TODO: Beef up validation to include properties
// Starting the telemetry prefixes/postfixes values to the request id, but the original guid is there
Assert.Equal(_invocationId.ToString(), requestTelemetry.Id);
// Exception needs to have associated id
Assert.Equal(_invocationId.ToString(), exceptionTelemetry.Context.Operation.Id);
Assert.Equal(_functionShortName, exceptionTelemetry.Context.Operation.Name);
Assert.Same(fex, exceptionTelemetry.Exception);
Assert.Equal(LogCategories.Results, exceptionTelemetry.Properties[LogConstants.CategoryNameKey]);
Assert.Equal(LogLevel.Error.ToString(), exceptionTelemetry.Properties[LogConstants.LogLevelKey]);
// TODO: Beef up validation to include properties
}
internal static TraceMonitor CreateTraceMonitor(ParameterInfo parameter, ITriggeredFunctionExecutor executor)
{
ErrorTriggerAttribute attribute = parameter.GetCustomAttribute <ErrorTriggerAttribute>(inherit: false);
// Determine whether this is a method level filter, and if so, create the filter
Func <TraceEvent, bool> methodFilter = null;
MethodInfo method = (MethodInfo)parameter.Member;
string functionLevelMessage = null;
if (method.Name.EndsWith(ErrorHandlerSuffix, StringComparison.OrdinalIgnoreCase))
{
string sourceMethodName = method.Name.Substring(0, method.Name.Length - ErrorHandlerSuffix.Length);
MethodInfo sourceMethod = method.DeclaringType.GetMethod(sourceMethodName);
if (sourceMethod != null)
{
string sourceMethodFullName = string.Format("{0}.{1}", method.DeclaringType.FullName, sourceMethod.Name);
methodFilter = p =>
{
FunctionInvocationException functionException = p.Exception as FunctionInvocationException;
return(p.Level == System.Diagnostics.TraceLevel.Error && functionException != null &&
string.Compare(functionException.MethodName, sourceMethodFullName, StringComparison.OrdinalIgnoreCase) == 0);
};
string sourceMethodShortName = string.Format("{0}.{1}", method.DeclaringType.Name, sourceMethod.Name);
functionLevelMessage = string.Format("Function '{0}' failed.", sourceMethodShortName);
}
}
string errorHandlerFullName = string.Format("{0}.{1}", method.DeclaringType.FullName, method.Name);
ErrorHandlers.Add(errorHandlerFullName);
// Create the TraceFilter instance
TraceFilter traceFilter = null;
if (attribute.FilterType != null)
{
if (methodFilter != null)
{
TraceFilter innerTraceFilter = (TraceFilter)Activator.CreateInstance(attribute.FilterType);
traceFilter = new CompositeTraceFilter(innerTraceFilter, methodFilter, attribute.Message ?? functionLevelMessage);
}
else
{
traceFilter = (TraceFilter)Activator.CreateInstance(attribute.FilterType);
}
}
else if (!string.IsNullOrEmpty(attribute.Window))
{
TimeSpan window = TimeSpan.Parse(attribute.Window);
traceFilter = new SlidingWindowTraceFilter(window, attribute.Threshold, methodFilter, attribute.Message);
}
else
{
traceFilter = TraceFilter.Create(methodFilter, attribute.Message ?? functionLevelMessage);
}
TraceMonitor traceMonitor = new TraceMonitor().Filter(traceFilter);
// Apply any additional monitor options
if (!string.IsNullOrEmpty(attribute.Throttle))
{
TimeSpan throttle = TimeSpan.Parse(attribute.Throttle);
traceMonitor.Throttle(throttle);
}
// Subscribe the error handler function to the error stream
traceMonitor.Subscribe(p =>
{
TriggeredFunctionData triggerData = new TriggeredFunctionData
{
TriggerValue = p
};
Task <FunctionResult> task = executor.TryExecuteAsync(triggerData, CancellationToken.None);
task.Wait();
});
return(traceMonitor);
}
private async Task <string> ExecuteWithLogMessageAsync(IFunctionInstance instance, FunctionStartedMessage message,
IDictionary <string, ParameterLog> parameterLogCollector, CancellationToken cancellationToken)
{
string startedMessageId;
// Create the console output writer
IFunctionOutputDefinition outputDefinition = await _functionOutputLogger.CreateAsync(instance, cancellationToken);
// Create a linked token source that will allow us to signal function cancellation
// (e.g. Based on TimeoutAttribute, etc.)
CancellationTokenSource functionCancellationTokenSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken);
using (IFunctionOutput outputLog = await outputDefinition.CreateOutputAsync(cancellationToken))
using (ITaskSeriesTimer updateOutputLogTimer = StartOutputTimer(outputLog.UpdateCommand, _backgroundExceptionDispatcher))
using (functionCancellationTokenSource)
{
// We create a new composite trace writer that will also forward
// output to the function output log (in addition to console, user TraceWriter, etc.).
TraceWriter traceWriter = new CompositeTraceWriter(_trace, outputLog.Output);
FunctionBindingContext functionContext = new FunctionBindingContext(instance.Id, functionCancellationTokenSource.Token, traceWriter);
// Must bind before logging (bound invoke string is included in log message).
IReadOnlyDictionary <string, IValueProvider> parameters =
await instance.BindingSource.BindAsync(new ValueBindingContext(functionContext, cancellationToken));
ExceptionDispatchInfo exceptionInfo;
using (ValueProviderDisposable.Create(parameters))
{
startedMessageId = await LogFunctionStartedAsync(message, outputDefinition, parameters, cancellationToken);
try
{
await ExecuteWithOutputLogsAsync(instance, parameters, traceWriter, outputDefinition, parameterLogCollector, functionCancellationTokenSource);
exceptionInfo = null;
}
catch (OperationCanceledException exception)
{
exceptionInfo = ExceptionDispatchInfo.Capture(exception);
}
catch (Exception exception)
{
string errorMessage = string.Format("Exception while executing function: {0}", instance.FunctionDescriptor.ShortName);
FunctionInvocationException functionException = new FunctionInvocationException(errorMessage, instance.Id, instance.FunctionDescriptor.FullName, exception);
traceWriter.Error(errorMessage, functionException, TraceSource.Execution);
exceptionInfo = ExceptionDispatchInfo.Capture(functionException);
}
}
if (exceptionInfo == null && updateOutputLogTimer != null)
{
await updateOutputLogTimer.StopAsync(cancellationToken);
}
// after all execution is complete, flush the TraceWriter
traceWriter.Flush();
// We save the exception info rather than doing throw; above to ensure we always write console output,
// even if the function fails or was canceled.
await outputLog.SaveAndCloseAsync(cancellationToken);
if (exceptionInfo != null)
{
// release any held singleton lock immediately
SingletonLock singleton = null;
if (TryGetSingletonLock(parameters, out singleton) && singleton.IsHeld)
{
await singleton.ReleaseAsync(cancellationToken);
}
exceptionInfo.Throw();
}
return(startedMessageId);
}
}
private async Task <string> ExecuteWithLoggingAsync(IFunctionInstance instance, FunctionStartedMessage message,
FunctionInstanceLogEntry fastItem,
IDictionary <string, ParameterLog> parameterLogCollector, TraceLevel functionTraceLevel, CancellationToken cancellationToken)
{
IFunctionOutputDefinition outputDefinition = null;
IFunctionOutput outputLog = null;
ITaskSeriesTimer updateOutputLogTimer = null;
TextWriter functionOutputTextWriter = null;
Func <Task> initializeOutputAsync = async() =>
{
outputDefinition = await _functionOutputLogger.CreateAsync(instance, cancellationToken);
outputLog = outputDefinition.CreateOutput();
functionOutputTextWriter = outputLog.Output;
updateOutputLogTimer = StartOutputTimer(outputLog.UpdateCommand, _exceptionHandler);
};
if (functionTraceLevel >= TraceLevel.Info)
{
await initializeOutputAsync();
}
try
{
// Create a linked token source that will allow us to signal function cancellation
// (e.g. Based on TimeoutAttribute, etc.)
CancellationTokenSource functionCancellationTokenSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken);
using (functionCancellationTokenSource)
{
// We create a new composite trace writer that will also forward
// output to the function output log (in addition to console, user TraceWriter, etc.).
TraceWriter traceWriter = new CompositeTraceWriter(_trace, functionOutputTextWriter, functionTraceLevel);
// Must bind before logging (bound invoke string is included in log message).
FunctionBindingContext functionContext = new FunctionBindingContext(instance.Id, functionCancellationTokenSource.Token, traceWriter);
var valueBindingContext = new ValueBindingContext(functionContext, cancellationToken);
var parameters = await instance.BindingSource.BindAsync(valueBindingContext);
Exception invocationException = null;
ExceptionDispatchInfo exceptionInfo = null;
string startedMessageId = null;
using (ValueProviderDisposable.Create(parameters))
{
if (functionTraceLevel >= TraceLevel.Info)
{
startedMessageId = await LogFunctionStartedAsync(message, outputDefinition, parameters, cancellationToken);
}
if (_fastLogger != null)
{
// Log started
fastItem.Arguments = message.Arguments;
await _fastLogger.AddAsync(fastItem);
}
try
{
await ExecuteWithLoggingAsync(instance, parameters, traceWriter, outputDefinition, parameterLogCollector, functionTraceLevel, functionCancellationTokenSource);
}
catch (Exception ex)
{
invocationException = ex;
}
}
if (invocationException != null)
{
if (outputDefinition == null)
{
// In error cases, even if logging is disabled for this function, we want to force
// log errors. So we must delay initialize logging here
await initializeOutputAsync();
startedMessageId = await LogFunctionStartedAsync(message, outputDefinition, parameters, cancellationToken);
}
// In the event of cancellation or timeout, we use the original exception without additional logging.
if (invocationException is OperationCanceledException || invocationException is FunctionTimeoutException)
{
exceptionInfo = ExceptionDispatchInfo.Capture(invocationException);
}
else
{
string errorMessage = string.Format("Exception while executing function: {0}", instance.FunctionDescriptor.ShortName);
FunctionInvocationException fex = new FunctionInvocationException(errorMessage, instance.Id, instance.FunctionDescriptor.FullName, invocationException);
traceWriter.Error(errorMessage, fex, TraceSource.Execution);
exceptionInfo = ExceptionDispatchInfo.Capture(fex);
}
}
if (exceptionInfo == null && updateOutputLogTimer != null)
{
await updateOutputLogTimer.StopAsync(cancellationToken);
}
// after all execution is complete, flush the TraceWriter
traceWriter.Flush();
// We save the exception info above rather than throwing to ensure we always write
// console output even if the function fails or was canceled.
if (outputLog != null)
{
await outputLog.SaveAndCloseAsync(fastItem, cancellationToken);
}
if (exceptionInfo != null)
{
// release any held singleton lock immediately
SingletonLock singleton = null;
if (TryGetSingletonLock(parameters, out singleton) && singleton.IsHeld)
{
await singleton.ReleaseAsync(cancellationToken);
}
exceptionInfo.Throw();
}
return(startedMessageId);
}
}
finally
{
if (outputLog != null)
{
((IDisposable)outputLog).Dispose();
}
if (updateOutputLogTimer != null)
{
((IDisposable)updateOutputLogTimer).Dispose();
}
}
}
