Proper test result exception message when hitting TimeoutAttribute

[Prodigio]

Hey guys,

lately I was expetimenting with the TimeoutAttribute and ran into a few timeouts for my tests. I only saw a Exception doesn't have a stacktrace as a test result message, which confused me at first sight. Then I realized, the test were hitting the timeout.

I tried to dig into the code to see, if implementing a timeout exception message is possible, but havn't found anything so far.

So I'd like to suggest a better test result message when hitting the timeout.

Code to reproduce:

[Test]
[Timeout(1000)]
public async Task Timeout()
{
    // Arrange

    // Act
    await Task.Delay(2000).ConfigureAwait(false);

    // Assert
    Assert.Pass();
}

Thanks and kind regards

[mikkelbu]

Hi @Prodigio

How are you running the tests (VS, dotnet test, or the console runner), which framework are you targeting, and which versions of NUnit, NUnit3TestAdapter, and console runner are you using?

Some initial skimming of the code could indicate that for dotnet core we don't set the message, but only set the label. Compare (framework flow)

nunit/src/NUnitFramework/framework/Internal/Commands/TimeoutCommand.cs

Line 83 in b34eba3

context.CurrentResult.SetResult(ResultState.Failure, $"Test exceeded Timeout value of {timeout}ms");

against (dotnet core flow)

nunit/src/NUnitFramework/framework/Internal/Commands/TimeoutCommand.cs

Lines 110 to 113 in b34eba3

	context.CurrentResult.SetResult(new ResultState(
	TestStatus.Failed,
	$"Test exceeded Timeout value {_timeout}ms.",
	FailureSite.Test));

Also compare the difference in the tests TimeoutCausesOtherwisePassingTestToFailWithoutDebuggerAttached(). Dotnet framework version

nunit/src/NUnitFramework/tests/Attributes/TimeoutTests.cs

Lines 297 to 299 in b34eba3

	Assert.That(result.ResultState.Status, Is.EqualTo(TestStatus.Failed));
	Assert.That(result.ResultState.Site, Is.EqualTo(FailureSite.Test));
	Assert.That(result.Message, Is.EqualTo($"Test exceeded Timeout value of {SampleTests.Timeout}ms"));

dotnet core version

nunit/src/NUnitFramework/tests/Attributes/TimeoutTests.cs

Lines 367 to 369 in b34eba3

	Assert.That(result.ResultState.Status, Is.EqualTo(TestStatus.Failed));
	Assert.That(result.ResultState.Site, Is.EqualTo(FailureSite.Test));
	Assert.That(result.ResultState.Label, Is.EqualTo($"Test exceeded Timeout value {SampleTests.Timeout}ms."));

I'm unsure if this difference is on purpose, but it looks like an mistake. Since we don't write anything in the message for dotnet core, the resulting XML does not contain any information and thus it cannot be presented for the user. On dotnet framework the test will have the following error message Test exceeded Timeout value of 1000ms

[Prodigio]

Hey @mikkelbu,

sorry for the missing information. Here it is:

• Locally I'm executing our tests with Resharper within VS 2019
• Our CI server is TeamCity, where we execute the "bare" tests on the one hand with dotnet test and on the other with the help of NUKE and dotnet test, for some coverage reports
• Targeting .NET Core 3.1 in all test projects

I do see the same message Exception doesn't have a stacktrace locally and on TeamCity.

I'm not using the console. Other NUnit versions are:

• NUnit v3.13.2
• NUnit.Engine v3.12.0
• NUnit3TestAdapter v4.0.0-beta.2

I noticed, that besides NUnit we also have Microsoft.NET.Test.Sdk v.16.9.4 installed as NuGet package. Could this be an issue?

Thanks!

[mikkelbu]

Hi @Prodigio

Thanks for all the information. I'm quite sure that the missing information is since you are targeting .NET Core 3.1 and we have made an mistake in #3190.

That being said I don't think that we record stacktrace when the test fail due to a timeout, as we don't know how far in the code we are (so where exactly should the stacktrace point to). The two calls to context.CurrentResult.SetResult above have a third argument which is the stacktrace, but we don't fill it in.

But I think we should fix the .NET Core flow, so we also report Test exceeded Timeout value ... as a message.

[lsokolova]

