Skip to content

Add TimingProperty with step timing to internal test framework test nodes #6882

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

Open
wants to merge 9 commits into
base: main
Choose a base branch
from
+64 −15
Open

Add TimingProperty with step timing to internal test framework test nodes #6882

Changes from all commits
Commits
Show all changes
9 commits
Select commit Hold shift + click to select a range
e091994
Initial plan
Copilot Nov 4, 2025
b47a317
Add TimingProperty to test nodes in TestFrameworkEngine
Copilot Nov 4, 2025
8b21bfd
Address code review feedback: initialize variables and extract timing…
Copilot Nov 4, 2025
df8cf2f
Add step timing for init, test, and cleanup phases
Copilot Nov 4, 2025
0cd417f
Update test/Utilities/TestFramework.ForTestingMSTest/TestFrameworkEng…
Evangelink Nov 4, 2025
697ff51
Update test/Utilities/TestFramework.ForTestingMSTest/TestFrameworkEng…
Evangelink Nov 4, 2025
e51aee2
Merge branch 'main' into copilot/add-timingproperty-to-test-nodes
Evangelink Nov 4, 2025
a963a3e
Apply suggestion from @Evangelink
Evangelink Nov 5, 2025
340bae2
Fix diagnostics
Evangelink Nov 16, 2025
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
79 changes: 64 additions & 15 deletions test/Utilities/TestFramework.ForTestingMSTest/TestFrameworkEngine.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -107,16 +107,39 @@ [.. publicMethod.GetParameters().Select(x => x.ParameterType.FullName!)],
progressNode.Properties.Add(InProgressTestNodeStateProperty.CachedInstance);
await messageBus.PublishAsync(this, new TestNodeUpdateMessage(request.Session.SessionUid, progressNode));

DateTimeOffset startTime = DateTimeOffset.UtcNow;
bool isSuccessRun = false;
bool isSuccessTeardown = false;
List<StepTimingInfo> stepTimings = [];

object? testClassInstance = await TryRunSetupMethodAsync(testContainerType, setupMethod, testNode, PublishNodeUpdateAsync);
if (testClassInstance is not null)
try
{
isSuccessRun = await RunTestMethodAsync(testClassInstance, publicMethod, testNode, PublishNodeUpdateAsync);
(object? testClassInstance, StepTimingInfo? setupTiming) = await TryRunSetupMethodAsync(testContainerType, setupMethod, testNode, PublishNodeUpdateAsync);
if (setupTiming is not null)
{
stepTimings.Add(setupTiming);
}

if (testClassInstance is not null)
{
(isSuccessRun, StepTimingInfo? testTiming) = await RunTestMethodAsync(testClassInstance, publicMethod, testNode, PublishNodeUpdateAsync);
if (testTiming is not null)
{
stepTimings.Add(testTiming);
}
}

// Always call teardown even if previous steps failed because we want to try to clean as much as we can.
(isSuccessTeardown, StepTimingInfo? teardownTiming) = await RunTestTeardownAsync(testClassInstance, testContainerType, teardownMethod, testNode, PublishNodeUpdateAsync);
if (teardownTiming is not null)
{
stepTimings.Add(teardownTiming);
}
}
finally
{
testNode.Properties.Add(CreateTimingProperty(startTime, stepTimings));
}

// Always call teardown even if previous steps failed because we want to try to clean as much as we can.
bool isSuccessTeardown = await RunTestTeardownAsync(testClassInstance, testContainerType, teardownMethod, testNode, PublishNodeUpdateAsync);

if (isSuccessRun && isSuccessTeardown)
{
Expand Down Expand Up @@ -199,29 +222,37 @@ private static bool IsTestContainer(Type typeInfo)
return false;
}

