DefaultTimeout in .runsettings + TearDown method seems to break test output

[patrykpiotrmarek]

NUnit v4.0.1 (regression after upgrade from 3.x)

I have simple test class with TestContext.WriteLine in test method and TearDown method.

[TestFixture]
public class Tests
{
    [Test]
    public void Test1()
    {
        TestContext.WriteLine("line1");
        Assert.That(1, Is.EqualTo(0));
    }

    [TearDown]
    public void TearDown()
    {
    }
}

and .runsettings file with DefaultTimeout setting

<?xml version="1.0" encoding="utf-8"?>
<RunSettings>
  <NUnit>
    <DefaultTimeout>600000</DefaultTimeout>
  </NUnit>
</RunSettings>

When I run this code from dotnet test with --settings parameter, there is no output message other than assertion.

PS C:\NUnitTest\NUnitTest\bin\Debug\net8.0> dotnet test NUnitTest.dll --settings .\nunit.runsettings
Microsoft (R) Test Execution Command Line Tool Version 17.8.0 (x64)
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
  Failed Test1 [20 ms]
  Error Message:
     Assert.That(1, Is.EqualTo(0))
  Expected: 0
  But was:  1

  Stack Trace:
     at NUnitTest.Tests.Test1() in C:\NUnitTest\NUnitTest\Tests.cs:line 12



Failed!  - Failed:     1, Passed:     0, Skipped:     0, Total:     1, Duration: 19 ms - NUnitTest.dll (net8.0)

Everything works fine after I remove TearDown method or DefaultTimeout setting

PS C:\NUnitTest\NUnitTest\bin\Debug\net8.0> dotnet test NUnitTest.dll --settings .\nunit.runsettings
Microsoft (R) Test Execution Command Line Tool Version 17.8.0 (x64)
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
line1

  Failed Test1 [17 ms]
  Error Message:
     Assert.That(1, Is.EqualTo(0))
  Expected: 0
  But was:  1

  Stack Trace:
     at NUnitTest.Tests.Test1() in C:\NUnitTest\NUnitTest\Tests.cs:line 12

1)    at NUnitTest.Tests.Test1() in C:\NUnitTest\NUnitTest\Tests.cs:line 12


  Standard Output Messages:
 line1



Failed!  - Failed:     1, Passed:     0, Skipped:     0, Total:     1, Duration: 17 ms - NUnitTest.dll (net8.0)

[stevenaw]

Thanks for the clear and minimal repro @patrykpiotrmarek
I'm not immediately sure what the cause may be here so it could take a bit of investigation from the team. Would you be able to upload your repro to https://github.com/nunit/nunit.issues ?

[stevenaw]

A repro for this was uploaded by @patrykpiotrmarek for investigation in nunit/nunit.issues#3

[stevenaw]

Interesting, and fascinating. I can confirm this from within Visual Studio using the "Tests" output pane.
On 3.14.0 I can see the output yet on 4.0.0, 4.0.1, and 4.1.0 I can't. Something in 3.14.0 -> 4.0.0 changes this behaviour.

[stevenaw]

Hm. Ok. This seems to manifest on net8 only. I can still see the output on net48 when consuming NUnit 4.0.0 or 4.1.0

[stevenaw]

I can't really explain why it happens, but this feels related to the changes in the Timeout attribute.

This setting gets read in here:

nunit/src/NUnitFramework/framework/Api/NUnitTestAssemblyRunner.cs

Lines 312 to 313 in 331944e

	if (Settings.TryGetValue(FrameworkPackageSettings.DefaultTimeout, out var timeout))
	context.TestCaseTimeout = (int)timeout;

Which I think then causes a TimeoutCommand to be created instead of a CancelAfterCommand here:

nunit/src/NUnitFramework/framework/Internal/Execution/SimpleWorkItem.cs

Lines 150 to 157 in 331944e

	int timeout = Test.Properties.TryGet(PropertyNames.Timeout, Context.TestCaseTimeout);
	bool useCancellation = Test.Properties.TryGet(PropertyNames.UseCancellation, Context.UseCancellation);
	if (timeout > 0)
	{
	command = useCancellation ?
	new CancelAfterCommand(command, timeout, _debugger) :
	new TimeoutCommand(command, timeout, _debugger);

Adding CancelAfter on the affected class does indeed cause the output to reappear as the presence of the property will instead cause the CancelAfterCommand to be used instead there.

// This works
[TestFixture, CancelAfter(60000)]
public class Tests
{
    [Test]
    public void Test1()
    {
        TestContext.WriteLine("line1");
        Assert.That(1, Is.EqualTo(0));
    }

    [TearDown]
    public void TearDown()
    {
    }
}

[stevenaw]

@patrykpiotrmarek Sorry it took us a while to investigate. This means that at least as a workaround it should be possible to see the output on .NET 8 by applying the CancelAfter attribute on the classes of any affected tests.

[manfred-brands]

Note that CancelAfter is using co-operative multi-tasking. It will not abort your tests unless you obey the CancellationToken.

[stevenaw]

Good point, thanks @manfred-brands ! I had forgotten to mention that.

It's also worth mentioning that CancelAfter is a better alternative to Timeout on newer runtimes like NET8 in particular if a test does out of process or generally "async" work as the cooperative cancellation model facilitates the correct cancellation of async calls.