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()); }
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" }; 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); }
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 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); }