internal void FunctionCompleted(FunctionStartedEvent functionStartedEvent)
{
var functionStage = (functionStartedEvent.Success == false) ? ExecutionStage.Failed : ExecutionStage.Succeeded;
long executionTimeInMS = (long)functionStartedEvent.Duration.TotalMilliseconds;
var monitoringEvent = new FunctionMetrics(functionStartedEvent.FunctionMetadata.Name, functionStage, executionTimeInMS);
_functionMetricsQueue.Enqueue(monitoringEvent);
var key = GetDictionaryKey(functionStartedEvent.FunctionMetadata.Name, functionStartedEvent.InvocationId);
if (_runningFunctions.ContainsKey(key))
{
lock (_functionMetricEventLockObject)
{
if (_runningFunctions.ContainsKey(key))
{
var functionInfo = _runningFunctions[key];
functionInfo.ExecutionStage = ExecutionStage.Finished;
functionInfo.Success = functionStartedEvent.Success;
var endTime = functionStartedEvent.Timestamp + functionStartedEvent.Duration;
functionInfo.EndTime = functionStartedEvent.Timestamp + functionStartedEvent.Duration;
RaiseFunctionMetricEvent(functionInfo, _runningFunctions.Keys.Count, endTime);
_runningFunctions.Remove(key);
}
}
}
}
public void Start()
{
startedEvent = new FunctionStartedEvent(_invocationId, _metadata);
_metrics.BeginEvent(startedEvent);
invokeLatencyEvent = FunctionInvokerBase.LogInvocationMetrics(_metrics, _metadata);
_invocationStopWatch.Start();
}
internal void FunctionStarted(FunctionStartedEvent startedEvent)
{
totalExecutionCount++;
runningFunctionCount++;
var metricEventPerFunction = new FunctionMetrics(startedEvent.FunctionMetadata.Name, ExecutionStage.Started, 0);
functionMetricsQueue.Enqueue(metricEventPerFunction);
}
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);
}
}
private void LogFunctionFailed(FunctionStartedEvent startedEvent, string resultString, string invocationId)
{
if (startedEvent != null)
{
startedEvent.Success = false;
}
TraceWriter.Error($"Function completed ({resultString}, Id={invocationId ?? "0"})");
}
public void EndEvent(MetricEvent metricEvent)
{
FunctionStartedEvent completedEvent = metricEvent as FunctionStartedEvent;
if (completedEvent != null)
{
completedEvent.EndTime = DateTime.Now;
_metricsEventManager.FunctionCompleted(completedEvent);
}
}
public void BeginEvent(MetricEvent metricEvent)
{
FunctionStartedEvent startedEvent = metricEvent as FunctionStartedEvent;
if (startedEvent != null)
{
startedEvent.Timestamp = DateTime.UtcNow;
_metricsEventManager.FunctionStarted(startedEvent);
}
}
public void Decorator_LogEventWithMetricEvent_Called()
{
Guid invocationId = Guid.NewGuid();
FunctionMetadata meta = new FunctionMetadata();
FunctionStartedEvent evt = new FunctionStartedEvent(invocationId, meta);
_metricsLogger.Setup(a => a.LogEvent(evt));
_metricsLoggerDecorator.LogEvent(evt);
_metricsLogger.Verify(a => a.LogEvent(evt), Times.Once());
_metricsLogger.Reset();
}
public static void FunctionStarted(FunctionStartedEvent startedEvent)
{
lock (functionActivityTrackerLockObject)
{
if (instance == null)
{
instance = new FunctionActivityTracker();
}
instance.FunctionStarted(startedEvent);
}
}
private void RaiseFunctionMetricEvent(FunctionStartedEvent runningFunctionInfo, int concurrency, DateTime currentTime)
{
double executionTimespan = 0;
ExecutionStage executionStage;
if (!runningFunctionInfo.Completed)
{
executionStage = ExecutionStage.InProgress;
executionTimespan = (currentTime - runningFunctionInfo.Timestamp).TotalMilliseconds;
}
else
{
// regardless of the actual Failed/Succeeded status, we always raise the final event
// with stage Finished
executionStage = ExecutionStage.Finished;
executionTimespan = runningFunctionInfo.Duration.TotalMilliseconds;
}
// Don't allocate the GUID string twice, though we can probably optimize this further upstream.
var invocationId = runningFunctionInfo.InvocationId.ToString();
MetricsEventGenerator.LogFunctionExecutionEvent(
_executionId,
_appServiceOptions.AppName,
concurrency,
runningFunctionInfo.FunctionMetadata.Name,
invocationId,
executionStage.ToString(),
(long)executionTimespan,
runningFunctionInfo.Success);
if (_metricsPublisher != null)
{
_metricsPublisher.AddFunctionExecutionActivity(
runningFunctionInfo.FunctionMetadata.Name,
invocationId,
concurrency,
executionStage.ToString(),
runningFunctionInfo.Success,
(long)executionTimespan,
_executionId,
currentTime,
runningFunctionInfo.Timestamp);
}
if (_linuxContainerActivityPublisher != null)
{
var triggerType = runningFunctionInfo.FunctionMetadata.Trigger?.Type;
var activity = new ContainerFunctionExecutionActivity(DateTime.UtcNow, runningFunctionInfo.FunctionMetadata.Name,
executionStage, triggerType,
runningFunctionInfo.Success);
_linuxContainerActivityPublisher.PublishFunctionExecutionActivity(activity);
}
}
internal void FunctionStarted(FunctionStartedEvent startedEvent)
{
lock (_functionActivityTrackerLockObject)
{
if (instance == null)
{
instance = new FunctionActivityTracker(_eventGenerator, _functionActivityFlushIntervalSeconds);
}
instance.FunctionStarted(startedEvent);
}
}
private void LogFunctionFailed(FunctionStartedEvent startedEvent, string resultString, string invocationId, long elapsedMs)
{
if (startedEvent != null)
{
startedEvent.Success = false;
}
string message = $"Function completed ({resultString}, Id={invocationId ?? "0"}, Duration={elapsedMs}ms)";
TraceWriter.Error(message);
Logger?.LogError(message);
}
internal void FunctionStarted(FunctionStartedEvent startedEvent)
{
lock (_functionActivityTrackerLockObject)
{
if (instance == null)
{
instance = new FunctionActivityTracker(_appServiceOptions, _eventGenerator, _metricsPublisher,
_linuxContainerActivityPublisher, _functionActivityFlushIntervalSeconds);
}
instance.FunctionStarted(startedEvent);
}
}
internal void FunctionCompleted(FunctionStartedEvent startedEvent)
{
Interlocked.Decrement(ref _activeFunctionCount);
var functionStage = !startedEvent.Success ? ExecutionStage.Failed : ExecutionStage.Succeeded;
long executionTimeInMS = (long)startedEvent.Duration.TotalMilliseconds;
var monitoringEvent = new FunctionMetrics(startedEvent.FunctionMetadata.Name, functionStage, executionTimeInMS);
_functionMetricsQueue.Enqueue(monitoringEvent);
RaiseFunctionMetricEvent(startedEvent, _activeFunctionCount, DateTime.UtcNow);
}
private async Task TestFunction(string name, Guid invocationId, WebHostMetricsLogger metricsLogger, TimeSpan waitTimeSpan)
{
var functionMetadata = new FunctionMetadata
{
Name = name
};
var functionEvent = new FunctionStartedEvent(invocationId, functionMetadata);
metricsLogger.BeginEvent(functionEvent);
await Task.Delay(waitTimeSpan);
metricsLogger.EndEvent(functionEvent);
}
internal void FunctionStarted(FunctionStartedEvent startedEvent)
{
_totalExecutionCount++;
Interlocked.Increment(ref _activeFunctionCount);
var monitoringEvent = new FunctionMetrics(startedEvent.FunctionMetadata.Name, ExecutionStage.Started, 0);
_functionMetricsQueue.Enqueue(monitoringEvent);
lock (_runningFunctionsSyncLock)
{
_runningFunctions.Add(startedEvent);
}
}
internal void FunctionCompleted(FunctionStartedEvent completedEvent)
{
if (runningFunctionCount > 0)
{
runningFunctionCount--;
}
var functionStage = (completedEvent.Success == false) ? ExecutionStage.Failed : ExecutionStage.Succeeded;
long executionTimeInMS = (long)completedEvent.EndTime.Subtract(completedEvent.StartTime).TotalMilliseconds;
var monitoringEvent = new FunctionMetrics(completedEvent.FunctionMetadata.Name, functionStage, executionTimeInMS);
functionMetricsQueue.Enqueue(monitoringEvent);
}
internal void FunctionStarted(FunctionStartedEvent startedEvent)
{
_totalExecutionCount++;
var monitoringEvent = new FunctionMetrics(startedEvent.FunctionMetadata.Name, ExecutionStage.Started, 0);
_functionMetricsQueue.Enqueue(monitoringEvent);
var key = GetDictionaryKey(startedEvent.FunctionMetadata.Name, startedEvent.InvocationId);
var triggerType = startedEvent.FunctionMetadata.Trigger?.Type;
var value = new RunningFunctionInfo(startedEvent.FunctionMetadata.Name, startedEvent.InvocationId, startedEvent.Timestamp, startedEvent.Success, triggerType);
_runningFunctions.AddOrUpdate(key, value, (k, v) => value);
}
public void EndEvent(MetricEvent metricEvent)
{
FunctionStartedEvent completedEvent = metricEvent as FunctionStartedEvent;
if (completedEvent != null)
{
completedEvent.Duration = DateTime.UtcNow - completedEvent.Timestamp;
_metricsEventManager.FunctionCompleted(completedEvent);
}
else
{
_metricsEventManager.EndEvent((object)metricEvent);
}
}
internal void FunctionCompleted(FunctionStartedEvent completedEvent)
{
lock (_functionActivityTrackerLockObject)
{
if (instance != null)
{
instance.FunctionCompleted(completedEvent);
if (!instance.IsActive)
{
instance.StopEtwTaskAndRaiseFinishedEvent();
instance = null;
}
}
}
}
private void StartFunction(FunctionInstanceLogEntry item)
{
if (_metadataManager.TryGetFunctionMetadata(item.LogName, out FunctionMetadata function))
{
var startedEvent = new FunctionStartedEvent(item.FunctionInstanceId, function);
_metrics.BeginEvent(startedEvent);
var invokeLatencyEvent = LogInvocationMetrics(function);
item.Properties[Key] = (startedEvent, invokeLatencyEvent);
}
else
{
throw new InvalidOperationException($"Unable to load metadata for function '{item.LogName}'.");
}
}
private void LogFunctionResult(FunctionStartedEvent startedEvent, bool success, string invocationId, long elapsedMs)
{
if (startedEvent != null)
{
startedEvent.Success = success;
}
string resultString = success ? "Success" : "Failure";
string message = $"Function completed ({resultString}, Id={invocationId ?? "0"}, Duration={elapsedMs}ms)";
TraceLevel traceWriterLevel = success ? TraceLevel.Info : TraceLevel.Error;
LogLevel logLevel = success ? LogLevel.Information : LogLevel.Error;
TraceWriter.Trace(message, traceWriterLevel, null);
Logger?.Log(logLevel, new EventId(0), message, null, (s, e) => s);
}
internal void FunctionStarted(FunctionStartedEvent startedEvent)
{
_totalExecutionCount++;
var metricEventPerFunction = new FunctionMetrics(startedEvent.FunctionMetadata.Name, ExecutionStage.Started, 0);
_functionMetricsQueue.Enqueue(metricEventPerFunction);
var key = GetDictionaryKey(startedEvent.FunctionMetadata.Name, startedEvent.InvocationId);
if (!_runningFunctions.ContainsKey(key))
{
lock (_functionMetricEventLockObject)
{
if (!_runningFunctions.ContainsKey(key))
{
_runningFunctions.Add(key, new RunningFunctionInfo(startedEvent.FunctionMetadata.Name, startedEvent.InvocationId, startedEvent.Timestamp, startedEvent.Success));
}
}
}
}
internal void FunctionCompleted(FunctionStartedEvent startedEvent)
{
var functionStage = (startedEvent.Success == false) ? ExecutionStage.Failed : ExecutionStage.Succeeded;
long executionTimeInMS = (long)startedEvent.Duration.TotalMilliseconds;
var monitoringEvent = new FunctionMetrics(startedEvent.FunctionMetadata.Name, functionStage, executionTimeInMS);
_functionMetricsQueue.Enqueue(monitoringEvent);
var key = GetDictionaryKey(startedEvent.FunctionMetadata.Name, startedEvent.InvocationId);
if (_runningFunctions.TryRemove(key, out RunningFunctionInfo functionInfo))
{
functionInfo.ExecutionStage = ExecutionStage.Finished;
functionInfo.Success = startedEvent.Success;
var endTime = startedEvent.Timestamp + startedEvent.Duration;
functionInfo.EndTime = startedEvent.Timestamp + startedEvent.Duration;
RaiseFunctionMetricEvent(functionInfo, _runningFunctions.Keys.Count, endTime);
}
}
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 Complete_TimestampSet_CompletesEvent()
{
var metadata = new FunctionMetadata();
var evt = new FunctionStartedEvent(Guid.NewGuid(), metadata);
evt.Timestamp = DateTime.UtcNow;
Assert.False(evt.Completed);
// complete immediately (potentially within system timer resolution)
evt.Complete();
Assert.True(evt.Completed);
evt = new FunctionStartedEvent(Guid.NewGuid(), metadata);
evt.Timestamp = DateTime.UtcNow;
Assert.False(evt.Completed);
// complete after a delay
await Task.Delay(250);
evt.Complete();
Assert.True(evt.Completed);
}
public async Task Complete_StopwatchSet_CompletesEvent()
{
var metadata = new FunctionMetadata();
var evt = new FunctionStartedEvent(Guid.NewGuid(), metadata);
evt.StopWatch = Stopwatch.StartNew();
Assert.False(evt.Completed);
// complete immediately (potentially within system timer resolution)
evt.Complete();
Assert.True(evt.Completed);
Assert.False(evt.StopWatch.IsRunning);
evt = new FunctionStartedEvent(Guid.NewGuid(), metadata);
evt.StopWatch = Stopwatch.StartNew();
Assert.False(evt.Completed);
// complete after a delay
await Task.Delay(250);
evt.Complete();
Assert.True(evt.Completed);
Assert.False(evt.StopWatch.IsRunning);
}
public async Task Complete_StopwatchSet_CompletesEvent()
{
var metadata = new FunctionMetadata();
var evt = new FunctionStartedEvent(Guid.NewGuid(), metadata);
evt.StopWatch = ValueStopwatch.StartNew();
Assert.False(evt.Completed);
// complete immediately (potentially within system timer resolution)
evt.Complete();
Assert.True(evt.Completed);
Assert.True(evt.StopWatch.IsActive); // The stopwatch has no state, but has been activated
evt = new FunctionStartedEvent(Guid.NewGuid(), metadata);
evt.StopWatch = ValueStopwatch.StartNew();
Assert.False(evt.Completed);
// complete after a delay
await Task.Delay(250);
evt.Complete();
Assert.True(evt.Completed);
Assert.True(evt.StopWatch.IsActive); // The stopwatch has no state, but has been activated
}
public async Task MetricsEventManager_ActivityTimer_HandlesExceptions()
{
// create a local event manager for this test, so we can override the flush interval
var logger = _loggerFactory.CreateLogger <MetricsEventManager>();
var metricsEventManager = new MetricsEventManager(_mockAppServiceOptions.Object, _mockEventGenerator.Object, 1, _mockEventPublisher.Object, _linuxFunctionExecutionActivityPublisher.Object, logger);
var metricsLogger = new WebHostMetricsLogger(metricsEventManager);
// execute some functions
var taskList = new List <Task>();
for (int currentIndex = 0; currentIndex < 10; currentIndex++)
{
taskList.Add(ShortTestFunction(metricsLogger));
}
await Task.WhenAll(taskList);
// wait for a flush to occur
await Task.Delay(1000);
// verify events
Assert.Equal(10, _functionExecutionEventArguments.Count);
Assert.True(_functionExecutionEventArguments.All(p => p.ExecutionStage == ExecutionStage.Finished.ToString()));
// now force a logging error for an in progress function
// on the background timer
_throwOnExecutionEvent = true;
var id = Guid.NewGuid();
var functionMetadata = new FunctionMetadata
{
Name = "Test"
};
var functionEvent = new FunctionStartedEvent(id, functionMetadata);
metricsLogger.BeginEvent(functionEvent);
// wait for the error to be logged
LogMessage errorLog = null;
await TestHelpers.Await(() =>
{
errorLog = _testLoggerProvider.GetAllLogMessages().SingleOrDefault();
return(errorLog != null);
}, timeout : 5000);
// verify error was logged
Assert.Equal(LogLevel.Error, errorLog.Level);
Assert.Equal("Error occurred when logging function activity", errorLog.FormattedMessage);
// execute some more functions, verifying that the timer is
// still running
taskList = new List <Task>();
for (int currentIndex = 0; currentIndex < 10; currentIndex++)
{
taskList.Add(ShortTestFunction(metricsLogger));
}
await Task.WhenAll(taskList);
await Task.Delay(1000);
// verify events
Assert.Equal(20, _functionExecutionEventArguments.Count(p => p.ExecutionStage == ExecutionStage.Finished.ToString()));
int inProgressCount = _functionExecutionEventArguments.Count(p => p.InvocationId == id.ToString() && p.ExecutionStage == ExecutionStage.InProgress.ToString());
Assert.True(inProgressCount > 0);
}
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);
}
}
}
