Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add TaskEventId to function traces #1386

Merged
merged 3 commits into from
Jun 16, 2020
Merged

Add TaskEventId to function traces #1386

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
3c6f0d4
Add TaskEventId to function traces
cgillum Jun 16, 2020
26a378a
Merge branch 'dev' into task-event-ids2
cgillum Jun 16, 2020
f3f6f11
PR feedback - comments
cgillum Jun 16, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 12 additions & 0 deletions src/WebJobs.Extensions.DurableTask/DurableTaskExtension.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -291,6 +291,7 @@ void IExtensionConfigProvider.Initialize(ExtensionConfigContext context)
.BindToTrigger(new EntityTriggerAttributeBindingProvider(this, context, storageConnectionString, this.TraceHelper));

this.taskHubWorker = new TaskHubWorker(this.defaultDurabilityProvider, this, this);
this.taskHubWorker.AddActivityDispatcherMiddleware(this.ActivityMiddleware);
this.taskHubWorker.AddOrchestrationDispatcherMiddleware(this.EntityMiddleware);
this.taskHubWorker.AddOrchestrationDispatcherMiddleware(this.OrchestrationMiddleware);

Expand Down Expand Up @@ -465,6 +466,17 @@ TaskActivity INameVersionObjectManager<TaskActivity>.GetObject(string name, stri
return new TaskActivityShim(this, info.Executor, this.hostLifetimeService, name);
}

private Task ActivityMiddleware(DispatchMiddlewareContext dispatchContext, Func<Task> next)
cgillum marked this conversation as resolved.
Show resolved Hide resolved
{
if (dispatchContext.GetProperty<TaskActivity>() is TaskActivityShim shim)
{
TaskScheduledEvent @event = dispatchContext.GetProperty<TaskScheduledEvent>();
shim.SetTaskEventId(@event?.EventId ?? -1);
}

return next();
}

private async Task OrchestrationMiddleware(DispatchMiddlewareContext dispatchContext, Func<Task> next)
{
TaskOrchestrationShim shim = dispatchContext.GetProperty<TaskOrchestration>() as TaskOrchestrationShim;
Expand Down
37 changes: 26 additions & 11 deletions src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -128,13 +128,15 @@ public void FunctionStarting(
string instanceId,
string input,
FunctionType functionType,
bool isReplay)
bool isReplay,
int taskEventId = -1)
{
EtwEventSource.Instance.FunctionStarting(
hubName,
LocalAppName,
LocalSlotName,
functionName,
taskEventId,
instanceId,
input,
functionType.ToString(),
Expand All @@ -144,9 +146,9 @@ public void FunctionStarting(
if (this.ShouldLogEvent(isReplay))
{
this.logger.LogInformation(
"{instanceId}: Function '{functionName} ({functionType})' started. IsReplay: {isReplay}. Input: {input}. State: {state}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.",
"{instanceId}: Function '{functionName} ({functionType})' started. IsReplay: {isReplay}. Input: {input}. State: {state}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}. TaskEventId: {taskEventId}",
instanceId, functionName, functionType, isReplay, input, FunctionState.Started, hubName,
LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++);
LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++, taskEventId);
}
}

Expand Down Expand Up @@ -212,13 +214,15 @@ public void FunctionCompleted(
string output,
bool continuedAsNew,
FunctionType functionType,
bool isReplay)
bool isReplay,
int taskEventId = -1)
{
EtwEventSource.Instance.FunctionCompleted(
hubName,
LocalAppName,
LocalSlotName,
functionName,
taskEventId,
instanceId,
output,
continuedAsNew,
Expand All @@ -229,9 +233,9 @@ public void FunctionCompleted(
if (this.ShouldLogEvent(isReplay))
{
this.logger.LogInformation(
"{instanceId}: Function '{functionName} ({functionType})' completed. ContinuedAsNew: {continuedAsNew}. IsReplay: {isReplay}. Output: {output}. State: {state}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.",
"{instanceId}: Function '{functionName} ({functionType})' completed. ContinuedAsNew: {continuedAsNew}. IsReplay: {isReplay}. Output: {output}. State: {state}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}. TaskEventId: {taskEventId}",
instanceId, functionName, functionType, continuedAsNew, isReplay, output, FunctionState.Completed,
hubName, LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++);
hubName, LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++, taskEventId);
}
}

Expand Down Expand Up @@ -299,16 +303,27 @@ public void FunctionFailed(
string instanceId,
string reason,
FunctionType functionType,
bool isReplay)
bool isReplay,
int taskEventId = -1)
{
EtwEventSource.Instance.FunctionFailed(hubName, LocalAppName, LocalSlotName, functionName,
instanceId, reason, functionType.ToString(), ExtensionVersion, isReplay);
EtwEventSource.Instance.FunctionFailed(
hubName,
LocalAppName,
LocalSlotName,
functionName,
taskEventId,
instanceId,
reason,
functionType.ToString(),
ExtensionVersion,
isReplay);

if (this.ShouldLogEvent(isReplay))
{
this.logger.LogError(
"{instanceId}: Function '{functionName} ({functionType})' failed with an error. Reason: {reason}. IsReplay: {isReplay}. State: {state}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.",
"{instanceId}: Function '{functionName} ({functionType})' failed with an error. Reason: {reason}. IsReplay: {isReplay}. State: {state}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}. TaskEventId: {taskEventId}",
instanceId, functionName, functionType, reason, isReplay, FunctionState.Failed, hubName,
LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++);
LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++, taskEventId);
}
}

