in src/Microsoft.Azure.WebJobs.Host/Executors/FunctionExecutor.cs [261:368]
internal async Task<string> ExecuteWithLoggingAsync(IFunctionInstanceEx instance, FunctionStartedMessage message,
FunctionInstanceLogEntry instanceLogEntry, ParameterHelper parameterHelper, ILogger logger, CancellationToken cancellationToken)
{
var outputDefinition = await _functionOutputLogger.CreateAsync(instance, cancellationToken);
var outputLog = outputDefinition.CreateOutput();
var updateOutputLogTimer = StartOutputTimer(outputLog.UpdateCommand, _exceptionHandler);
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)
{
FunctionOutputLogger.SetOutput(outputLog);
// Must bind before logging (bound invoke string is included in log message).
var functionContext = new FunctionBindingContext(instance, functionCancellationTokenSource.Token);
var valueBindingContext = new ValueBindingContext(functionContext, cancellationToken);
using (logger.BeginScope(_inputBindingScope))
{
var valueProviders = await instance.BindingSource.BindAsync(valueBindingContext);
parameterHelper.SetValueProviders(valueProviders);
}
// Log started events
CompleteStartedMessage(message, outputDefinition, parameterHelper);
string startedMessageId = _functionInstanceLogger.LogFunctionStarted(message);
instanceLogEntry.Arguments = message.Arguments;
await _functionEventCollector.AddAsync(instanceLogEntry);
Exception invocationException = null;
ITaskSeriesTimer updateParameterLogTimer = null;
try
{
if (outputDefinition != NullFunctionOutputDefinition.Instance)
{
var parameterWatchers = parameterHelper.CreateParameterWatchers();
var updateParameterLogCommand = outputDefinition.CreateParameterLogUpdateCommand(parameterWatchers, logger);
updateParameterLogTimer = StartParameterLogTimer(updateParameterLogCommand, _exceptionHandler);
}
await ExecuteWithWatchersAsync(instance, parameterHelper, logger, functionCancellationTokenSource);
if (updateParameterLogTimer != null)
{
// Stop the watches after calling IValueBinder.SetValue (it may do things that should show up in
// the watches).
// Also, IValueBinder.SetValue could also take a long time (flushing large caches), and so it's
// useful to have watches still running.
await updateParameterLogTimer.StopAsync(functionCancellationTokenSource.Token);
}
}
catch (Exception ex)
{
invocationException = ex;
}
finally
{
updateParameterLogTimer?.Dispose();
parameterHelper.FlushParameterWatchers();
}
var exceptionInfo = GetExceptionDispatchInfo(invocationException, instance);
if (exceptionInfo == null && updateOutputLogTimer != null)
{
await updateOutputLogTimer.StopAsync(cancellationToken);
}
// 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(instanceLogEntry, cancellationToken);
}
if (exceptionInfo != null)
{
if (parameterHelper.HasSingleton)
{
// release any held singleton lock immediately
SingletonLock singleton = await parameterHelper.GetSingletonLockAsync();
if (singleton != null && singleton.IsHeld)
{
await singleton.ReleaseAsync(CancellationToken.None);
}
}
exceptionInfo.Throw();
}
return startedMessageId;
}
}
finally
{
if (outputLog != null)
{
outputLog.Dispose();
}
if (updateOutputLogTimer != null)
{
updateOutputLogTimer.Dispose();
}
}
}