Hi @mikkelbu,
We are switching from .net4.8 to .net6.
We use the Timeout attribute in our tests. To make sure some cleaning is done when a test times out, we wrap the test method into try-finally. Example:

[Test, EndToEnd, Timeout(5000)]
        [TestCaseSource(nameof(_testCaseSource))]
        public void TestSearchedDocuments(IEndToEndConfigData configData)
        {
            try
            {
                AssertDocumentsAreIndexedAndMatchingSnapshots(configData);
            }
            finally
            {
                DeleteSource();
            }
        }

This works fine in .net4.8, DeleteSource() is executed when the test times out. But it is not executed in .net6.

I wonder if our issue is related to this one?

Btw, I see #3190 is merged but we are still having that issue.

Our versions:

• NUnit v3.13.2
• NUnit3TestAdapter v.4.1.0

Thank you!

[manfred-brands]

@lsokolova In .NET Framework, NUnit uses Thread.Abort to cancel a test when it exceeds the allowed time. This functionality is no longer available in .NETCore (nor .NET6), so any test that is subject to a Timeout keeps running in the background and if that test shares state (member fields or otherwise) you might get surprising issues.
It actually makes the TimeoutAttribute dangerous as tests can run in parallel when test might not expect this.

[Test, Timeout(1100)]
public void Check()
{
    try
    {
        for (int i = 0; i < 10; i++)
        {
            Console.WriteLine(i);
            Thread.Sleep(1000);
        }
        Assert.Pass("Success");
    }
    catch (Exception ex)
    {
        Console.WriteLine(ex.Message);
    }
    finally
    {
        Console.WriteLine("Task finished");
    }
}

In .NET48, the above test prints both Thread was being aborted. and Task finished
In .NET6.0 it shows neither.

However, if you change Console.Writeline to something like File.AppendAllLines you can see that the net6.0 test runs to the end. (You will have to add another long test so the runner doesn't exit before the code finishes).
So although the runner claims the test timed out, it actually keeps running until it either finishes or the runner exits after all other tests have completed.

NET Core and later only uses cooperative CancellationToken which needs to be passed in and checked by your code.
Unfortunately, I don't see a CancellationToken in NUnit's TestContext you could use.

[lsokolova]

Thank you for your answer @manfred-brands.
Are there any thoughts of adding a CancellationToken in NUnit's TestContext that could be used to time out the tests?

[manfred-brands]

@lsokolova I don't see any open issues about it. So I created one #4021

To make it work, the developer would not only have to re-write the tests but also the user code so that the CancellationToken is passed down into non-test user code. This would work if user code already expects one, but in that case you can easily do this with your own:

using CancellationTokenSource cancellationTokenSource = new CancellationTokenSource(5000);
CancellationToken cancellationToken = cancellationTokenSource.Token;

Adding this to TestContext make it easier and removes duplication.

[bormm]

With >= .net5 I don't see any timeout related message at all:

Its just failing without reason.

Using "Microsoft.NET.Test.Sdk" Version="17.0.0", "NUnit" Version="3.13.2", "NUnit3TestAdapter" Version="4.2.1".

[loop-evgeny]

Also running into this with .NET Core 3.1. No useful message shown with either dotnet test, VS 2022 or Rider - very frustrating to debug, especially when it only times out sometimes!

[manfred-brands]

I added this as part of #4025, but as that is stalled, I might need to separate the message fix from the cancellation part.

[loop-evgeny]

That would be nice! I was considering removing the use of TimeoutAttribute from our test code and adding a unit test that checks via Reflection if it's used to prevent other developers from wasting their time on this.

[manfred-brands]

Temporary nuget package available from PR build artifacts

[loop-evgeny]

Could we have a release with this fix, please?

[eatdrinksleepcode]

@manfred-brands Running "dotnet test" with the .NET 6 SDK and the latest versions of the NUnit (3.13.3) and NUnit3TestAdapter (4.3.1) packages still does not produce any message upon test timeout. Any idea what we need to do to get this fix into a production release?

[mikkelbu]

#4118 has milestone 3.13.4, so this will be part of the next release, and this still have some outstanding items - https://github.com/nunit/nunit/milestone/42 - I guess some of them can be postponed. I think we have other bugs that also should be part of this milestone, but I don't have time to check it closely today.