vstest icon indicating copy to clipboard operation
vstest copied to clipboard

Console.WriteLine calls during dotnet test are not emitted to the console on Windows

Open livarcocc opened this issue 8 years ago • 72 comments
trafficstars

From @jonsequitur on December 15, 2016 19:10

Steps to reproduce

  • Add a Console.WriteLine call in a test, .e.g GivenThatIWantToMigrateTestApps.ItMigratesRootProjectAndReferences
  • On Windows, dotnet test --test-case-filter "FullyQualifiedName=Microsoft.DotNet.Migration.Tests.GivenThatIWantToMigrateTestApps.ItMigratesRootProjectAndR eferences"

Expected behavior

The string passed to Console.WriteLine appears in console output.

Actual behavior

C:\dev\github\cli\test\dotnet-migrate.Tests [rel/1.0.0 ↓ +0 ~2 -0 !]> dotnet test --test-case-filter "FullyQualifiedName=Microsoft.DotNet.Migration.Tests.GivenThatIWantToMigrateTestApps.ItMigratesRootProjectAndR
eferences"
Build started, please wait...
Build completed.

Test run for C:\dev\github\cli\test\dotnet-migrate.Tests\bin\Debug\netcoreapp1.0\dotnet-migrate.Tests.dll(.NETCoreApp,Version=v1.0)
Microsoft (R) Test Execution Command Line Tool Version 15.0.0.0
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
Passed   Microsoft.DotNet.Migration.Tests.GivenThatIWantToMigrateTestApps.ItMigratesRootProjectAndReferences(projectName: "ProjectB", expectedProjects: "ProjectB,ProjectC,ProjectD,ProjectE")
Passed   Microsoft.DotNet.Migration.Tests.GivenThatIWantToMigrateTestApps.ItMigratesRootProjectAndReferences(projectName: "ProjectA", expectedProjects: "ProjectA,ProjectB,ProjectC,ProjectD,ProjectE")
Passed   Microsoft.DotNet.Migration.Tests.GivenThatIWantToMigrateTestApps.ItMigratesRootProjectAndReferences(projectName: "ProjectC", expectedProjects: "ProjectC,ProjectD,ProjectE")
Passed   Microsoft.DotNet.Migration.Tests.GivenThatIWantToMigrateTestApps.ItMigratesRootProjectAndReferences(projectName: "ProjectE", expectedProjects: "ProjectE")
Passed   Microsoft.DotNet.Migration.Tests.GivenThatIWantToMigrateTestApps.ItMigratesRootProjectAndReferences(projectName: "ProjectD", expectedProjects: "ProjectD")

Total tests: 5. Passed: 5. Failed: 0. Skipped: 0.
Test Run Successful.
Test execution time: 32.2825 Seconds

Environment data

dotnet --info output:

.NET Command Line Tools (1.0.0-preview5-004253)

Product Information: Version: 1.0.0-preview5-004253 Commit SHA-1 hash: 0caae96daf

Runtime Environment: OS Name: Windows OS Version: 10.0.14393 OS Platform: Windows RID: win10-x64 Base Path: C:\dev\github\cli\artifacts\win10-x64\stage2\sdk\1.0.0-preview5-004253

Copied from original issue: dotnet/cli#5033

livarcocc avatar May 10 '17 20:05 livarcocc

From @krwq on January 5, 2017 23:46

@jonsequitur You should probably be using Xunit's ITestOutputHelper. making Console.WriteLine forward to that might be slightly harder

livarcocc avatar May 10 '17 20:05 livarcocc

From @jonsequitur on January 6, 2017 4:35

The issue that I was seeing was that this works on OS X but not on Windows.

livarcocc avatar May 10 '17 20:05 livarcocc

I am seeing that too on windows. None of the Console.WriteLine from my tests gets printed out. We should not ask users to use special APIs to print to the console.

@codito @Faizan2304 Can you guys take a look?

I think we should move this bug to the vstest repo.

livarcocc avatar May 10 '17 20:05 livarcocc

I think this should be handled by adapters at some level. MSTest for instance captures and sends the console outputs to the runner, I think we are including them in trx logger, but not in the console. We can start showing them in console. cc: @Faizan2304

There were a few requests to capture console output in xunit: https://xunit.github.io/docs/capturing-output.html suggests to use IOutputHelper https://github.com/xunit/xunit/issues/1141

codito avatar May 11 '17 01:05 codito

Fixed!!

Faizan2304 avatar May 16 '17 08:05 Faizan2304

