Using ReSharper, how to show debug output during a long-running unit test?

Question

I'm using xUnit with the ReSharper test runner and the xUnitContrib resharper plugin.

When I have a long-running test, I'd like to be able to output some progress indicator to the Unit Test Output window.

I've tried Debug.WriteLines, Trace.WriteLine and Console.WriteLine. All of which have the same behavior - nothing shows in the output window until the test has completed.

For example:

[Fact]
public void Test()
{
    Debug.WriteLine("A");
    Trace.WriteLine("B");
    Console.WriteLine("C");

    Thread.Sleep(10000);
}

The test shows no output until the 10 seconds have elapsed and the test completes. How do I get output along the way?

UPDATE 1

I tried also with MSTest and NUnit. NUnit is the only one that shows output along the way.

MSTest and XUnit don't return any output until the test completes. The weird part is that while the XUnit and NUnit test output looks like this:

A
B
C

The MSTest output looks like this:

C


Debug Trace:

A
B

Given all of these variations, I think the answer is that it is up to the test runner implementation to decide how and when to output. Does anyone know if it is possible to configure the XUnit test runner?

UPDATE 2

I think this must be a deficiency in xUnitContrib. Posted to their CodePlex issue tracker.

Ahron

Debug.WriteLine() works perfectly fine for me when I'm in debug mode. So if you want to log in in a general way I recommend brenton's answer – Fidelfidela

@derape - No, it doesn't work with xunit. No output appears until the test completes. – Ahron

I see, I've not played with XUnit - only NUnit. And NUnit logging does work along the debug threads... – Reena

Yes, NUnit does work for this. See my update. – Ahron

Answer 1

XunitLogger uses AsyncLocal<T> to keep track of the logging context so calls to Trace.Writeline and Console.Writeline can be routed to the correct instance of ITestOutputHelper.

Usage:

static class ClassBeingTested
{
    public static void Method()
    {
        Trace.WriteLine("From Trace");
        Console.WriteLine("From Console");
        Console.Error.WriteLine("From Console Error");
    }
}

public class TestBaseSample  :
    XunitLoggingBase
{
    [Fact]
    public void Write_lines()
    {
        WriteLine("From Test");
        ClassBeingTested.Method();

        var logs = XunitLogger.Logs;

        Assert.Contains("From Test", logs);
        Assert.Contains("From Trace", logs);
        Assert.Contains("From Console", logs);
        Assert.Contains("From Console Error", logs);
    }

    public TestBaseSample(ITestOutputHelper output) :
        base(output)
    {
    }
}

Roryros

Answer 2

If you used xUnit.net 1.x, you may have previously been writing output to Console, Debug, or Trace. When xUnit.net v2 shipped with parallelization turned on by default, this output capture mechanism was no longer appropriate; it is impossible to know which of the many tests that could be running in parallel were responsible for writing to those shared resources. Users who are porting code from v1.x to v2.x should use one of the two new methods instead.

Have a look here for example of how to perform logging with xUnit.net v2:

http://xunit.github.io/docs/capturing-output.html

This is the example:

using Xunit;
using Xunit.Abstractions;

public class MyTestClass
{
    private readonly ITestOutputHelper output;

    public MyTestClass(ITestOutputHelper output)
    {
        this.output = output;
    }

    [Fact]
    public void MyTest()
    {
        var temp = "my class!";
        output.WriteLine("This is output from {0}", temp);
    }
}

Misbegotten

This is useful for writing output from within the tests, but when you need to output info in real-time from code called by the tests you have to amend the code being tested to pass in and utilize ITestOutputHelper. I understand the issue of concurrency making it difficult to handle output from the code, I just wanted to point out for others that this solution does have a limitation. It would be nice to leverage something like trace listeners or hijacking the default output stream for the Debug.Write* methods. – Pronator

Answer 3

For NUnit this works:

Console.SetOut(TestContext.Progress);

** The late answer is because I had the same problem, and I just solved it. may help others

Heterogeneous

This did not work for me with .net core linux + nunit 3.11 – Nonsuch

Thanks for updating. Sorry, don’t have an environment to try fix it. – Heterogeneous

Answer 4

ReSharper somehow removed the default listener in unit tests. To display text in the Output window, just add this line:

Debug.Listeners.Add(new DefaultTraceListener());

Flabellum

This didn't work for me, in either the Unit Test Sessions window, or the Output window (using MSTest). – Hebraist

Answer 5

I had the same issue for NUnit, now 8 years after you asked the question. :-(

I'm pretty sure that this was implemented by default from Resharper at some point, as I can't remember I had to do this manually before. But sometime down the line, it stopped working.

The solution (for NUnit) is to add this line at the top of your NUnit unit tests.

Console.SetOut(TestContext.Progress)

This makes all your (existing) Console.Out.WriteLine("") output directly to the Resharper Unit Test Runner output section, while the unit test is executing.

Gondola

Answer 6

The easiest I've found is to utilize log4net and create a console logger. Along the way, as you're running, you'd call logger.Info("info here"); or log.Debug("info here"); - really whatever your preferred logging level - and the output will show in Resharper Unit Test Sessions.

Read more about the log4net framework on the Apache log4net homepage. The configuration examples will also be invaluable.

Reena

Nope. Added log4net, and those messages don't even make it into the unit test output at all. I used a simple console appender - the one from the examples. – Ahron

Answer 7

You may also consider using xunit.NLog which is a very nice and clean way to inject ITestOutputhelper into your SUTs.

http://www.tomdupont.net/2015/06/capture-xunit-test-output-with-nlog-and.html

Gaullism

Answer 8

For Console.WriteLine, this is one way (there may be a better way, but this works for me):

public class ConsoleOutputHelper : TextWriter, ITestOutputHelper
{
    private readonly ITestOutputHelper _helper;

    public ConsoleOutputHelper(ITestOutputHelper helper) => _helper = helper;

    public override void WriteLine(string? message)
    {
        try
        {
            _helper.WriteLine(message);
        }
        catch (InvalidOperationException ex) when (ex.Message.Contains("no currently active test"))
        {
        }
    }

    public override void WriteLine(string format, params object?[] args) => 
        _helper.WriteLine(format, args);

    public override Encoding Encoding => new UTF8Encoding();
}

... then, in your test constructors:

public MyTests(ITestOutputHelper helper) => 
    Console.SetOut(new ConsoleOutputHelper(helper));

... then, in the code you're testing

Console.Out.WriteLine("Beginning something...");

Update

Trace.WriteLine is probably better in production code.

Setup looks like this (need to add and remove the trace listener):

public class MyTests : IDisposable
{
    private readonly TraceOutputHelper _traceOutputHelper;

    public MyTests(ITestOutputHelper helper)
    {
        _traceOutputHelper = new TraceOutputHelper(helper);
        Trace.Listeners.Add(_traceOutputHelper);
    }

    public void Dispose() => Trace.Listeners.Remove(_traceOutputHelper);

... and TraceOutputHelper is very similar to ConsoleOutputHelper above:

public class TraceOutputHelper : TextWriterTraceListener, ITestOutputHelper
{
    private readonly ITestOutputHelper _helper;

    public TraceOutputHelper(ITestOutputHelper helper) => _helper = helper;

    public override void WriteLine(string? message)
        => _helper.WriteLine(message);

    public void WriteLine(string format, params object[] args) => _helper.WriteLine(format, args);
}

Armored