private void EndFunction(FunctionInstanceLogEntry item)
{
item.Properties.TryGetValue(Key, out (FunctionStartedEvent, object)invocationTuple);
bool success = item.ErrorDetails == null;
var startedEvent = invocationTuple.Item1;
startedEvent.Success = success;
var function = startedEvent.FunctionMetadata;
string eventName = success ? MetricEventNames.FunctionInvokeSucceeded : MetricEventNames.FunctionInvokeFailed;
string functionName = function != null ? function.Name : string.Empty;
string data = string.Format(Microsoft.Azure.WebJobs.Script.Properties.Resources.FunctionInvocationMetricsData, startedEvent.FunctionMetadata.Language, functionName, success, Stopwatch.IsHighResolution);
_metrics.LogEvent(eventName, startedEvent.FunctionName, data);
startedEvent.Data = data;
_metrics.EndEvent(startedEvent);
var invokeLatencyEvent = invocationTuple.Item2;
if (invokeLatencyEvent is MetricEvent metricEvent)
{
metricEvent.Data = data;
}
_metrics.EndEvent(invokeLatencyEvent);
}
// Called on success and failure
public void End(bool success)
{
startedEvent.Success = success;
string eventName = success ? MetricEventNames.FunctionInvokeSucceeded : MetricEventNames.FunctionInvokeFailed;
dynamic data = new JObject();
data.Language = startedEvent.FunctionMetadata.Language;
data.FunctionName = _metadata != null ? _metadata.Name : string.Empty;
data.Success = success;
string jsonData = data.ToString();
startedEvent.Data = jsonData;
_metrics.LogEvent(eventName, startedEvent.FunctionName, jsonData);
_metrics.EndEvent(startedEvent);
if (invokeLatencyEvent != null)
{
MetricEvent metricEvent = invokeLatencyEvent as MetricEvent;
if (metricEvent != null)
{
metricEvent.Data = jsonData;
}
_metrics.EndEvent(invokeLatencyEvent);
}
}
// Called on success and failure
public void End(bool success)
{
_startedEvent.Success = success;
string eventName = success ? MetricEventNames.FunctionInvokeSucceeded : MetricEventNames.FunctionInvokeFailed;
var data = new JObject
{
["Language"] = _startedEvent.FunctionMetadata.Language,
["FunctionName"] = _metadata != null ? _metadata.Name : string.Empty,
["Success"] = success,
["IsStopwatchHighResolution"] = Stopwatch.IsHighResolution
};
string jsonData = data.ToString();
_startedEvent.Data = jsonData;
_metrics.LogEvent(eventName, _startedEvent.FunctionName, jsonData);
_metrics.EndEvent(_startedEvent);
if (_invokeLatencyEvent is MetricEvent metricEvent)
{
metricEvent.Data = jsonData;
}
_metrics.EndEvent(_invokeLatencyEvent);
}
// Called on success and failure
public void End(bool success)
{
startedEvent.Success = success;
_metrics.EndEvent(startedEvent);
if (invokeLatencyEvent != null)
{
_metrics.EndEvent(invokeLatencyEvent);
}
}
public void Decorator_EndEventWithMetricEvent_Called()
{
Guid invocationId = Guid.NewGuid();
FunctionMetadata meta = new FunctionMetadata();
FunctionStartedEvent evt = new FunctionStartedEvent(invocationId, meta);
_metricsLogger.Setup(a => a.EndEvent(evt));
_metricsLoggerDecorator.EndEvent(evt);
_metricsLogger.Verify(a => a.EndEvent(evt), Times.Once());
_metricsLogger.Reset();
}
// Called on success and failure
public void End(bool success)
{
_logInfo.LogFunctionResult(success, _invocationId.ToString(), _invocationStopWatch.ElapsedMilliseconds);
startedEvent.Success = success;
_metrics.EndEvent(startedEvent);
if (invokeLatencyEvent != null)
{
_metrics.EndEvent(invokeLatencyEvent);
}
}
// Called on success and failure
public void End(bool success)
{
startedEvent.Success = success;
string eventName = success ? MetricEventNames.FunctionInvokeSucceeded : MetricEventNames.FunctionInvokeFailed;
_metrics.LogEvent(eventName, startedEvent.FunctionName);
_metrics.EndEvent(startedEvent);
if (invokeLatencyEvent != null)
{
_metrics.EndEvent(invokeLatencyEvent);
}
}
public void Dispose()
{
if (_metricsLogger != null && _metricEvent != null)
{
_metricsLogger.EndEvent(_metricEvent);
}
}
public override async Task Invoke(object[] parameters)
{
// TODO: Refactor common code for providers.
object input = parameters[0];
TraceWriter traceWriter = (TraceWriter)parameters[1];
Binder binder = (Binder)parameters[2];
ExecutionContext functionExecutionContext = (ExecutionContext)parameters[3];
string invocationId = functionExecutionContext.InvocationId.ToString();
FunctionStartedEvent startedEvent = new FunctionStartedEvent(functionExecutionContext.InvocationId, Metadata);
_metrics.BeginEvent(startedEvent);
try
{
TraceWriter.Info(string.Format("Function started (Id={0})", invocationId));
object convertedInput = ConvertInput(input);
ApplyBindingData(convertedInput, binder);
Dictionary <string, object> bindingData = binder.BindingData;
bindingData["InvocationId"] = invocationId;
Dictionary <string, string> environmentVariables = new Dictionary <string, string>();
string functionInstanceOutputPath = Path.Combine(Path.GetTempPath(), "Functions", "Binding", invocationId);
await ProcessInputBindingsAsync(convertedInput, functionInstanceOutputPath, binder, _inputBindings, _outputBindings, bindingData, environmentVariables);
InitializeEnvironmentVariables(environmentVariables, functionInstanceOutputPath, input, _outputBindings, functionExecutionContext);
PSDataCollection <ErrorRecord> errors = await InvokePowerShellScript(environmentVariables, traceWriter);
await ProcessOutputBindingsAsync(functionInstanceOutputPath, _outputBindings, input, binder, bindingData);
if (errors.Any())
{
ErrorRecord error = errors.FirstOrDefault();
if (error != null)
{
throw new RuntimeException("PowerShell script error", error.Exception, error);
}
}
else
{
TraceWriter.Info(string.Format("Function completed (Success, Id={0})", invocationId));
}
}
catch (Exception)
{
startedEvent.Success = false;
TraceWriter.Error(string.Format("Function completed (Failure, Id={0})", invocationId));
throw;
}
finally
{
_metrics.EndEvent(startedEvent);
}
}
// Called on success and failure
public void End(bool success)
{
_startedEvent.Success = success;
string eventName = success ? MetricEventNames.FunctionInvokeSucceeded : MetricEventNames.FunctionInvokeFailed;
string functionName = _metadata != null ? _metadata.Name : string.Empty;
string data = string.Format(Properties.Resources.FunctionInvocationMetricsData, _startedEvent.FunctionMetadata.Language, functionName, success, Stopwatch.IsHighResolution);
_metrics.LogEvent(eventName, _startedEvent.FunctionName, data);
_startedEvent.Data = data;
_metrics.EndEvent(_startedEvent);
if (_invokeLatencyEvent is MetricEvent metricEvent)
{
metricEvent.Data = data;
}
_metrics.EndEvent(_invokeLatencyEvent);
}
public override async Task Invoke(object[] parameters)
{
object input = parameters[0];
TraceWriter traceWriter = (TraceWriter)parameters[1];
IBinderEx binder = (IBinderEx)parameters[2];
ExecutionContext functionExecutionContext = (ExecutionContext)parameters[3];
string invocationId = functionExecutionContext.InvocationId.ToString();
FunctionStartedEvent startedEvent = new FunctionStartedEvent(functionExecutionContext.InvocationId, Metadata);
_metrics.BeginEvent(startedEvent);
try
{
TraceWriter.Verbose(string.Format("Function started (Id={0})", invocationId));
var scriptExecutionContext = CreateScriptExecutionContext(input, traceWriter, TraceWriter, functionExecutionContext);
Dictionary <string, string> bindingData = GetBindingData(input, binder, _inputBindings, _outputBindings);
bindingData["InvocationId"] = invocationId;
scriptExecutionContext["bindingData"] = bindingData;
await ProcessInputBindingsAsync(binder, scriptExecutionContext, bindingData);
object functionResult = await ScriptFunc(scriptExecutionContext);
await ProcessOutputBindingsAsync(_outputBindings, input, binder, bindingData, scriptExecutionContext, functionResult);
TraceWriter.Verbose(string.Format("Function completed (Success, Id={0})", invocationId));
}
catch
{
startedEvent.Success = false;
TraceWriter.Verbose(string.Format("Function completed (Failure, Id={0})", invocationId));
throw;
}
finally
{
_metrics.EndEvent(startedEvent);
}
}
public async Task Invoke(object[] parameters)
{
// We require the ExecutionContext, so this will throw if one is not found.
ExecutionContext functionExecutionContext = parameters.OfType <ExecutionContext>().First();
PopulateExecutionContext(functionExecutionContext);
// These may not be present, so null is okay.
TraceWriter functionTraceWriter = parameters.OfType <TraceWriter>().FirstOrDefault();
Binder binder = parameters.OfType <Binder>().FirstOrDefault();
ILogger logger = parameters.OfType <ILogger>().FirstOrDefault();
string invocationId = functionExecutionContext.InvocationId.ToString();
var startedEvent = new FunctionStartedEvent(functionExecutionContext.InvocationId, Metadata);
_metrics.BeginEvent(startedEvent);
var invokeLatencyEvent = LogInvocationMetrics(_metrics, Metadata);
var invocationStopWatch = new Stopwatch();
invocationStopWatch.Start();
try
{
string startMessage = $"Function started (Id={invocationId})";
TraceWriter.Info(startMessage);
Logger?.LogInformation(startMessage);
FunctionInvocationContext context = new FunctionInvocationContext
{
ExecutionContext = functionExecutionContext,
Binder = binder,
TraceWriter = functionTraceWriter,
Logger = logger
};
await InvokeCore(parameters, context);
invocationStopWatch.Stop();
LogFunctionResult(startedEvent, true, invocationId, invocationStopWatch.ElapsedMilliseconds);
}
catch (AggregateException ex)
{
ExceptionDispatchInfo exInfo = null;
// If there's only a single exception, rethrow it by itself
Exception singleEx = ex.Flatten().InnerExceptions.SingleOrDefault();
if (singleEx != null)
{
exInfo = ExceptionDispatchInfo.Capture(singleEx);
}
else
{
exInfo = ExceptionDispatchInfo.Capture(ex);
}
invocationStopWatch.Stop();
LogFunctionResult(startedEvent, false, invocationId, invocationStopWatch.ElapsedMilliseconds);
exInfo.Throw();
}
catch
{
invocationStopWatch.Stop();
LogFunctionResult(startedEvent, false, invocationId, invocationStopWatch.ElapsedMilliseconds);
throw;
}
finally
{
if (startedEvent != null)
{
_metrics.EndEvent(startedEvent);
}
if (invokeLatencyEvent != null)
{
_metrics.EndEvent(invokeLatencyEvent);
}
}
}
public override async Task Invoke(object[] parameters)
{
FunctionStartedEvent startedEvent = null;
string invocationId = null;
try
{
// Separate system parameters from the actual method parameters
object[] originalParameters = parameters;
MethodInfo function = await GetFunctionTargetAsync();
int actualParameterCount = function.GetParameters().Length;
object[] systemParameters = parameters.Skip(actualParameterCount).ToArray();
parameters = parameters.Take(actualParameterCount).ToArray();
ExecutionContext functionExecutionContext = (ExecutionContext)systemParameters[0];
invocationId = functionExecutionContext.InvocationId.ToString();
startedEvent = new FunctionStartedEvent(functionExecutionContext.InvocationId, Metadata);
_metrics.BeginEvent(startedEvent);
TraceWriter.Info(string.Format("Function started (Id={0})", invocationId));
parameters = ProcessInputParameters(parameters);
object functionResult = function.Invoke(null, parameters);
// after the function executes, we have to copy values back into the original
// array to ensure object references are maintained (since we took a copy above)
for (int i = 0; i < parameters.Length; i++)
{
originalParameters[i] = parameters[i];
}
if (functionResult is Task)
{
functionResult = await((Task)functionResult).ContinueWith(t => GetTaskResult(t));
}
if (functionResult != null)
{
_resultProcessor(function, parameters, systemParameters, functionResult);
}
TraceWriter.Info(string.Format("Function completed (Success, Id={0})", invocationId));
}
catch
{
if (startedEvent != null)
{
startedEvent.Success = false;
TraceWriter.Error(string.Format("Function completed (Failure, Id={0})", invocationId));
}
else
{
TraceWriter.Error("Function completed (Failure)");
}
throw;
}
finally
{
if (startedEvent != null)
{
_metrics.EndEvent(startedEvent);
}
}
}
public void EndEvent(MetricEvent metricEvent)
{
_metricsLogger.EndEvent(metricEvent);
}
internal async Task ExecuteScriptAsync(string path, string arguments, object[] invocationParameters)
{
object input = invocationParameters[0];
TraceWriter traceWriter = (TraceWriter)invocationParameters[1];
Binder binder = (Binder)invocationParameters[2];
ExecutionContext functionExecutionContext = (ExecutionContext)invocationParameters[3];
string invocationId = functionExecutionContext.InvocationId.ToString();
FunctionStartedEvent startedEvent = new FunctionStartedEvent(functionExecutionContext.InvocationId, Metadata);
_metrics.BeginEvent(startedEvent);
try
{
TraceWriter.Info(string.Format("Function started (Id={0})", invocationId));
string workingDirectory = Path.GetDirectoryName(_scriptFilePath);
string functionInstanceOutputPath = Path.Combine(Path.GetTempPath(), "Functions", "Binding", invocationId);
Dictionary <string, string> environmentVariables = new Dictionary <string, string>();
InitializeEnvironmentVariables(environmentVariables, functionInstanceOutputPath, input, _outputBindings, functionExecutionContext);
object convertedInput = ConvertInput(input);
ApplyBindingData(convertedInput, binder);
Dictionary <string, object> bindingData = binder.BindingData;
bindingData["InvocationId"] = invocationId;
await ProcessInputBindingsAsync(convertedInput, functionInstanceOutputPath, binder, _inputBindings, _outputBindings, bindingData, environmentVariables);
// TODO
// - put a timeout on how long we wait?
// - need to periodically flush the standard out to the TraceWriter
Process process = CreateProcess(path, workingDirectory, arguments, environmentVariables);
process.Start();
process.WaitForExit();
string output = process.StandardOutput.ReadToEnd();
TraceWriter.Info(output);
traceWriter.Info(output);
startedEvent.Success = process.ExitCode == 0;
if (!startedEvent.Success)
{
string error = process.StandardError.ReadToEnd();
throw new ApplicationException(error);
}
await ProcessOutputBindingsAsync(functionInstanceOutputPath, _outputBindings, input, binder, bindingData);
TraceWriter.Info(string.Format("Function completed (Success, Id={0})", invocationId));
}
catch
{
startedEvent.Success = false;
TraceWriter.Error(string.Format("Function completed (Failure, Id={0})", invocationId));
throw;
}
finally
{
_metrics.EndEvent(startedEvent);
}
}
public async Task Invoke(object[] parameters)
{
// We require the ExecutionContext, so this will throw if one is not found.
ExecutionContext functionExecutionContext = parameters.OfType <ExecutionContext>().First();
// These may not be present, so null is okay.
TraceWriter functionTraceWriter = parameters.OfType <TraceWriter>().FirstOrDefault();
Binder binder = parameters.OfType <Binder>().FirstOrDefault();
string invocationId = functionExecutionContext.InvocationId.ToString();
FunctionStartedEvent startedEvent = new FunctionStartedEvent(functionExecutionContext.InvocationId, Metadata);
_metrics.BeginEvent(startedEvent);
LogInvocationMetrics(_metrics, Metadata.Bindings);
try
{
TraceWriter.Info($"Function started (Id={invocationId})");
FunctionInvocationContext context = new FunctionInvocationContext
{
ExecutionContext = functionExecutionContext,
Binder = binder,
TraceWriter = functionTraceWriter
};
await InvokeCore(parameters, context);
TraceWriter.Info($"Function completed (Success, Id={invocationId})");
}
catch (AggregateException ex)
{
ExceptionDispatchInfo exInfo = null;
// If there's only a single exception, rethrow it by itself
Exception singleEx = ex.Flatten().InnerExceptions.SingleOrDefault();
if (singleEx != null)
{
exInfo = ExceptionDispatchInfo.Capture(singleEx);
}
else
{
exInfo = ExceptionDispatchInfo.Capture(ex);
}
LogFunctionFailed(startedEvent, "Failure", invocationId);
exInfo.Throw();
}
catch
{
LogFunctionFailed(startedEvent, "Failure", invocationId);
throw;
}
finally
{
if (startedEvent != null)
{
_metrics.EndEvent(startedEvent);
}
}
}
internal async Task ExecuteScriptAsync(string path, string arguments, object[] invocationParameters)
{
object input = invocationParameters[0];
TraceWriter traceWriter = (TraceWriter)invocationParameters[1];
IBinderEx binder = (IBinderEx)invocationParameters[2];
ExecutionContext functionExecutionContext = (ExecutionContext)invocationParameters[3];
string invocationId = functionExecutionContext.InvocationId.ToString();
FunctionStartedEvent startedEvent = new FunctionStartedEvent(functionExecutionContext.InvocationId, Metadata);
_metrics.BeginEvent(startedEvent);
// perform any required input conversions
object convertedInput = input;
if (input != null)
{
HttpRequestMessage request = input as HttpRequestMessage;
if (request != null)
{
// TODO: Handle other content types? (E.g. byte[])
if (request.Content != null && request.Content.Headers.ContentLength > 0)
{
convertedInput = ((HttpRequestMessage)input).Content.ReadAsStringAsync().Result;
}
}
}
TraceWriter.Info(string.Format("Function started (Id={0})", invocationId));
string workingDirectory = Path.GetDirectoryName(_scriptFilePath);
string functionInstanceOutputPath = Path.Combine(Path.GetTempPath(), "Functions", "Binding", invocationId);
Dictionary <string, string> environmentVariables = new Dictionary <string, string>();
InitializeEnvironmentVariables(environmentVariables, functionInstanceOutputPath, input, _outputBindings, functionExecutionContext);
Dictionary <string, string> bindingData = GetBindingData(convertedInput, binder);
bindingData["InvocationId"] = invocationId;
await ProcessInputBindingsAsync(convertedInput, functionInstanceOutputPath, binder, bindingData, environmentVariables);
// TODO
// - put a timeout on how long we wait?
// - need to periodically flush the standard out to the TraceWriter
Process process = CreateProcess(path, workingDirectory, arguments, environmentVariables);
process.Start();
process.WaitForExit();
bool failed = process.ExitCode != 0;
startedEvent.Success = !failed;
_metrics.EndEvent(startedEvent);
if (failed)
{
startedEvent.Success = false;
TraceWriter.Error(string.Format("Function completed (Failure, Id={0})", invocationId));
string error = process.StandardError.ReadToEnd();
throw new ApplicationException(error);
}
string output = process.StandardOutput.ReadToEnd();
TraceWriter.Info(output);
traceWriter.Info(output);
await ProcessOutputBindingsAsync(functionInstanceOutputPath, _outputBindings, input, binder, bindingData);
TraceWriter.Info(string.Format("Function completed (Success, Id={0})", invocationId));
}