Expand Down
15 changes: 9 additions & 6 deletions src/WebJobs.Extensions.DurableTask/EtwEventSource.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -34,19 +34,20 @@ public void FunctionScheduled(
this.WriteEvent(201, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay);
}

[Event(202, Level = EventLevel.Informational, Version = 4)]
[Event(202, Level = EventLevel.Informational, Version = 5)]
public void FunctionStarting(
string TaskHub,
string AppName,
string SlotName,
string FunctionName,
int TaskEventId,
string InstanceId,
string Input,
string FunctionType,
string ExtensionVersion,
bool IsReplay)
{
this.WriteEvent(202, TaskHub, AppName, SlotName, FunctionName, InstanceId, Input ?? "(null)", FunctionType, ExtensionVersion, IsReplay);
this.WriteEvent(202, TaskHub, AppName, SlotName, FunctionName, TaskEventId, InstanceId, Input ?? "(null)", FunctionType, ExtensionVersion, IsReplay);
}

[Event(203, Level = EventLevel.Informational, Version = 4)]
Expand Down Expand Up @@ -94,20 +95,21 @@ public void ExternalEventRaised(
this.WriteEvent(205, TaskHub, AppName, SlotName, FunctionName, InstanceId, EventName, Input ?? "(null)", FunctionType, ExtensionVersion, IsReplay);
}

[Event(206, Level = EventLevel.Informational, Version = 4)]
[Event(206, Level = EventLevel.Informational, Version = 5)]
public void FunctionCompleted(
string TaskHub,
string AppName,
string SlotName,
string FunctionName,
int TaskEventId,
string InstanceId,
string Output,
bool ContinuedAsNew,
string FunctionType,
string ExtensionVersion,
bool IsReplay)
{
this.WriteEvent(206, TaskHub, AppName, SlotName, FunctionName, InstanceId, Output ?? "(null)", ContinuedAsNew, FunctionType, ExtensionVersion, IsReplay);
this.WriteEvent(206, TaskHub, AppName, SlotName, FunctionName, TaskEventId, InstanceId, Output ?? "(null)", ContinuedAsNew, FunctionType, ExtensionVersion, IsReplay);
}

[Event(207, Level = EventLevel.Warning, Version = 2)]
Expand All @@ -125,19 +127,20 @@ public void FunctionTerminated(
this.WriteEvent(207, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay);
}

[Event(208, Level = EventLevel.Error, Version = 3)]
[Event(208, Level = EventLevel.Error, Version = 4)]
public void FunctionFailed(
string TaskHub,
string AppName,
string SlotName,
string FunctionName,
int TaskEventId,
string InstanceId,
string Reason,
string FunctionType,
string ExtensionVersion,
bool IsReplay)
{
this.WriteEvent(208, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay);
this.WriteEvent(208, TaskHub, AppName, SlotName, FunctionName, TaskEventId, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay);
}

[Event(209, Level = EventLevel.Informational, Version = 2)]
Expand Down
16 changes: 13 additions & 3 deletions src/WebJobs.Extensions.DurableTask/Listener/TaskActivityShim.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,8 @@ internal class TaskActivityShim : TaskActivity
private readonly IApplicationLifetimeWrapper hostServiceLifetime;
private readonly string activityName;

private int taskEventId = -1;

public TaskActivityShim(
DurableTaskExtension config,
ITriggeredFunctionExecutor executor,
Expand Down Expand Up @@ -56,7 +58,8 @@ public override async Task<string> RunAsync(TaskContext context, string rawInput
instanceId,
this.config.GetIntputOutputTrace(rawInput),
functionType: FunctionType.Activity,
isReplay: false);
isReplay: false,
taskEventId: this.taskEventId);

WrappedFunctionResult result = await FunctionExecutionHelper.ExecuteActivityFunction(
this.executor,
Expand All @@ -74,7 +77,8 @@ public override async Task<string> RunAsync(TaskContext context, string rawInput
this.config.GetIntputOutputTrace(serializedOutput),
continuedAsNew: false,
functionType: FunctionType.Activity,
isReplay: false);
isReplay: false,
taskEventId: this.taskEventId);

return serializedOutput;
case WrappedFunctionResult.FunctionResultStatus.FunctionsRuntimeError:
Expand Down Expand Up @@ -106,7 +110,8 @@ public override async Task<string> RunAsync(TaskContext context, string rawInput
instanceId,
exceptionToReport?.ToString() ?? string.Empty,
functionType: FunctionType.Activity,
isReplay: false);
isReplay: false,
taskEventId: this.taskEventId);

throw new TaskFailureException(
$"Activity function '{this.activityName}' failed: {exceptionToReport.Message}",
Expand All @@ -122,6 +127,11 @@ public override string Run(TaskContext context, string input)
throw new NotImplementedException();
}

internal void SetTaskEventId(int taskEventId)
cgillum marked this conversation as resolved.
Show resolved Hide resolved
{
this.taskEventId = taskEventId;
}

private static Exception StripFunctionInvocationException(Exception e)
{
var infrastructureException = e as FunctionInvocationException;
Expand Down