NUnit adapter fires asynchronous events to InProcDataCollector

[pkrukp]

Summary

This is a followup from microsoft/vstest#1833

The issue: In-Proc Data Collector events are not (fully?) synchronized with executed tests. For example the sequence of events currently could look like this:

InProcDataCollector event TestCaseStart: TEST_ONE
Actual test started: TEST_ONE
Actual test finished: TEST_ONE
Actual test started: TEST_TWO
InProcDataCollector event TestCaseEnd: TEST_ONE
InProcDataCollector event TestCaseStart: TEST_TWO
Actual test finished TEST_TWO
InProcDataCollector event TestCaseEnd: TEST_TWO

while it should look like this:

InProcDataCollector event TestCaseStart: TEST_ONE
Actual test started: TEST_ONE
Actual test finished: TEST_ONE
InProcDataCollector event TestCaseEnd: TEST_ONE
InProcDataCollector event TestCaseStart: TEST_TWO
Actual test started: TEST_TWO
Actual test finished TEST_TWO
InProcDataCollector event TestCaseEnd: TEST_TWO

This is a problem for example when you want to collect coverage and connect it with executed test.

In my tests the problem appears in nunit 3.11.0. Older version nunit 3.9.0 seems to be OK, so maybe this is a regression? I have not tested all versions of nunit between 3.9.0 and 3.11.0 so I don't know when the change happened.

Repro

Attaching solution: VstestEvents.zip

It contains 3 test project (for nunit, xunit and mstest), "VstestRunner" project which runs UT and the "VstestRunner.InProcDataCollector" project. It also contains runTest.bat which may need to be updated.

As a result, it produces two .txt files which contain logs from UT and from data collector. The location of the files differs between UT frameworks.

How to use Repro

1. download, unpack and compile solution
2. download and unpack (unzip) https://www.nuget.org/packages/Microsoft.TestPlatform/15.9.0
3. edit runTest.bat and update path to vstest.console.exe
4. execute runTest.bat from the same directory it is placed in

In result, there should be 2 new files created next to runTest.bat file:

• from_dc.txt
• from_test.txt

You can also edit runTest.bat to uncomment lines which execute tests for xunit and mstest. In that case, the from_*.txt files will be created next to analyzed assembly (in bin/debug)

My results from the running tests

nunit 3.11.0:

[2018-11-14T11:07:27.1192794+01:00] TestCaseStart: TestFail (from DC)
[2018-11-14T11:07:27.1202795+01:00] TestFail (from test) started
[2018-11-14T11:07:28.1293804+01:00] TestFail (from test) finished
[2018-11-14T11:07:28.1343809+01:00] TestPass (from test) started
[2018-11-14T11:07:28.1463821+01:00] TestCaseEnd: TestFail (from DC)
[2018-11-14T11:07:28.1523827+01:00] TestCaseStart: TestPass (from DC)
[2018-11-14T11:07:29.1354810+01:00] TestPass (from test) finished
[2018-11-14T11:07:29.1384813+01:00] TestCaseEnd: TestPass (from DC)

nunit 3.9.0:

[2018-11-14T11:19:00.9356541+01:00] TestCaseStart: TestFail (from DC)
[2018-11-14T11:19:00.9506556+01:00] TestFail (from test) started
[2018-11-14T11:19:01.9557561+01:00] TestFail (from test) finished
[2018-11-14T11:19:01.9697575+01:00] TestCaseEnd: TestFail (from DC)
[2018-11-14T11:19:01.9767582+01:00] TestCaseStart: TestPass (from DC)
[2018-11-14T11:19:01.9777583+01:00] TestPass (from test) started
[2018-11-14T11:19:02.9788584+01:00] TestPass (from test) finished
[2018-11-14T11:19:02.9798585+01:00] TestCaseEnd: TestPass (from DC)

[pkrukp]

I have tested with older nunit versions. It looks like the change happened in 3.11.0:

nunit 3.10.1 (3.10.0) + vstest 15.6.2: OK
nunit 3.10.1 (3.10.0) + vstest 15.9.0: OK
nunit 3.11.0 + vstest 15.9.0: BAD
nunit 3.11.0 + vstest 15.6.2: BAD

[pkrukp]

I noticed #510 which says:

Add a CollectDataForEachTestSeparately setting
Add a setting to make NUnit run tests sequentially, making the InProcDataCollectors receive the events before a test starts and after a test ends. This allows adapters to opt into the sequential mode.

It looks related. If I'm reading it correctly, with this setting the InProcDataCollector should get events synchronously. And indeed, when I used it in the repro, the events were fired correctly.

If that's the case, I wonder, maybe it should be the default? I mean, without it, the data collector is partially unusable. I think it is also expected that by default the events are synchronized with tests, also looking at the InProcDataCollection docs in https://github.com/Microsoft/vstest/blob/master/src/Microsoft.TestPlatform.ObjectModel/DataCollector/InProcDataCollector/InProcDataCollector.cs that's the impression (although it's not 100% as it says e.g. "Called when test case starts" for TestCaseStart)

[OsirisTerje]

@pkruk2 Thanks for the issue and the very well prepared repro! We'll have a look, and find a fix.

[rprouse]

@pkruk2 can you clarify, when you say that the issue happened in NUnit 3.11, do you mean that it happened when you changed the NUnit Adapter or NUnit Framework to 3.11? I think that you mean the adapter project, but I want to confirm because there are also changes in the framework that might have caused this.

[OsirisTerje]

@rprouse Seems he have been switching both at the same time, but the adapter doesn't "fire any events", but just responds to events from the engine, so the root cause "should" be in the engine or framework.

[pkrukp]

@rprouse it's as @OsirisTerje said, I was switching both - i.e. I had framework 3.10.1 and adapter 3.10.0 (latest 3.10.x) and then switched both to 3.11.0 (latest 3.11.x)

[rprouse]

I've looked through the NUnit Framework changes between 3.10.1 and 3.11 and don't see anything obvious. #510 does look very suspicious. @pkruk2 have you tried adding the following to your runsettings? I'm not certain you should need to, but I'd like to see if it fixes the issue.

    <RunConfiguration>
        <CollectDataForEachTestSeparately>true</CollectDataForEachTestSeparately>
    </RunConfiguration>

[pkrukp]

@rprouse yes, I wrote about it 5 days ago ;)
#560 (comment)