@Faizan2304 Is it fixed in Visual Studio Community 2017 Version 15.2 (26430.15) Release? I still cannot get the output in the output window or the test explorer. I'm using xunit.

zwcloud avatar Jul 29 '17 08:07 zwcloud

I also still do not see test output and would love to, please.

From dotnet test output:

Test ...Tests\bin\Debug\netcoreapp2.0\~.dll(.NETCoreApp,Version=v2.0)
Microsoft (R) Test Execution Command Line Tool Version 15.3.0-preview-20170703-02

and in csproj:

    <PackageReference Include="Microsoft.NET.Test.Sdk" Version="15.3.0-preview-20170628-02" />
    <PackageReference Include="xunit" Version="2.2.0" />
    <PackageReference Include="xunit.runner.visualstudio" Version="2.2.0" />

(I am using preview version of VS and latest dotnet core from github)

rogusdev avatar Aug 04 '17 13:08 rogusdev

Sorry for the late reply. I missed this thread. @zwcloud: We have fixed it in vstest.console of version v15.3.0-preview-20170517-02 and it is part of Visual studio 2017 Update3 preview3. Please see below answer to see test output with xunit.

@rogusdev : How are you writing output from test method? Is it Console.WriteLine ? If yes then it seems xunit doesn't support that. There were a few requests to capture console output in xunit: https://xunit.github.io/docs/capturing-output.html suggests to use IOutputHelper xunit/xunit#1141

Faizan2304 avatar Aug 08 '17 08:08 Faizan2304

@Faizan2304

Is it Console.WriteLine ? If yes then it seems xunit doesn't support that.

Yes. But @bradwilson said in xunit#1141

There is no way to see that output with dotnet test because of limitations in the VSTest runner.

