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

Update function state change traces to improve orchestration monitoring query #2302

Merged
merged 13 commits into from
Oct 10, 2023
Merged

Update function state change traces to improve orchestration monitoring query #2302

Show file tree
Hide file tree
Changes from 9 commits
Commits
Show all changes
13 commits
Select commit Hold shift + click to select a range
2e0489c
initial commit
bachuv Oct 31, 2022
e55f6da
updated tests
bachuv Nov 16, 2022
adbef6c
modified logs for timer tests
bachuv Nov 16, 2022
32bfab7
updated sequential orchestration test
bachuv Nov 16, 2022
805a1ce
removed functionState property
bachuv Jun 28, 2023
651ab9c
added state change log for Suspend
bachuv Aug 7, 2023
5b58f59
removed additional state trace and added RuntimeStatus field to exist…
bachuv Aug 7, 2023
469c4cc
Merge branch 'dev' into vabachu/addingfunctionstatetraces
bachuv Aug 7, 2023
2f004bd
removed package reference added on accident
bachuv Aug 9, 2023
122b4eb
updating resuming orchestrator runtime status
bachuv Oct 9, 2023
7e31206
Merge branch 'dev' into vabachu/addingfunctionstatetraces
bachuv Oct 9, 2023
e8d96e2
updating timer test log message check
bachuv Oct 9, 2023
27f85cc
updated event grid api test expected logs
bachuv Oct 10, 2023
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
44 changes: 22 additions & 22 deletions src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -116,8 +116,8 @@ public void FunctionScheduled(
isReplay);

this.logger.LogInformation(
"{instanceId}: Function '{functionName} ({functionType})' scheduled. Reason: {reason}. IsReplay: {isReplay}. State: {state}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.",
instanceId, functionName, functionType, reason, isReplay, FunctionState.Scheduled, hubName,
"{instanceId}: Function '{functionName} ({functionType})' scheduled. Reason: {reason}. IsReplay: {isReplay}. State: {state}. RuntimeStatus: {runtimeStatus}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.",
instanceId, functionName, functionType, reason, isReplay, FunctionState.Scheduled, OrchestrationRuntimeStatus.Pending, hubName,
LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++);
}
}
Expand Down Expand Up @@ -146,8 +146,8 @@ public void FunctionStarting(
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}. TaskEventId: {taskEventId}",
instanceId, functionName, functionType, isReplay, input, FunctionState.Started, hubName,
"{instanceId}: Function '{functionName} ({functionType})' started. IsReplay: {isReplay}. Input: {input}. State: {state}. RuntimeStatus: {runtimeStatus}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}. TaskEventId: {taskEventId}",
instanceId, functionName, functionType, isReplay, input, FunctionState.Started, OrchestrationRuntimeStatus.Running, hubName,
LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++, taskEventId);
}
}
Expand Down Expand Up @@ -233,9 +233,9 @@ public void FunctionCompleted(
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}. TaskEventId: {taskEventId}",
instanceId, functionName, functionType, continuedAsNew, isReplay, output, FunctionState.Completed,
hubName, LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++, taskEventId);
"{instanceId}: Function '{functionName} ({functionType})' completed. ContinuedAsNew: {continuedAsNew}. IsReplay: {isReplay}. Output: {output}. State: {state}. RuntimeStatus: {runtimeStatus}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}. TaskEventId: {taskEventId}",
instanceId, functionName, functionType, continuedAsNew, isReplay, output, FunctionState.Completed, OrchestrationRuntimeStatus.Completed, hubName,
LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++, taskEventId);
}
}

Expand Down Expand Up @@ -279,9 +279,9 @@ public void FunctionTerminated(
IsReplay: false);

this.logger.LogWarning(
"{instanceId}: Function '{functionName} ({functionType})' was terminated. Reason: {reason}. State: {state}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.",
instanceId, functionName, functionType, reason, FunctionState.Terminated, hubName, LocalAppName,
LocalSlotName, ExtensionVersion, this.sequenceNumber++);
"{instanceId}: Function '{functionName} ({functionType})' was terminated. Reason: {reason}. State: {state}. RuntimeStatus: {runtimeStatus}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.",
instanceId, functionName, functionType, reason, FunctionState.Terminated, OrchestrationRuntimeStatus.Terminated, hubName,
LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++);
}

public void SuspendingOrchestration(
Expand All @@ -304,9 +304,9 @@ public void SuspendingOrchestration(
IsReplay: false);

this.logger.LogInformation(
"{instanceId}: Suspending function '{functionName} ({functionType})'. Reason: {reason}. State: {state}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.",
instanceId, functionName, functionType, reason, FunctionState.Suspended, hubName, LocalAppName,
LocalSlotName, ExtensionVersion, this.sequenceNumber++);
"{instanceId}: Suspending function '{functionName} ({functionType})'. Reason: {reason}. State: {state}. RuntimeStatus: {runtimeStatus}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.",
instanceId, functionName, functionType, reason, FunctionState.Suspended, OrchestrationRuntimeStatus.Suspended, hubName,
LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++);
}

public void ResumingOrchestration(
Expand All @@ -329,9 +329,9 @@ public void ResumingOrchestration(
IsReplay: false);

this.logger.LogInformation(
"{instanceId}: Resuming function '{functionName} ({functionType})'. Reason: {reason}. State: {state}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.",
instanceId, functionName, functionType, reason, FunctionState.Scheduled, hubName, LocalAppName,
LocalSlotName, ExtensionVersion, this.sequenceNumber++);
"{instanceId}: Resuming function '{functionName} ({functionType})'. Reason: {reason}. State: {state}. RuntimeStatus: {runtimeStatus}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.",
instanceId, functionName, functionType, reason, FunctionState.Scheduled, OrchestrationRuntimeStatus.Pending, hubName,
bachuv marked this conversation as resolved.
Show resolved Hide resolved
LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++);
}

public void FunctionRewound(
Expand All @@ -355,8 +355,8 @@ public void FunctionRewound(

this.logger.LogWarning(
"{instanceId}: Function '{functionName} ({functionType})' was rewound. Reason: {reason}. State: {state}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.",
instanceId, functionName, functionType, reason, FunctionState.Rewound, hubName, LocalAppName,
LocalSlotName, ExtensionVersion, this.sequenceNumber++);
instanceId, functionName, functionType, reason, FunctionState.Rewound, hubName,
LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++);
}

public void FunctionFailed(
Expand All @@ -383,8 +383,8 @@ public void FunctionFailed(
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}. TaskEventId: {taskEventId}",
instanceId, functionName, functionType, reason, isReplay, FunctionState.Failed, hubName,
"{instanceId}: Function '{functionName} ({functionType})' failed with an error. Reason: {reason}. IsReplay: {isReplay}. State: {state}. RuntimeStatus: {runtimeStatus}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}. TaskEventId: {taskEventId}",
instanceId, functionName, functionType, reason, isReplay, FunctionState.Failed, OrchestrationRuntimeStatus.Failed, hubName,
LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++, taskEventId);
}
}
Expand Down Expand Up @@ -953,8 +953,8 @@ public void TimerExpired(

this.logger.LogInformation(
"{instanceId}: Function '{functionName} ({functionType})' was resumed by a timer scheduled for '{expirationTime}'. IsReplay: {isReplay}. State: {state}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.",
instanceId, functionName, functionType, expirationTimeString, isReplay, FunctionState.TimerExpired,
hubName, LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++);
instanceId, functionName, functionType, expirationTimeString, isReplay, FunctionState.TimerExpired, hubName,
LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++);
}
}

Expand Down
10 changes: 5 additions & 5 deletions test/Common/TestHelpers.cs
View file
Open in desktop
bachuv marked this conversation as resolved.
Show resolved Hide resolved
Original file line number Diff line number Diff line change
Expand Up @@ -483,8 +483,8 @@ private static List<LogMessage> GetLogMessages(
if (testName.Equals("TimerCancellation", StringComparison.OrdinalIgnoreCase) ||
testName.Equals("TimerExpiration", StringComparison.OrdinalIgnoreCase))
{
// It is assumed that the 4th log message is a timer message.
timeStamp = GetTimerTimestamp(logMessages[3].FormattedMessage);
// It is assumed that the 5th log message is a timer message.
timeStamp = GetTimerTimestamp(logMessages[4].FormattedMessage);
bachuv marked this conversation as resolved.
Show resolved Hide resolved
}
else if (testName.Equals("Orchestration_OnValidOrchestrator", StringComparison.OrdinalIgnoreCase) ||
testName.Equals("Orchestration_Activity", StringComparison.OrdinalIgnoreCase))
Expand Down Expand Up @@ -608,9 +608,9 @@ private static List<string> GetLogs_OrchestrationEventGridApiReturnBadStatus(str
{
var list = new List<string>()
{
$"{messageId}: Function '{functionNames[0]} ({FunctionType.Orchestrator})' scheduled. Reason: NewInstance. IsReplay: False. State: Scheduled.",
$"{messageId}: Function '{functionNames[0]} ({FunctionType.Orchestrator})' started. IsReplay: False. Input: \"World\". State: Started.",
$"{messageId}: Function '{functionNames[0]} ({FunctionType.Orchestrator})' completed. ContinuedAsNew: False. IsReplay: False. Output: \"Hello, World!\". State: Completed.",
$"{messageId}: Function '{functionNames[0]} ({FunctionType.Orchestrator})' scheduled. Reason: NewInstance. IsReplay: False. State: Scheduled. RuntimeState: Pending.",
$"{messageId}: Function '{functionNames[0]} ({FunctionType.Orchestrator})' started. IsReplay: False. Input: \"World\". State: Started. RuntimeState: Running.",
$"{messageId}: Function '{functionNames[0]} ({FunctionType.Orchestrator})' completed. ContinuedAsNew: False. IsReplay: False. Output: \"Hello, World!\". State: Completed. RuntimeState: Completed",
$"{messageId}: Function '{functionNames[0]} ({FunctionType.Orchestrator})' failed to send a 'Started' notification event to Azure Event Grid. Status code: 500. Details: {{\"message\":\"Exception has been thrown\"}}. ",
$"{messageId}: Function '{functionNames[0]} ({FunctionType.Orchestrator})' failed to send a 'Completed' notification event to Azure Event Grid. Status code: 500. Details: {{\"message\":\"Exception has been thrown\"}}. ",
};
Expand Down