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.

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

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

Open
patrykpiotrmarek opened this issue Jan 11, 2024 · 11 comments · May be fixed by #4692
Open

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

patrykpiotrmarek opened this issue Jan 11, 2024 · 11 comments · May be fixed by #4692
Assignees
Labels

Comments

@patrykpiotrmarek
Copy link

patrykpiotrmarek commented Jan 11, 2024

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
Copy link
Member

stevenaw commented Jan 13, 2024

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
Copy link
Member

stevenaw commented Jan 16, 2024

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

@OsirisTerje OsirisTerje added the Investigate We will look into this label Jan 23, 2024
@stevenaw
Copy link
Member

stevenaw commented Mar 1, 2024

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 stevenaw added is:bug and removed Investigate We will look into this labels Mar 1, 2024
@stevenaw
Copy link
Member

stevenaw commented Mar 1, 2024

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
Copy link
Member

stevenaw commented Mar 1, 2024

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:

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:

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
Copy link
Member

stevenaw commented Mar 1, 2024

@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
Copy link
Member

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

@stevenaw
Copy link
Member

stevenaw commented Mar 2, 2024

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.

@stevenaw
Copy link
Member

A bit of an update here as I have to pause my own investigation for now

An early option I'd considered but had to rule out was passing the TextWriter around by simply adding a new parameter to MakeTestResult(). As a public abstract method, it was a challenge to do this in a way which didn't have an outside chance of breaking a consumer somewhere. I opted for caution here as this appears a common integration point.

I did manage to "fix" it in a branch here: https://github.com/stevenaw/nunit/tree/4598-timeout-context-output though I'm not particularly happy with the result. It meant extending and wrapping a TextWriter as a publicly exposed property and changing a readonly field to be internally settable. This felt a little heavy-handed given this may become a .NET6-only issue if we did the Timeout rework in #4673.

An idea I haven't time to pursue yet is "snapshotting" the state of the TestResult at the time of the Timeout and applying it to the context here. It's possible there may be other options here too.

@manfred-brands
Copy link
Member

@stevenaw the timeout refactor is working good for net462 and net8. For net6 this now throws a PlatformNotSupported exception as it never previously worked as intended. I hope to get the PR up this weekend.

@stevenaw
Copy link
Member

Fantastic, thanks @manfred-brands .
I took a quick look through your Timeout PR and it looks like it's taking things in a great direction

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants