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

maettu-this commented 5 months ago

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

Describe the bug See 3. "...caching/flushing issue..." at https://github.com/TestCentric/testcentric-gui/issues/1043#issuecomment-2043534958.

To Reproduce

Build https://github.com/TestCentric/testcentric-gui/files/14910397/TextOutputIssue.with.ProgressTraceListener.zip
Open the assembly in TC
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 https://github.com/TestCentric/testcentric-gui/issues/1043#issuecomment-2043534958.

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 commented 5 months ago

I assume you mean this project...

TextOutputIssue with ProgressTraceListener.zip

and this output...

grafik

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 commented 4 months ago

Clarifying To Reproduce:

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

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

CharliePoole commented 4 months ago

@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 commented 4 months ago

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 commented 4 months ago

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

maettu-this commented 4 months ago

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

grafik

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

grafik

maettu-this commented 4 months ago

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 commented 4 months ago

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 commented 4 months ago

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 commented 4 months ago

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!

TestCentric / testcentric-gui

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