public async Task LogFunctionStartedAsync_CallsTraceWriter()
{
FunctionStartedMessage message = new FunctionStartedMessage
{
Function = new FunctionDescriptor
{
ShortName = "TestJob"
},
ReasonDetails = "TestReason",
HostInstanceId = Guid.NewGuid(),
FunctionInstanceId = Guid.NewGuid()
};
await _logger.LogFunctionStartedAsync(message, CancellationToken.None);
Assert.Equal(1, _traceWriter.Traces.Count);
TraceEvent traceEvent = _traceWriter.Traces[0];
Assert.Equal(TraceLevel.Info, traceEvent.Level);
Assert.Equal(Host.TraceSource.Execution, traceEvent.Source);
Assert.Equal(string.Format("Executing 'TestJob' (Reason='TestReason', Id={0})", message.FunctionInstanceId), traceEvent.Message);
Assert.Equal(3, traceEvent.Properties.Count);
Assert.Equal(message.HostInstanceId, traceEvent.Properties["MS_HostInstanceId"]);
Assert.Equal(message.FunctionInstanceId, traceEvent.Properties["MS_FunctionInvocationId"]);
Assert.Same(message.Function, traceEvent.Properties["MS_FunctionDescriptor"]);
}
public Task <string> LogFunctionStartedAsync(FunctionStartedMessage message, CancellationToken cancellationToken)
{
string traceMessage = string.Format(CultureInfo.InvariantCulture, "Executing: '{0}' - Reason: '{1}'", message.Function.ShortName, message.FormatReason());
Trace(TraceLevel.Info, message.HostInstanceId, message.Function, message.FunctionInstanceId, traceMessage, TraceSource.Execution);
return(Task.FromResult <string>(null));
}
public async Task <IDelayedException> TryExecuteAsync(IFunctionInstance instance, CancellationToken cancellationToken)
{
FunctionStartedMessage startedMessage = CreateStartedMessageWithoutArguments(instance);
IDictionary <string, ParameterLog> parameterLogCollector = new Dictionary <string, ParameterLog>();
FunctionCompletedMessage completedMessage = null;
ExceptionDispatchInfo exceptionInfo = null;
string startedMessageId = null;
try
{
startedMessageId = await ExecuteWithLogMessageAsync(instance, startedMessage, parameterLogCollector, cancellationToken);
completedMessage = CreateCompletedMessage(startedMessage);
}
catch (Exception exception)
{
if (completedMessage == null)
{
completedMessage = CreateCompletedMessage(startedMessage);
}
completedMessage.Failure = new FunctionFailure
{
Exception = exception,
ExceptionType = exception.GetType().FullName,
ExceptionDetails = exception.ToDetails(),
};
exceptionInfo = ExceptionDispatchInfo.Capture(exception);
}
completedMessage.ParameterLogs = parameterLogCollector;
completedMessage.EndTime = DateTimeOffset.UtcNow;
bool loggedStartedEvent = startedMessageId != null;
CancellationToken logCompletedCancellationToken;
if (loggedStartedEvent)
{
// If function started was logged, don't cancel calls to log function completed.
logCompletedCancellationToken = CancellationToken.None;
}
else
{
logCompletedCancellationToken = cancellationToken;
}
await _functionInstanceLogger.LogFunctionCompletedAsync(completedMessage,
logCompletedCancellationToken);
if (loggedStartedEvent)
{
await _functionInstanceLogger.DeleteLogFunctionStartedAsync(startedMessageId, cancellationToken);
}
return(exceptionInfo != null ? new ExceptionDispatchInfoDelayedException(exceptionInfo) : null);
}
private void Process(PersistentQueueMessage message)
{
HostStartedMessage hostStartedMessage = message as HostStartedMessage;
if (hostStartedMessage != null)
{
_hostIndexer.ProcessHostStarted(hostStartedMessage);
return;
}
FunctionCompletedMessage functionCompletedMessage = message as FunctionCompletedMessage;
if (functionCompletedMessage != null)
{
_functionIndexer.ProcessFunctionCompleted(functionCompletedMessage);
return;
}
FunctionStartedMessage functionStartedMessage = message as FunctionStartedMessage;
if (functionStartedMessage != null)
{
_functionIndexer.ProcessFunctionStarted(functionStartedMessage);
return;
}
string errorMessage =
String.Format(CultureInfo.InvariantCulture, "Unknown message type '{0}'.", message.Type);
throw new InvalidOperationException(errorMessage);
}
// This method runs concurrently with other index processing.
// Ensure all logic here is idempotent.
public void ProcessFunctionStarted(FunctionStartedMessage message)
{
FunctionInstanceSnapshot snapshot = CreateSnapshot(message);
_functionInstanceLogger.LogFunctionStarted(snapshot);
string functionId = new FunctionIdentifier(message.SharedQueueName, message.Function.Id).ToString();
Guid functionInstanceId = message.FunctionInstanceId;
DateTimeOffset startTime = message.StartTime;
WebJobRunIdentifier webJobRunId = message.WebJobRunIdentifier;
Guid? parentId = message.ParentId;
// Race to write index entries for function started.
if (!HasLoggedFunctionCompleted(functionInstanceId))
{
CreateOrUpdateIndexEntries(snapshot, startTime, webJobRunId);
}
// If the function has since completed, we lost the race.
// Delete any function started index entries.
// Note that this code does not depend on whether or not the index entries were previously written by this
// method, as this processing could have been aborted and resumed at another point in time. In that case,
// we still own cleaning up any dangling function started index entries.
DateTimeOffset?functionCompletedTime = GetFunctionCompletedTime(functionInstanceId);
bool hasLoggedFunctionCompleted = functionCompletedTime.HasValue;
if (hasLoggedFunctionCompleted)
{
DeleteFunctionStartedIndexEntriesIfNeeded(functionInstanceId, message.StartTime,
functionCompletedTime.Value, functionId, parentId, webJobRunId);
}
}
public async Task LogFunctionStarted_CallsLogger()
{
FunctionStartedMessage message = new FunctionStartedMessage
{
Function = new FunctionDescriptor
{
ShortName = "Function.TestJob",
LogName = "TestJob"
},
ReasonDetails = "TestReason",
HostInstanceId = Guid.NewGuid(),
FunctionInstanceId = Guid.NewGuid()
};
await _instanceLogger.LogFunctionStartedAsync(message, CancellationToken.None);
string expectedCategory = LogCategories.CreateFunctionCategory("TestJob");
LogMessage logMessage = _provider.GetAllLogMessages().Single();
Assert.Equal(LogLevel.Information, logMessage.Level);
Assert.Equal(expectedCategory, logMessage.Category);
Assert.Null(logMessage.State);
Assert.Equal($"Executing 'Function.TestJob' (Reason='TestReason', Id={message.FunctionInstanceId})", logMessage.FormattedMessage);
}
private FunctionStartedMessage CreateStartedMessageWithoutArguments(IFunctionInstance instance)
{
FunctionStartedMessage message = new FunctionStartedMessage
{
HostInstanceId = _hostOutputMessage.HostInstanceId,
HostDisplayName = _hostOutputMessage.HostDisplayName,
SharedQueueName = _hostOutputMessage.SharedQueueName,
InstanceQueueName = _hostOutputMessage.InstanceQueueName,
Heartbeat = _hostOutputMessage.Heartbeat,
WebJobRunIdentifier = _hostOutputMessage.WebJobRunIdentifier,
FunctionInstanceId = instance.Id,
Function = instance.FunctionDescriptor,
ParentId = instance.ParentId,
Reason = instance.Reason,
StartTime = DateTimeOffset.UtcNow
};
// It's important that the host formats the reason before sending the message.
// This enables extensibility scenarios. For the built in types, the Host and Dashboard
// share types so it's possible (in the case of triggered functions) for the formatting
// to require a call to TriggerParameterDescriptor.GetTriggerReason and that can only
// be done on the Host side in the case of extensions (since the dashboard doesn't
// know about extension types).
message.ReasonDetails = message.FormatReason();
return(message);
}
public void FormatReason_BlobTriggeredFunction_ReturnsExpectedReason()
{
FunctionStartedMessage message = new FunctionStartedMessage();
message.Reason = ExecutionReason.AutomaticTrigger;
BlobTriggerParameterDescriptor triggerParameterDescriptor = new BlobTriggerParameterDescriptor
{
Name = "paramName"
};
FunctionDescriptor function = new FunctionDescriptor()
{
Parameters = new ParameterDescriptor[] { triggerParameterDescriptor },
TriggerParameterDescriptor = triggerParameterDescriptor
};
message.Function = function;
message.Arguments = new Dictionary <string, string>()
{
{ "paramName", "blob/path" }
};
string result = message.FormatReason();
Assert.Equal("New blob detected: blob/path", result);
}
/// <summary>Formats a function's <see cref="ExecutionReason"/> in a display-friendly text format.</summary>
/// <param name="message">The function whose reason to format.</param>
/// <returns>A function's <see cref="ExecutionReason"/> in a display-friendly text format.</returns>
public static string FormatReason(this FunctionStartedMessage message)
{
if (message == null)
{
throw new ArgumentNullException("message");
}
#if PUBLICPROTOCOL
// If the message already contains details use them. This will be the case for
// messages serialized from the Host to the Dashboard. The host will format the
// reason before sending
return(message.ReasonDetails);
#else
if (!string.IsNullOrEmpty(message.ReasonDetails))
{
return(message.ReasonDetails);
}
switch (message.Reason)
{
case ExecutionReason.AutomaticTrigger:
return(message.Function.TriggerParameterDescriptor?.GetTriggerReason(message.Arguments));
case ExecutionReason.HostCall:
return("This function was programmatically called via the host APIs.");
case ExecutionReason.Dashboard:
return(message.ParentId.HasValue ? "Replayed from Dashboard." : "Ran from Dashboard.");
default:
return(null);
}
#endif
}
private static string GetAutomaticTriggerReason(FunctionStartedMessage message)
{
string blobPath = GetArgumentValue <BlobTriggerParameterDescriptor>(message);
if (blobPath != null)
{
return("New blob detected: " + blobPath);
}
QueueTriggerParameterDescriptor queueTrigger = GetParameterDescriptor <QueueTriggerParameterDescriptor>(message);
if (queueTrigger != null)
{
return("New queue message detected on '" + queueTrigger.QueueName + "'.");
}
ServiceBusTriggerParameterDescriptor serviceBusTrigger = GetParameterDescriptor <ServiceBusTriggerParameterDescriptor>(message);
if (serviceBusTrigger != null)
{
return("New service bus message detected on '" + GetPath(serviceBusTrigger) + "'.");
}
return(null);
}
private void LogTemplatizedTriggerDetails(FunctionStartedMessage message)
{
var templateKeys = message.TriggerDetails.Select(entry => $"{entry.Key}: {{{entry.Key}}}");
string messageTemplate = "Trigger Details: " + string.Join(", ", templateKeys);
string[] templateValues = message.TriggerDetails.Values.ToArray();
Log(LogLevel.Information, message.Function, messageTemplate, templateValues);
}
public Task <string> LogFunctionStartedAsync(FunctionStartedMessage message, CancellationToken cancellationToken)
{
string traceMessage = string.Format(CultureInfo.InvariantCulture, "Executing '{0}' (Reason='{1}', Id={2})", message.Function.ShortName, message.FormatReason(), message.FunctionInstanceId);
Log(LogLevel.Information, message.Function, message.FunctionInstanceId, traceMessage);
return(Task.FromResult <string>(null));
}
public void FormatReason_ReasonDetailsAlreadySet_ReturnsExpectedReason()
{
FunctionStartedMessage message = new FunctionStartedMessage();
message.ReasonDetails = "The trigger fired!";
string result = message.FormatReason();
Assert.Equal("The trigger fired!", result);
}
public void FormatReason_Portal_ReturnsExpectedReason()
{
FunctionStartedMessage message = new FunctionStartedMessage();
message.Reason = ExecutionReason.Portal;
Assert.Equal("Ran from Portal.", message.FormatReason());
message.ParentId = Guid.NewGuid();
Assert.Equal("Replayed from Portal.", message.FormatReason());
}
public void FormatReason_ReasonDetailsAlreadySet_ReturnsExpectedReason()
{
FunctionStartedMessage message = new FunctionStartedMessage();
message.ReasonDetails = "The trigger fired!";
string result = message.FormatReason();
Assert.Equal("The trigger fired!", result);
}
private static string GetAutomaticTriggerReason(FunctionStartedMessage message)
{
TriggerParameterDescriptor triggerParameterDescriptor = GetParameterDescriptor <TriggerParameterDescriptor>(message);
if (triggerParameterDescriptor != null)
{
return(triggerParameterDescriptor.GetTriggerReason(message.Arguments));
}
return(null);
}
public void LogLevel_IsStringEnumSerialized()
{
FunctionStartedMessage message = new FunctionStartedMessage()
{
LogLevel = TraceLevel.Verbose
};
string json = JsonConvert.SerializeObject(message);
Assert.True(json.Contains("\"LogLevel\":\"Verbose\""));
FunctionStartedMessage result = JsonConvert.DeserializeObject<FunctionStartedMessage>(json);
Assert.Equal(TraceLevel.Verbose, result.LogLevel);
}
internal static FunctionStatusMessage CreateFunctionStatusMessage(FunctionStartedMessage message)
{
return new FunctionStatusMessage()
{
FunctionId = message.Function.Id,
FunctionInstanceId = message.FunctionInstanceId,
Status = "Started",
StartTime = message.StartTime,
OutputBlob = message.OutputBlob,
ParameterLogBlob = message.ParameterLogBlob
};
}
private Task <string> LogFunctionStartedAsync(FunctionStartedMessage message,
IFunctionOutputDefinition functionOutput,
IReadOnlyDictionary <string, IValueProvider> parameters,
CancellationToken cancellationToken)
{
// Finish populating the function started snapshot.
message.OutputBlob = functionOutput.OutputBlob;
message.ParameterLogBlob = functionOutput.ParameterLogBlob;
message.Arguments = CreateArguments(parameters);
// Log that the function started.
return(_functionInstanceLogger.LogFunctionStartedAsync(message, cancellationToken));
}
public async Task LogFunctionStarted_CallsLogger()
{
Dictionary <string, string> triggerDetails = new Dictionary <string, string>()
{
{ "MessageId", Guid.NewGuid().ToString() },
{ "DequeueCount", "1" },
{ "InsertionTime", DateTime.Now.ToString() }
};
FunctionStartedMessage message = new FunctionStartedMessage
{
Function = new FunctionDescriptor
{
ShortName = "Function.TestJob",
LogName = "TestJob"
},
ReasonDetails = "TestReason",
HostInstanceId = Guid.NewGuid(),
FunctionInstanceId = Guid.NewGuid(),
TriggerDetails = triggerDetails
};
string expectedMessage = $"MessageId: {triggerDetails["MessageId"]}, " +
$"DequeueCount: {triggerDetails["DequeueCount"]}, " +
$"InsertionTime: {triggerDetails["InsertionTime"]}";
await _instanceLogger.LogFunctionStartedAsync(message, CancellationToken.None);
string expectedCategory = LogCategories.CreateFunctionCategory("TestJob");
LogMessage[] logMessages = _provider.GetAllLogMessages().ToArray();
Assert.Equal(2, logMessages.Length);
LogMessage invocationLogMessage = logMessages[0];
Assert.Equal(LogLevel.Information, invocationLogMessage.Level);
Assert.Equal(expectedCategory, invocationLogMessage.Category);
Assert.Null(invocationLogMessage.State);
Assert.Equal($"Executing 'Function.TestJob' (Reason='TestReason', Id={message.FunctionInstanceId})",
invocationLogMessage.FormattedMessage);
LogMessage triggerDetailsLogMessage = logMessages[1];
Assert.Equal(LogLevel.Information, triggerDetailsLogMessage.Level);
Assert.Equal(expectedCategory, triggerDetailsLogMessage.Category);
Assert.NotNull(triggerDetailsLogMessage.State);
Assert.Equal($"Trigger Details: {expectedMessage}",
triggerDetailsLogMessage.FormattedMessage);
}
public async Task<string> LogFunctionStartedAsync(FunctionStartedMessage message, CancellationToken cancellationToken)
{
if (message == null)
{
throw new ArgumentNullException("message");
}
if (message.LogLevel == TraceLevel.Verbose)
{
FunctionStatusMessage statusMessage = CreateFunctionStatusMessage(message);
await LogFunctionStatusAsync(statusMessage, cancellationToken);
}
return null;
}
public async Task<string> LogFunctionStartedAsync(FunctionStartedMessage message, CancellationToken cancellationToken)
{
if (message == null)
{
throw new ArgumentNullException("message");
}
if (message.Reason == ExecutionReason.Portal)
{
FunctionStatusMessage statusMessage = CreateFunctionStatusMessage(message);
await LogFunctionStatusAsync(statusMessage, cancellationToken);
}
return null;
}
private static string GetArgumentValue <T>(FunctionStartedMessage message) where T : ParameterDescriptor
{
T parameterDescriptor = GetParameterDescriptor <T>(message);
if (parameterDescriptor == null)
{
return(null);
}
if (!message.Arguments.ContainsKey(parameterDescriptor.Name))
{
return(null);
}
return(message.Arguments[parameterDescriptor.Name]);
}
public async Task LogFunctionStartedAsync_CallsTraceWriter()
{
FunctionStartedMessage message = new FunctionStartedMessage
{
Function = new FunctionDescriptor
{
ShortName = "TestJob"
},
ReasonDetails = "TestReason"
};
_mockTraceWriter.Setup(p => p.Trace(TraceLevel.Info, Host.TraceSource.Execution, "Executing: 'TestJob' - Reason: 'TestReason'", null));
await _logger.LogFunctionStartedAsync(message, CancellationToken.None);
_mockTraceWriter.VerifyAll();
}
public void FormatReason_BlobTriggeredFunction_ReturnsExpectedReason()
{
FunctionStartedMessage message = new FunctionStartedMessage();
message.Reason = ExecutionReason.AutomaticTrigger;
BlobTriggerParameterDescriptor triggerParameterDescriptor = new BlobTriggerParameterDescriptor
{
Name = "paramName"
};
FunctionDescriptor function = new FunctionDescriptor();
function.Parameters = new ParameterDescriptor[] { triggerParameterDescriptor };
message.Function = function;
message.Arguments = new Dictionary<string, string>() { { "paramName", "blob/path" } };
string result = message.FormatReason();
Assert.Equal("New blob detected: blob/path", result);
}
public async Task LogFunctionStartedAsync_CallsTraceWriter()
{
FunctionStartedMessage message = new FunctionStartedMessage
{
Function = new FunctionDescriptor
{
ShortName = "TestJob"
},
ReasonDetails = "TestReason"
};
_mockTraceWriter.Setup(p => p.Trace(TraceLevel.Info, Host.TraceSource.Execution, "Executing: 'TestJob' - Reason: 'TestReason'", null));
await _logger.LogFunctionStartedAsync(message, CancellationToken.None);
_mockTraceWriter.VerifyAll();
}
public async Task LogFunctionStartedAsync_CallsTraceWriter()
{
FunctionStartedMessage message = new FunctionStartedMessage
{
Function = new FunctionDescriptor
{
ShortName = "TestJob"
},
ReasonDetails = "TestReason"
};
await _logger.LogFunctionStartedAsync(message, CancellationToken.None);
Assert.Equal(1, _traceWriter.Traces.Count);
TraceEvent traceEvent = _traceWriter.Traces[0];
Assert.Equal(TraceLevel.Info, traceEvent.Level);
Assert.Equal(Host.TraceSource.Execution, traceEvent.Source);
Assert.Equal("Executing: 'TestJob' - Reason: 'TestReason'", traceEvent.Message);
}
public void FormatReason_QueueTriggeredFunction_ReturnsExpectedReason()
{
FunctionStartedMessage message = new FunctionStartedMessage();
QueueTriggerParameterDescriptor triggerParameterDescriptor = new QueueTriggerParameterDescriptor
{
Name = "paramName",
QueueName = "testqueue"
};
FunctionDescriptor function = new FunctionDescriptor
{
Parameters = new ParameterDescriptor[] { triggerParameterDescriptor }
};
message.Function = function;
message.Reason = ExecutionReason.AutomaticTrigger;
string result = message.FormatReason();
Assert.Equal("New queue message detected on 'testqueue'.", result);
}
public async Task LogFunctionStartedAsync_CallsTraceWriter()
{
FunctionStartedMessage message = new FunctionStartedMessage
{
Function = new FunctionDescriptor
{
ShortName = "TestJob"
},
ReasonDetails = "TestReason"
};
await _logger.LogFunctionStartedAsync(message, CancellationToken.None);
Assert.Equal(1, _traceWriter.Traces.Count);
TraceEvent traceEvent = _traceWriter.Traces[0];
Assert.Equal(TraceLevel.Info, traceEvent.Level);
Assert.Equal(Host.TraceSource.Execution, traceEvent.Source);
Assert.Equal("Executing: 'TestJob' - Reason: 'TestReason'", traceEvent.Message);
}
private static FunctionCompletedMessage CreateCompletedMessage(FunctionStartedMessage startedMessage)
{
return(new FunctionCompletedMessage
{
HostInstanceId = startedMessage.HostInstanceId,
HostDisplayName = startedMessage.HostDisplayName,
SharedQueueName = startedMessage.SharedQueueName,
InstanceQueueName = startedMessage.InstanceQueueName,
Heartbeat = startedMessage.Heartbeat,
WebJobRunIdentifier = startedMessage.WebJobRunIdentifier,
FunctionInstanceId = startedMessage.FunctionInstanceId,
Function = startedMessage.Function,
Arguments = startedMessage.Arguments,
ParentId = startedMessage.ParentId,
Reason = startedMessage.Reason,
StartTime = startedMessage.StartTime,
OutputBlob = startedMessage.OutputBlob,
ParameterLogBlob = startedMessage.ParameterLogBlob
});
}
public void FormatReason_QueueTriggeredFunction_ReturnsExpectedReason()
{
FunctionStartedMessage message = new FunctionStartedMessage();
QueueTriggerParameterDescriptor triggerParameterDescriptor = new QueueTriggerParameterDescriptor
{
Name = "paramName",
QueueName = "testqueue"
};
FunctionDescriptor function = new FunctionDescriptor
{
Parameters = new ParameterDescriptor[] { triggerParameterDescriptor }
};
message.Function = function;
message.Reason = ExecutionReason.AutomaticTrigger;
string result = message.FormatReason();
Assert.Equal("New queue message detected on 'testqueue'.", result);
}
public async Task<string> LogFunctionStartedAsync(FunctionStartedMessage message, CancellationToken cancellationToken)
{
string startedMessageId = null;
foreach (IFunctionInstanceLogger logger in _loggers)
{
var messageId = await logger.LogFunctionStartedAsync(message, cancellationToken);
if (!String.IsNullOrEmpty(messageId))
{
if (String.IsNullOrEmpty(startedMessageId))
{
startedMessageId = messageId;
}
else if (startedMessageId != messageId)
{
throw new NotSupportedException();
}
}
}
return startedMessageId;
}
public void CreateFunctionStatusMessage_FunctionStart_CreatesExpectedMessage()
{
FunctionStartedMessage startMessage = new FunctionStartedMessage
{
Function = new FunctionDescriptor
{
Id = "TestHost.TestFunction"
},
FunctionInstanceId = Guid.NewGuid(),
StartTime = DateTime.Now,
OutputBlob = new LocalBlobDescriptor(),
ParameterLogBlob = new LocalBlobDescriptor()
};
FunctionStatusMessage statusMessage = FunctionStatusLogger.CreateFunctionStatusMessage(startMessage);
Assert.Equal(startMessage.Function.Id, statusMessage.FunctionId);
Assert.Equal(startMessage.FunctionInstanceId, statusMessage.FunctionInstanceId);
Assert.Equal("Started", statusMessage.Status);
Assert.Equal(startMessage.StartTime, statusMessage.StartTime);
Assert.Same(startMessage.OutputBlob, statusMessage.OutputBlob);
Assert.Same(startMessage.ParameterLogBlob, statusMessage.ParameterLogBlob);
}
public async Task <string> LogFunctionStartedAsync(FunctionStartedMessage message, CancellationToken cancellationToken)
{
string startedMessageId = null;
foreach (IFunctionInstanceLogger logger in _loggers)
{
var messageId = await logger.LogFunctionStartedAsync(message, cancellationToken);
if (!String.IsNullOrEmpty(messageId))
{
if (String.IsNullOrEmpty(startedMessageId))
{
startedMessageId = messageId;
}
else if (startedMessageId != messageId)
{
throw new NotSupportedException();
}
}
}
return(startedMessageId);
}
/// <summary>Format's a function's <see cref="ExecutionReason"/> in a display-friendly text format.</summary>
/// <param name="message">The function whose reason to format.</param>
/// <returns>A function's <see cref="ExecutionReason"/> in a display-friendly text format.</returns>
public static string FormatReason(this FunctionStartedMessage message)
{
if (message == null)
{
throw new ArgumentNullException("message");
}
ExecutionReason reason = message.Reason;
switch (reason)
{
case ExecutionReason.AutomaticTrigger:
return(GetAutomaticTriggerReason(message));
case ExecutionReason.HostCall:
return("This was function was programmatically called via the host APIs.");
case ExecutionReason.Dashboard:
return(message.ParentId.HasValue ? "Replayed from Dashboard." : "Ran from Dashboard.");
default:
return(null);
}
}
internal static FunctionInstanceSnapshot CreateSnapshot(FunctionStartedMessage message)
{
return(new FunctionInstanceSnapshot
{
Id = message.FunctionInstanceId,
HostInstanceId = message.HostInstanceId,
InstanceQueueName = message.InstanceQueueName,
Heartbeat = message.Heartbeat,
FunctionId = new FunctionIdentifier(message.SharedQueueName, message.Function.Id).ToString(),
FunctionFullName = message.Function.FullName,
FunctionShortName = message.Function.ShortName,
Arguments = CreateArguments(message.Function.Parameters, message.Arguments),
ParentId = message.ParentId,
Reason = message.FormatReason(),
QueueTime = message.StartTime,
StartTime = message.StartTime,
OutputBlob = message.OutputBlob,
ParameterLogBlob = message.ParameterLogBlob,
WebSiteName = message.WebJobRunIdentifier != null ? message.WebJobRunIdentifier.WebSiteName : null,
WebJobType = message.WebJobRunIdentifier != null?message.WebJobRunIdentifier.JobType.ToString() : null,
WebJobName = message.WebJobRunIdentifier != null ? message.WebJobRunIdentifier.JobName : null,
WebJobRunId = message.WebJobRunIdentifier != null ? message.WebJobRunIdentifier.RunId : null
});
}
// This method runs concurrently with other index processing.
// Ensure all logic here is idempotent.
public void ProcessFunctionStarted(FunctionStartedMessage message)
{
if (message == null)
{
throw new ArgumentNullException("message");
}
FunctionInstanceSnapshot snapshot = CreateSnapshot(message);
_functionInstanceLogger.LogFunctionStarted(snapshot);
string functionId = new FunctionIdentifier(message.SharedQueueName, message.Function.Id).ToString();
Guid functionInstanceId = message.FunctionInstanceId;
DateTimeOffset startTime = message.StartTime;
WebJobRunIdentifier webJobRunId = message.WebJobRunIdentifier;
Guid? parentId = message.ParentId;
// Race to write index entries for function started.
if (!HasLoggedFunctionCompleted(functionInstanceId))
{
CreateOrUpdateIndexEntries(snapshot, startTime, webJobRunId);
}
// If the function has since completed, we lost the race.
// Delete any function started index entries.
// Note that this code does not depend on whether or not the index entries were previously written by this
// method, as this processing could have been aborted and resumed at another point in time. In that case,
// we still own cleaning up any dangling function started index entries.
DateTimeOffset? functionCompletedTime = GetFunctionCompletedTime(functionInstanceId);
bool hasLoggedFunctionCompleted = functionCompletedTime.HasValue;
if (hasLoggedFunctionCompleted)
{
DeleteFunctionStartedIndexEntriesIfNeeded(functionInstanceId, message.StartTime,
functionCompletedTime.Value, functionId, parentId, webJobRunId);
}
}
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 Task <string> LogFunctionStartedAsync(FunctionStartedMessage message, CancellationToken cancellationToken)
{
Console.WriteLine("Executing: '{0}' - Reason: '{1}'", message.Function.ShortName, message.FormatReason());
return(Task.FromResult <string>(null));
}
public async Task LogFunctionStartedAsync_Portal_WritesExpectedBlob()
{
FunctionStartedMessage startMessage = new FunctionStartedMessage
{
Function = new FunctionDescriptor
{
Id = "TestHost.TestFunction"
},
FunctionInstanceId = Guid.NewGuid(),
StartTime = DateTime.Now,
OutputBlob = new LocalBlobDescriptor(),
ParameterLogBlob = new LocalBlobDescriptor(),
Reason = ExecutionReason.Portal
};
FunctionStatusMessage statusMessage = FunctionStatusLogger.CreateFunctionStatusMessage(startMessage);
CancellationToken cancellationToken = new CancellationToken();
string expectedContent = JsonConvert.SerializeObject(statusMessage, JsonSerialization.Settings);
string blobName = string.Format("invocations/{0}/{1}/{2}", _hostId, startMessage.Function.Id, startMessage.FunctionInstanceId);
Mock<IStorageBlockBlob> blobMock = new Mock<IStorageBlockBlob>(MockBehavior.Strict);
blobMock.Setup(p => p.UploadTextAsync(expectedContent, null, null, null, null, cancellationToken)).Returns(Task.FromResult(0));
_containerMock.Setup(p => p.GetBlockBlobReference(blobName)).Returns(blobMock.Object);
string id = await _logger.LogFunctionStartedAsync(startMessage, cancellationToken);
Assert.Null(id);
_containerMock.VerifyAll();
blobMock.VerifyAll();
}
internal static FunctionInstanceSnapshot CreateSnapshot(FunctionStartedMessage message)
{
return new FunctionInstanceSnapshot
{
Id = message.FunctionInstanceId,
HostInstanceId = message.HostInstanceId,
InstanceQueueName = message.InstanceQueueName,
Heartbeat = message.Heartbeat,
FunctionId = new FunctionIdentifier(message.SharedQueueName, message.Function.Id).ToString(),
FunctionFullName = message.Function.FullName,
FunctionShortName = message.Function.ShortName,
Arguments = CreateArguments(message.Function.Parameters, message.Arguments),
ParentId = message.ParentId,
Reason = message.FormatReason(),
QueueTime = message.StartTime,
StartTime = message.StartTime,
OutputBlob = message.OutputBlob,
ParameterLogBlob = message.ParameterLogBlob,
WebSiteName = message.WebJobRunIdentifier != null ? message.WebJobRunIdentifier.WebSiteName : null,
WebJobType = message.WebJobRunIdentifier != null ? message.WebJobRunIdentifier.JobType.ToString() : null,
WebJobName = message.WebJobRunIdentifier != null ? message.WebJobRunIdentifier.JobName : null,
WebJobRunId = message.WebJobRunIdentifier != null ? message.WebJobRunIdentifier.RunId : null
};
}
public void CreateSnapshot_CreatesExpectedSnapshot()
{
FunctionDescriptor function = new FunctionDescriptor
{
Id = "FunctionId",
FullName = "FullName",
ShortName = "ShortName",
Parameters = new ParameterDescriptor[]
{
new ParameterDescriptor {
Name = "param1"
},
new ParameterDescriptor {
Name = "param2"
}
}
};
FunctionStartedMessage message = new FunctionStartedMessage
{
FunctionInstanceId = Guid.NewGuid(),
HostInstanceId = Guid.NewGuid(),
InstanceQueueName = "InstanceQueueName",
Reason = ExecutionReason.AutomaticTrigger,
ReasonDetails = "A trigger fired!",
Heartbeat = new HeartbeatDescriptor
{
InstanceBlobName = "InstanceBlobName",
SharedContainerName = "SharedContainerName",
SharedDirectoryName = "SharedDirectoryName",
ExpirationInSeconds = 5
},
SharedQueueName = "SharedQueueName",
Function = function,
Arguments = new Dictionary <string, string>
{
{ "param1", "foo" },
{ "param2", "bar" }
},
ParentId = Guid.NewGuid(),
StartTime = DateTime.Now,
OutputBlob = new LocalBlobDescriptor {
BlobName = "OutputBlobName", ContainerName = "OutputBlobContainerName"
},
ParameterLogBlob = new LocalBlobDescriptor {
BlobName = "ParameterLogBlobName", ContainerName = "ParameterLogBlobContainerName"
},
WebJobRunIdentifier = new WebJobRunIdentifier {
JobName = "JobName", JobType = WebJobTypes.Triggered, RunId = "RunId", WebSiteName = "WebSiteName"
}
};
FunctionInstanceSnapshot snapshot = FunctionIndexer.CreateSnapshot(message);
Assert.Equal(message.FunctionInstanceId, snapshot.Id);
Assert.Equal(message.HostInstanceId, snapshot.HostInstanceId);
Assert.Equal(message.InstanceQueueName, snapshot.InstanceQueueName);
Assert.Same(message.Heartbeat, snapshot.Heartbeat);
Assert.Equal("SharedQueueName_FunctionId", snapshot.FunctionId);
Assert.Equal(message.Function.FullName, snapshot.FunctionFullName);
Assert.Equal(message.Function.ShortName, snapshot.FunctionShortName);
Assert.Equal(2, snapshot.Arguments.Count);
Assert.Equal("foo", snapshot.Arguments["param1"].Value);
Assert.Equal("bar", snapshot.Arguments["param2"].Value);
Assert.Equal(message.ParentId, snapshot.ParentId);
Assert.Equal(message.ReasonDetails, snapshot.Reason);
Assert.Equal(message.StartTime, snapshot.QueueTime);
Assert.Equal(message.StartTime, snapshot.StartTime);
Assert.Equal(message.OutputBlob, snapshot.OutputBlob);
Assert.Same(message.ParameterLogBlob, snapshot.ParameterLogBlob);
Assert.Equal(message.WebJobRunIdentifier.WebSiteName, snapshot.WebSiteName);
Assert.Equal(message.WebJobRunIdentifier.JobType.ToString(), snapshot.WebJobType);
Assert.Equal(message.WebJobRunIdentifier.JobName, snapshot.WebJobName);
Assert.Equal(message.WebJobRunIdentifier.RunId, snapshot.WebJobRunId);
}
public Task<string> LogFunctionStartedAsync(FunctionStartedMessage message, CancellationToken cancellationToken)
{
Console.WriteLine("Executing: '{0}' - Reason: '{1}'", message.Function.ShortName, message.FormatReason());
return Task.FromResult<string>(null);
}
public Task<string> LogFunctionStartedAsync(FunctionStartedMessage message, CancellationToken cancellationToken)
{
return _queueWriter.EnqueueAsync(message, cancellationToken);
}
public Task<string> LogFunctionStartedAsync(FunctionStartedMessage message, CancellationToken cancellationToken)
{
return Task.FromResult(string.Empty);
}
public Task<string> LogFunctionStartedAsync(FunctionStartedMessage message, CancellationToken cancellationToken)
{
_trace.Info(string.Format(CultureInfo.InvariantCulture, "Executing: '{0}' - Reason: '{1}'", message.Function.ShortName, message.FormatReason()), TraceSource.Execution);
return Task.FromResult<string>(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);
}
Task<string> IFunctionInstanceLogger.LogFunctionStartedAsync(FunctionStartedMessage message,
CancellationToken cancellationToken)
{
return Task.FromResult(string.Empty);
}
public Task <string> LogFunctionStartedAsync(FunctionStartedMessage message, CancellationToken cancellationToken)
{
_trace.Info(string.Format(CultureInfo.InvariantCulture, "Executing: '{0}' - Reason: '{1}'", message.Function.ShortName, message.FormatReason()), TraceSource.Execution);
return(Task.FromResult <string>(null));
}
public Task <string> LogFunctionStartedAsync(FunctionStartedMessage message, CancellationToken cancellationToken)
{
return(Task.FromResult(String.Empty));
}
public async Task LogFunctionStartedAsync_NonPortal_DoesNotWriteBlob()
{
FunctionStartedMessage startMessage = new FunctionStartedMessage
{
Reason = ExecutionReason.Dashboard
};
// Since we haven't set up the mocks, this would throw if it didn't noop
string id = await _logger.LogFunctionStartedAsync(startMessage, CancellationToken.None);
Assert.Null(id);
}
public void CreateSnapshot_CreatesExpectedSnapshot()
{
FunctionDescriptor function = new FunctionDescriptor
{
Id = "FunctionId",
FullName = "FullName",
ShortName = "ShortName",
Parameters = new ParameterDescriptor[]
{
new ParameterDescriptor { Name = "param1" },
new ParameterDescriptor { Name = "param2" }
}
};
FunctionStartedMessage message = new FunctionStartedMessage
{
FunctionInstanceId = Guid.NewGuid(),
HostInstanceId = Guid.NewGuid(),
InstanceQueueName = "InstanceQueueName",
Reason = ExecutionReason.AutomaticTrigger,
ReasonDetails = "A trigger fired!",
Heartbeat = new HeartbeatDescriptor
{
InstanceBlobName = "InstanceBlobName",
SharedContainerName = "SharedContainerName",
SharedDirectoryName = "SharedDirectoryName",
ExpirationInSeconds = 5
},
SharedQueueName = "SharedQueueName",
Function = function,
Arguments = new Dictionary<string, string>
{
{ "param1", "foo" },
{ "param2", "bar" }
},
ParentId = Guid.NewGuid(),
StartTime = DateTime.Now,
OutputBlob = new LocalBlobDescriptor { BlobName = "OutputBlobName", ContainerName = "OutputBlobContainerName" },
ParameterLogBlob = new LocalBlobDescriptor { BlobName = "ParameterLogBlobName", ContainerName = "ParameterLogBlobContainerName" },
WebJobRunIdentifier = new WebJobRunIdentifier { JobName = "JobName", JobType = WebJobTypes.Triggered, RunId = "RunId", WebSiteName = "WebSiteName" }
};
FunctionInstanceSnapshot snapshot = FunctionIndexer.CreateSnapshot(message);
Assert.Equal(message.FunctionInstanceId, snapshot.Id);
Assert.Equal(message.HostInstanceId, snapshot.HostInstanceId);
Assert.Equal(message.InstanceQueueName, snapshot.InstanceQueueName);
Assert.Same(message.Heartbeat, snapshot.Heartbeat);
Assert.Equal("SharedQueueName_FunctionId", snapshot.FunctionId);
Assert.Equal(message.Function.FullName, snapshot.FunctionFullName);
Assert.Equal(message.Function.ShortName, snapshot.FunctionShortName);
Assert.Equal(2, snapshot.Arguments.Count);
Assert.Equal("foo", snapshot.Arguments["param1"].Value);
Assert.Equal("bar", snapshot.Arguments["param2"].Value);
Assert.Equal(message.ParentId, snapshot.ParentId);
Assert.Equal(message.ReasonDetails, snapshot.Reason);
Assert.Equal(message.StartTime, snapshot.QueueTime);
Assert.Equal(message.StartTime, snapshot.StartTime);
Assert.Equal(message.OutputBlob, snapshot.OutputBlob);
Assert.Same(message.ParameterLogBlob, snapshot.ParameterLogBlob);
Assert.Equal(message.WebJobRunIdentifier.WebSiteName, snapshot.WebSiteName);
Assert.Equal(message.WebJobRunIdentifier.JobType.ToString(), snapshot.WebJobType);
Assert.Equal(message.WebJobRunIdentifier.JobName, snapshot.WebJobName);
Assert.Equal(message.WebJobRunIdentifier.RunId, snapshot.WebJobRunId);
}
