Missing console output when use SetUp method

[RedHeadIvan]

Setup:

• NUnit 3.13.3
• NUnit3TeasAdapter 4.2.1
• VS2022
• .NET5

Wrote single test for module that runs with multiple threads and writes logs by NLog. Runed this test, all necessary logs are present in test journal. Then I splited it to OneTimeSetUp and Test to write another test with similar logic. After that test journal contains only logs writed by Test method thread. Missing output from HostRepresentative_CorrectionReady and other threads that triggers by ValueChanged method.

    [TestFixture]
    class TimingTests
    {
        HostRepresentative hostRepresentative;
        PathProcessor pathProcessor;
        HWPropEngine.ConfigProps configProps;
        AutoResetEvent readyEvent = new AutoResetEvent(false);
        List<Span> sweeplist;

        [OneTimeSetUp]
        public void Setup()
        {
            hostRepresentative = HostRepresentative.getInstance();
            pathProcessor = PathProcessor.getInstance();
            configProps = new HWPropEngine.ConfigProps();

            // Some Init stuff

            hostRepresentative.CorrectionReady += HostRepresentative_CorrectionReady;
        }

        private void HostRepresentative_CorrectionReady(object sender, Dictionary<string, string> e)
        {
            foreach (var item in e)
            {
                Console.WriteLine($"{item.Key} = {item.Value}");
            }

            readyEvent.Set();
        }

        [Test, MaxTime(150)]
        public void FullTimingTestSmallSweep()
        {
            readyEvent.Reset();

            configProps.CF.SetValue(100e6);
            hostRepresentative.ValueChanged(configProps.CF.HardwareProperty);

            readyEvent.WaitOne();
            sweeplist = pathProcessor.CreateSweepList();
        }
    }

[OsirisTerje]

@RedHeadIvan In order to determine if this is an adapter issue or something else, please provide a workable repro for the case. It should compile and run "as is".

[RedHeadIvan]

@OsirisTerje https://github.com/RedHeadIvan/NUnitLogTest

[OsirisTerje]

I've run the repro, and I do understand you're missing something there. Could you please elaborate - that is explicitly say what output was expected and is not present?

[RedHeadIvan]

Using define "DoubleStage" you can run test different ways.
If you undefine "DoubleStage" and run test in single method, you will see this console output

CF waiting for processing
get CF with value 200000000
FSM: Jetpack, Waiting -> FirstPack
Processing CF with value 200000000
Property CF applied!
CF corrected!
Span waiting for processing
get Span with value 8000000
Processing Span with value 8000000
Property Span applied!
Span corrected!
0 ====================================================
CF waiting for processing
get CF with value 201000000
Span waiting for processing
...

etc

That's output I wanted.

But if you define "DoubleStage" test will run using OneTimeSetUp and console output will be noticeable reduced:

CF waiting for processing
get CF with value 200000000
Span waiting for processing
get Span with value 8000000
0 ====================================================
CF waiting for processing
get CF with value 201000000
Span waiting for processing
...

As you can see, only Test marked method thread console output remained

[OsirisTerje]

@RedHeadIvan Hi! I had a new look at this (sorry for the delay though) , and the difference between the two ways of running is that with DoubleStage enabled then the preprocessor.Init() is called in the OneTimeSetup method, without it is connected to the Test itself. The OneTimeSetup happens before any tests are run, and we don't actually capture the output from that part. If you enable the Dump feature you can actually see where the output goesfrom NUnit, so NUnit captures this. The problem is with the Test Explorer.

The reason for this is that we don't have any suitable place to go - in the Test Explorer - with this output. We can send the output to the Test Explorer - which is responsible for displaying this - for each test case, but there is no sink for something like OneTimeSetup.

We do have some other issues related to the same, so this is a duplicate of those. (E.g. #266, #503 and nunit/nunit#4314).
We'll have another look for a fix on this.

Thank you for reporting.