protected override async Task <object> InvokeCore(object[] parameters, FunctionInvocationContext context)
{
FunctionInstanceLogEntry item = new FunctionInstanceLogEntry
{
FunctionInstanceId = context.ExecutionContext.InvocationId,
StartTime = DateTime.UtcNow,
FunctionName = Metadata.Name,
Properties = new Dictionary <string, object>()
};
await _fastLogger.AddAsync(item);
InvocationData invocation = parameters.OfType <InvocationData>().FirstOrDefault() ?? new InvocationData();
string error = "failed";
try
{
if (invocation.Throw)
{
throw new InvalidOperationException("Kaboom!");
}
await Task.Delay(invocation.Delay);
error = null; // success
return(null);
}
finally
{
item.EndTime = DateTime.UtcNow;
item.ErrorDetails = error;
await _fastLogger.AddAsync(item);
}
}
internal static void LogFunctionResult(this ILogger logger, FunctionInstanceLogEntry logEntry)
{
bool succeeded = logEntry.Exception == null;
// build the string and values
string result = succeeded ? "Succeeded" : "Failed";
string logString = $"Executed '{{{LogConstants.FullNameKey}}}' ({result}, Id={{{LogConstants.InvocationIdKey}}})";
object[] values = new object[]
{
logEntry.FunctionName,
logEntry.FunctionInstanceId
};
// generate additional payload that is not in the string
IDictionary <string, object> properties = new Dictionary <string, object>();
properties.Add(LogConstants.NameKey, logEntry.LogName);
properties.Add(LogConstants.TriggerReasonKey, logEntry.TriggerReason);
properties.Add(LogConstants.StartTimeKey, logEntry.StartTime);
properties.Add(LogConstants.EndTimeKey, logEntry.EndTime);
properties.Add(LogConstants.DurationKey, logEntry.Duration);
properties.Add(LogConstants.SucceededKey, succeeded);
FormattedLogValuesCollection payload = new FormattedLogValuesCollection(logString, values, new ReadOnlyDictionary <string, object>(properties));
LogLevel level = succeeded ? LogLevel.Information : LogLevel.Error;
logger.Log(level, 0, payload, logEntry.Exception, (s, e) => s.ToString());
}
internal static void LogFunctionResult(this ILogger logger, FunctionInstanceLogEntry logEntry)
{
bool succeeded = logEntry.Exception == null;
IDictionary <string, object> payload = new Dictionary <string, object>();
payload.Add(LogConstants.FullNameKey, logEntry.FunctionName);
payload.Add(LogConstants.InvocationIdKey, logEntry.FunctionInstanceId);
payload.Add(LogConstants.NameKey, logEntry.LogName);
payload.Add(LogConstants.TriggerReasonKey, logEntry.TriggerReason);
payload.Add(LogConstants.StartTimeKey, logEntry.StartTime);
payload.Add(LogConstants.EndTimeKey, logEntry.EndTime);
payload.Add(LogConstants.DurationKey, logEntry.Duration);
payload.Add(LogConstants.SucceededKey, succeeded);
LogLevel level = succeeded ? LogLevel.Information : LogLevel.Error;
// Only pass the state dictionary; no string message.
logger.Log(level, 0, payload, logEntry.Exception, (s, e) => null);
}
public async Task <IDelayedException> TryExecuteAsync(IFunctionInstance functionInstance, CancellationToken cancellationToken)
{
FunctionStartedMessage functionStartedMessage = CreateStartedMessageWithoutArguments(functionInstance);
IDictionary <string, ParameterLog> parameterLogCollector = new Dictionary <string, ParameterLog>();
FunctionCompletedMessage functionCompletedMessage = null;
ExceptionDispatchInfo exceptionInfo = null;
string functionStartedMessageId = null;
TraceLevel functionTraceLevel = GetFunctionTraceLevel(functionInstance);
FunctionInstanceLogEntry fastItem = new FunctionInstanceLogEntry
{
FunctionInstanceId = functionStartedMessage.FunctionInstanceId,
ParentId = functionStartedMessage.ParentId,
FunctionName = functionStartedMessage.Function.ShortName,
TriggerReason = functionStartedMessage.ReasonDetails,
StartTime = functionStartedMessage.StartTime.DateTime
};
try
{
functionStartedMessageId = await ExecuteWithLoggingAsync(functionInstance, functionStartedMessage, fastItem, parameterLogCollector, functionTraceLevel, cancellationToken);
functionCompletedMessage = CreateCompletedMessage(functionStartedMessage);
}
catch (Exception exception)
{
if (functionCompletedMessage == null)
{
functionCompletedMessage = CreateCompletedMessage(functionStartedMessage);
}
functionCompletedMessage.Failure = new FunctionFailure
{
Exception = exception,
ExceptionType = exception.GetType().FullName,
ExceptionDetails = exception.ToDetails(),
};
exceptionInfo = ExceptionDispatchInfo.Capture(exception);
}
if (functionCompletedMessage != null)
{
functionCompletedMessage.ParameterLogs = parameterLogCollector;
functionCompletedMessage.EndTime = DateTimeOffset.UtcNow;
}
bool loggedStartedEvent = functionStartedMessageId != null;
CancellationToken logCompletedCancellationToken;
if (loggedStartedEvent)
{
// If function started was logged, don't cancel calls to log function completed.
logCompletedCancellationToken = CancellationToken.None;
}
else
{
logCompletedCancellationToken = cancellationToken;
}
if (_fastLogger != null)
{
// Log completed
fastItem.EndTime = DateTime.UtcNow;
fastItem.Arguments = functionCompletedMessage.Arguments;
if (exceptionInfo != null)
{
var ex = exceptionInfo.SourceException;
if (ex.InnerException != null)
{
ex = ex.InnerException;
}
fastItem.ErrorDetails = ex.Message;
}
await _fastLogger.AddAsync(fastItem);
}
if (functionCompletedMessage != null &&
((functionTraceLevel >= TraceLevel.Info) || (functionCompletedMessage.Failure != null && functionTraceLevel >= TraceLevel.Error)))
{
await _functionInstanceLogger.LogFunctionCompletedAsync(functionCompletedMessage, logCompletedCancellationToken);
}
if (loggedStartedEvent)
{
await _functionInstanceLogger.DeleteLogFunctionStartedAsync(functionStartedMessageId, cancellationToken);
}
if (exceptionInfo != null)
{
await HandleExceptionAsync(functionInstance.FunctionDescriptor.Method, exceptionInfo, _exceptionHandler);
}
return(exceptionInfo != null ? new ExceptionDispatchInfoDelayedException(exceptionInfo) : null);
}
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();
}
}
}
public async Task SaveAndCloseAsync(FunctionInstanceLogEntry item, CancellationToken cancellationToken)
{
await UpdateOutputBlob(cancellationToken, flushAndClose : true);
}
public Task SaveAndCloseAsync(FunctionInstanceLogEntry item, CancellationToken cancellationToken)
{
return(Task.FromResult(0));
}
// We want the short name for use with Application Insights.
internal static void LogFunctionResult(this ILogger logger, string shortName, FunctionInstanceLogEntry logEntry, TimeSpan duration, Exception exception = null)
{
bool succeeded = exception == null;
// build the string and values
string result = succeeded ? "Succeeded" : "Failed";
string logString = $"Executed '{{{LoggingKeys.FullName}}}' ({result}, Id={{{LoggingKeys.InvocationId}}})";
object[] values = new object[]
{
logEntry.FunctionName,
logEntry.FunctionInstanceId
};
// generate additional payload that is not in the string
IDictionary <string, object> properties = new Dictionary <string, object>();
properties.Add(LoggingKeys.Name, shortName);
properties.Add(LoggingKeys.TriggerReason, logEntry.TriggerReason);
properties.Add(LoggingKeys.StartTime, logEntry.StartTime);
properties.Add(LoggingKeys.EndTime, logEntry.EndTime);
properties.Add(LoggingKeys.Duration, duration);
properties.Add(LoggingKeys.Succeeded, succeeded);
if (logEntry.Arguments != null)
{
foreach (var arg in logEntry.Arguments)
{
properties.Add(LoggingKeys.ParameterPrefix + arg.Key, arg.Value);
}
}
FormattedLogValuesCollection payload = new FormattedLogValuesCollection(logString, values, new ReadOnlyDictionary <string, object>(properties));
LogLevel level = succeeded ? LogLevel.Information : LogLevel.Error;
logger.Log(level, 0, payload, exception, (s, e) => s.ToString());
}
