Redirected progress output appears multiplicated by the number a test has been ran

[maettu-this]

This issue is extracted from #1043 as it an additional finding.

Describe the bug
See 3. "...caching/flushing issue..." at #1043 (comment).

To Reproduce

1. Build https://github.com/TestCentric/testcentric-gui/files/14910397/TextOutputIssue.with.ProgressTraceListener.zip
2. Open the assembly in TC
3. Run the test multiple times

Expected behavior
Redirected progress output shall be output once only for each test run.

Screenshots
See 3. "...caching/flushing issue..." at #1043 (comment).

Environment (please complete the following information):

• TestCentric Version 2.0.0-beta4
• OS: Win10
• Target Runtime for your test assembly: .NET Framework 4.8

[CharliePoole]

I assume you mean this project...

TextOutputIssue with ProgressTraceListener.zip

and this output...

Please describe the specific way you are running the test, i.e., clicking some button, right-clicking in the tree, running the whole assembly or a part, etc. It's possible that it makes no difference, but still useful as a starting point.

[maettu-this]

Clarifying To Reproduce:

1. Download and extract https://github.com/TestCentric/testcentric-gui/files/14910397/TextOutputIssue.with.ProgressTraceListener.zip
2. Open the project in VS2022 and build [Debug]
3. Open \bin\Debug\TextOutputIssue.dll in TC
4. Press the [Run] button
5. [Run] again
6. [Run] again

For each [Run], the redirected Progress output gets output once more.

[CharliePoole]

@maettu-this Are you sure you have given me the correct project for this issue? I'm not seeing the replication at all.

[maettu-this]

Hmm... I can reproduce each time. If you like we can open a Teamviewer or whatever session. You can download the latest file at https://sourceforge.net/projects/y-a-terminal/ and open [!-ReadMe.txt] to find an email address that will reach me. (For not having to disclose any email address here.)

And let me state the versions in more detail:

PS D:\Workspace> choco list
Chocolatey v2.2.2
chocolatey 2.2.2
testcentric-extension-net462-pluggable-agent 2.4.2
testcentric-extension-net60-pluggable-agent 2.4.1
testcentric-extension-net70-pluggable-agent 2.4.1
testcentric-extension-net80-pluggable-agent 2.4.1
testcentric-gui 2.0.0-beta4
6 packages installed.

Microsoft Visual Studio Community 2022 (64-bit) Version 17.8.7

  <package id="NUnit" version="3.14.0" targetFramework="net48" />
  <package id="NUnit3TestAdapter" version="4.5.0" targetFramework="net48" />

Dropping the NUnit3TestAdapter makes no difference, still getting multiple "...doing something..." for the same timestamp.

[CharliePoole]

What happens without the trace listener? Do you get replication then?

[maettu-this]

Without any lister, I no longer see the testee progress, only the "...awaiting testee..." output:

Using the ConsoleTraceListener instead of the ProgressTraceListener, the output still multiplicates, but of course in wrong sequence:

[maettu-this]

Note that I am off for a week now. I'll respond as soon as back. In case you still don't find anything, you could describe how I can try debugging the issue at my end. Just give me some hints on what to build and how to debug and where in the code to look at.

[CharliePoole]

Quick comments while I'm still waking up...

• Then something in your workaround implementation must cause it. Keep in mind that you started with a workaround aimed at the VS test adapter, which uses the engine in an entirely different way from any other runner.
• Of course, the adapter also uses a different engine so the problem may lie there. I doubt it but I can test that.
• I'm testing using the same release as you... I may go to the latest build on my machine, so I can debug into it.

I'll get back to you.

[CharliePoole]

Each time you run the tests you create a new trace listener. So on first run there is one listener, second run two, etc. Removing the listener in OneTimeTearDown made it work for me.

You need to be aware that OneTimeSetUp and OneTimeTearDown execute once per test run.

Closing as Not a Bug.

[maettu-this]

Great, that's it!

For some reason, the VS Test Adapter or the VS Test Explorer behaves differently on this, running the test multiple times there does not result in a multiplication:

========== Starting test run ==========
NUnit Adapter 4.5.0.0: Test execution started
Running selected tests in <Workspace>\TextOutputIssue.with.ProgressTraceListener\bin\Debug\TextOutputIssue.dll
   NUnit3TestExecutor discovered 1 of 1 NUnit test cases using Current Discovery mode, Non-Explicit run
...doing something, 100 ms have elapsed, duration is 1000 ms...
...doing something, 200 ms have elapsed, duration is 1000 ms...
...awaiting testee, 250 ms have elapsed, time-out is 2000 ms...
...doing something, 300 ms have elapsed, duration is 1000 ms...
...doing something, 400 ms have elapsed, duration is 1000 ms...
...awaiting testee, 500 ms have elapsed, time-out is 2000 ms...
...doing something, 500 ms have elapsed, duration is 1000 ms...
...doing something, 600 ms have elapsed, duration is 1000 ms...
...doing something, 700 ms have elapsed, duration is 1000 ms...
...awaiting testee, 750 ms have elapsed, time-out is 2000 ms...
...doing something, 800 ms have elapsed, duration is 1000 ms...
...doing something, 900 ms have elapsed, duration is 1000 ms...
...something done
...awaiting testee, 1000 ms have elapsed, time-out is 2000 ms...
...test completed after less than 1000 ms
NUnit Adapter 4.5.0.0: Test execution complete
========== Test run finished: 1 Tests (1 Passed, 0 Failed, 0 Skipped) run in 2.1 sec ==========
========== Starting test run ==========
NUnit Adapter 4.5.0.0: Test execution started
Running selected tests in <Workspace>\TextOutputIssue.with.ProgressTraceListener\bin\Debug\TextOutputIssue.dll
   NUnit3TestExecutor discovered 1 of 1 NUnit test cases using Current Discovery mode, Non-Explicit run
...doing something, 100 ms have elapsed, duration is 1000 ms...
...doing something, 200 ms have elapsed, duration is 1000 ms...
...awaiting testee, 250 ms have elapsed, time-out is 2000 ms...
...doing something, 300 ms have elapsed, duration is 1000 ms...
...doing something, 400 ms have elapsed, duration is 1000 ms...
...awaiting testee, 500 ms have elapsed, time-out is 2000 ms...
...doing something, 500 ms have elapsed, duration is 1000 ms...
...doing something, 600 ms have elapsed, duration is 1000 ms...
...doing something, 700 ms have elapsed, duration is 1000 ms...
...awaiting testee, 750 ms have elapsed, time-out is 2000 ms...
...doing something, 800 ms have elapsed, duration is 1000 ms...
...doing something, 900 ms have elapsed, duration is 1000 ms...
...something done
...awaiting testee, 1000 ms have elapsed, time-out is 2000 ms...
...test completed after less than 1000 ms
NUnit Adapter 4.5.0.0: Test execution complete
========== Test run finished: 1 Tests (1 Passed, 0 Failed, 0 Skipped) run in 2.1 sec ==========

Instead of adding and removing each time, this also prevents the multiplication:

if (!Trace.Listeners.OfType<ProgressTraceListener>().Any())
    Trace.Listeners.Add(new ProgressTraceListener());

Thanks for finding the root cause!