We do not capture stdout (users are free to use that if they so choose). Our output capture system pushes that information into the test result rather than to stdout. The TRX report may or may not generate reports which include "output" results (I don't personally know, since I have no knowledge of this format), but today there's no simple way today to get this output from dotnet test directly on the console.

Visual Studio's UI, on the other hand, offers ready access to "output", which is where this information is captured.

So.. could you fix or change the behaviour of VSTest runner to remove the limitaion?

zwcloud avatar Aug 08 '17 10:08 zwcloud

@zwcloud: We display what adapter sends in TestResult.Message Code here And here

Its the responsibility of adapter to fill console.WriteLine message in TestResult.Message.

But as you can see, @bradwilson said in xunit#1141 that they are not capturing console output to test result

Users will use ITestOutputHelper to write output. That's what ends up in ITestResultMessage.Output. We do not capture any device like console, debug, or tracing.

In this case you have to follow this article. xunit is suggesting to use IOutputHelper to log your message.

Faizan2304 avatar Aug 08 '17 15:08 Faizan2304

Why the issue is closed if there is still no console output in tests?

It's kinda strange to have console test runner which doesn't show console output.

evil-shrike avatar Sep 01 '17 09:09 evil-shrike

Bumping this in case anyone else comes along hoping to find an answer.

dotnet test -v n

I learned that running the above will show the "Standard Output Messages:" that you would expect from Console.Write*. It does flood the terminal with information at build but at least is a solution for the time. "-v" is a Verbosity argument. "n" represents "normal". Refer here for more information.

I use this with a .NET Core Unit / Integration test projects running NUnit.

ValorMorgan avatar Mar 14 '18 12:03 ValorMorgan

@Faizan2304 Apparently you guys think you have done quite well in handling the console output. But that's far from the truth. We don't want to use IOutputHelper to log your message, just implement a simple way today to get this output from dotnet test directly on the console.

zwcloud avatar Mar 15 '18 02:03 zwcloud

I solved the problem by letting my xUnit test classes inherit from a base class, that rewires console to ITestOutputHelper. Has some drawbacks since everything is first copied at the end, i.e. not during debugging. Someone can probably improve it.

using System;
using System.Diagnostics;
using System.IO;
using Xunit;
using Xunit.Abstractions;

namespace MyStd.Test
{
    public class MakeConsoleWork : IDisposable
    {
        private readonly ITestOutputHelper _output;
        private readonly TextWriter _originalOut;
        private readonly TextWriter _textWriter;

        public MakeConsoleWork(ITestOutputHelper output)
        {
            _output = output;
            _originalOut = Console.Out;
            _textWriter = new StringWriter();
            Console.SetOut(_textWriter);
        }

        public void Dispose()
        {
            _output.WriteLine(_textWriter.ToString());
            Console.SetOut(_originalOut);
        }
    }

    public class ConsoleWriterTest : MakeConsoleWork
    {
        public ConsoleWriterTest(ITestOutputHelper output) : base(output)
        {
        }

        [Fact]
        public void Test1()
        {
            Console.WriteLine("nunit console visible in test runner");
        }
    }
}

mattiasw2 avatar Apr 07 '18 10:04 mattiasw2

@mattiasw2 nice job! but, it's a bug in dotnet test?

alexsandro-xpt avatar Apr 13 '18 21:04 alexsandro-xpt

@alexsandro-xpt Sorry, you are correct, it is related to Xunit, and the reason I ended up here is @Faizan2304

Also, since I did the above, I realized it only works if you do not run tests in parallel. The core problem is actually Console.SetOut, since you would actually want to have a Console.SetOut that only changes the Console in the current thread, something that is hard in dotnet (but easy in Clojure). So. you can delete my comments as not relevant.

mattiasw2 avatar Apr 14 '18 16:04 mattiasw2

Why is this closed?

dhowe avatar May 17 '18 05:05 dhowe

@Faizan2304 this is not working for me using dotnet test. No System.Console.WriteLine output shows up during unit tests.

Could you please re-open the issue? This is still broken for many.

JoshuaKGoldberg avatar Sep 19 '18 01:09 JoshuaKGoldberg

Could this be re-opened? It is clearly not fixed for a very large number of users. The ITestOutputHelper is not a good solution for a variety of reasons - for example, how am I supposed to log the output of the actual library I am testing (i.e. not in the test class itself)? I'm supposed to pass this XUnit object into my actual library?

BTW, if anyone is having trouble getting the ITestOutputHelper to work, note that it will not output anything if your test passes. It needs to fail for output to be shown. Hope that helps.

roblframpton avatar Sep 21 '18 10:09 roblframpton

I'm also experiencing this problem on Windows. On Linux, it works just fine.

Interestingly, on Appveyor Windows builds, I also see the console output. It's only locally that I see nothing.

adamralph avatar Oct 20 '18 21:10 adamralph

How does appveyor do this?

devedse avatar Nov 06 '18 21:11 devedse

using (var writer = new System.IO.StreamWriter(System.Console.OpenStandardOutput()))
       writer.WriteLine("This will show up!");

Works on Linux/Mac, but not on Windows...

wizofaus avatar Nov 21 '18 00:11 wizofaus

Any final solution to this problem for Windows?

Edit:

This is what I ended up doing:

public class Client : ClientWConsole {
        public Client(ITestOutputHelper output) : base(output) { }

        [Fact]
        public void Execute() {

            Debug.WriteLine("Hello world - D "); // for debug results 
            this.output.WriteLine("Hello world - C"); // for test  output results 
        }
    }
public class ClientWConsole {
         protected readonly ITestOutputHelper output;

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

    }

danvln avatar Nov 21 '18 08:11 danvln

Yeah but that approach doesn't work when you don't want to modify your exisiting code.

devedse avatar Nov 21 '18 11:11 devedse

Tagging @Faizan2304

devedse avatar Nov 21 '18 11:11 devedse

How does appveyor do this?

Don't know anything about appveyor but it's certainly in principle possible for an application to execute the mstest runner itself so that std-output is redirected in away the output can be captured. Briefly looking through the dotnet cli source code I couldn't really see why Windows would be different to linux/mac etc. (though certainly Console.OpenStandardOutput is implemented differently between them)

wizofaus avatar Nov 22 '18 00:11 wizofaus

It's April 2019, Visual Studio 2017 Community, Run XUnit tests for the first time from an xUnit Tests project created by VS - no console output. Neither from test code, nor from code under test. Running the same test with NUnit happily produces the output.

chhh avatar Apr 09 '19 19:04 chhh

@chhh that is a design decision by xunit so as to avoid the use of static state. one possible option is to try this approach https://github.com/SimonCropp/XunitLogger which uses asynclocal to keep track of the logging context

SimonCropp avatar Apr 15 '19 20:04 SimonCropp

This doesn't work with latest dotnet core cli (3.0.101) on either Windows or Linux with MSTest v2(.0.0). Why is this still closed and ignored after so many requests for actual consideration here for something that is clearly a bug even by the maintainers' replies here?

ransagy avatar Dec 01 '19 19:12 ransagy

Doesn't work with 3.1.100 either.

dazinator avatar Dec 16 '19 15:12 dazinator