private async Task<object?> TryRunSetupMethodAsync(TypeInfo testContainerType, ConstructorInfo setupMethod, TestNode testNode,
private async Task<(object? TestClassInstance, StepTimingInfo? SetupTiming)> TryRunSetupMethodAsync(TypeInfo testContainerType, ConstructorInfo setupMethod, TestNode testNode,
Func<TestNode, Task> publishNodeUpdateAsync)
{
DateTimeOffset stepStartTime = DateTimeOffset.UtcNow;
try
{
_logger.LogDebug($"Executing test '{testNode.DisplayName}' setup (ctor for '{testContainerType.FullName}')");
return setupMethod.Invoke(null);
object? instance = setupMethod.Invoke(null);
DateTimeOffset stepEndTime = DateTimeOffset.UtcNow;
return (instance, new StepTimingInfo("init", "Test initialization", new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime)));
}
catch (Exception ex)
{
Exception realException = ex.InnerException ?? ex;
_logger.LogError("Error during test setup", realException);
DateTimeOffset stepEndTime = DateTimeOffset.UtcNow;
TestNode errorNode = CloneTestNode(testNode);
errorNode.Properties.Add(new TimingProperty(
Copy link
Member

@Youssef1313 Youssef1313 Nov 16, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In case of errors, won't we add the timing property twice? Once here in the catch, and once in the finally from the caller?

new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime),
[new StepTimingInfo("init", "Test initialization", new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime))]));
errorNode.Properties.Add(new ErrorTestNodeStateProperty(ex));
errorNode.Properties.Add(new TrxExceptionProperty(ex.Message, ex.StackTrace));
await publishNodeUpdateAsync(errorNode);
return null;
return (null, null);
}
}

private async Task<bool> RunTestMethodAsync(object testClassInstance, MethodInfo publicMethod, TestNode testNode,
private async Task<(bool IsSuccess, StepTimingInfo? TestTiming)> RunTestMethodAsync(object testClassInstance, MethodInfo publicMethod, TestNode testNode,
Func<TestNode, Task> publishNodeUpdateAsync)
{
DateTimeOffset stepStartTime = DateTimeOffset.UtcNow;
try
{
_logger.LogDebug($"Executing test '{testNode.DisplayName}'");
Expand All @@ -230,24 +261,30 @@ private async Task<bool> RunTestMethodAsync(object testClassInstance, MethodInfo
await task;
}

return true;
DateTimeOffset stepEndTime = DateTimeOffset.UtcNow;
return (true, new StepTimingInfo("test", "Test method execution", new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime)));
}
catch (Exception ex)
{
Exception realException = ex is TargetInvocationException ? ex.InnerException! : ex;
_logger.LogError("Error during test", realException);
DateTimeOffset stepEndTime = DateTimeOffset.UtcNow;
TestNode errorNode = CloneTestNode(testNode);
errorNode.Properties.Add(new TimingProperty(
new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime),
[new StepTimingInfo("test", "Test method execution", new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime))]));
errorNode.Properties.Add(new ErrorTestNodeStateProperty(realException));
errorNode.Properties.Add(new TrxExceptionProperty(realException.Message, realException.StackTrace));
await publishNodeUpdateAsync(errorNode);

return false;
return (false, null);
}
}

private async Task<bool> RunTestTeardownAsync(object? testClassInstance, TypeInfo testContainerType, MethodInfo teardownMethod, TestNode testNode,
private async Task<(bool IsSuccess, StepTimingInfo? TeardownTiming)> RunTestTeardownAsync(object? testClassInstance, TypeInfo testContainerType, MethodInfo teardownMethod, TestNode testNode,
Func<TestNode, Task> publishNodeUpdateAsync)
{
DateTimeOffset stepStartTime = DateTimeOffset.UtcNow;
try
{
if (testClassInstance is not null)
Expand All @@ -256,20 +293,32 @@ private async Task<bool> RunTestTeardownAsync(object? testClassInstance, TypeInf
teardownMethod.Invoke(testClassInstance, null);
}

return true;
DateTimeOffset stepEndTime = DateTimeOffset.UtcNow;
return (true, new StepTimingInfo("cleanup", "Test cleanup", new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime)));
}
catch (Exception ex)
{
Exception realException = ex.InnerException ?? ex;
_logger.LogError("Error during test teardown", realException);
DateTimeOffset stepEndTime = DateTimeOffset.UtcNow;
TestNode errorNode = CloneTestNode(testNode);
errorNode.Properties.Add(new TimingProperty(
new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime),
[new StepTimingInfo("cleanup", "Test cleanup", new TimingInfo(stepStartTime, stepEndTime, stepEndTime - stepStartTime))]));
errorNode.Properties.Add(new ErrorTestNodeStateProperty(ex));
await publishNodeUpdateAsync(errorNode);

return false;
return (false, null);
}
}

private static TimingProperty CreateTimingProperty(DateTimeOffset startTime, List<StepTimingInfo> stepTimings)
{
DateTimeOffset endTime = DateTimeOffset.UtcNow;
TimeSpan duration = endTime - startTime;
return new TimingProperty(new TimingInfo(startTime, endTime, duration), [.. stepTimings]);
}

private static TestNode CloneTestNode(TestNode testNode)
=> new()
{
Expand Down