Sometimes not all test results are reported to VS

[jgefele]

Symptoms: When running tests, GTA reports that n tests have been executed, but VS shows less test results in the test explorer. When we insert a small delay between between reporting individual test case results all tests are reported.

Reason: We suspect this is due to inter process communication, but we do not have a lot of expertise in this area, and there is no official documentation of the VS test framework API

Workaround: Configure Report waiting time at Tools/Options/Google Test Adapter/Advanced

[Alfred5020]

Hi!
I’m not sure if my information is new for you but maybe can help if I describe what I’m recognize.
On my PC this problem is only appearing if I activate parallel test execution. Doesn’t’ matter if I limit the used thread to 1.
With a waiting period of 1 it will work.
As additional information the test output
------ Run test started ------
Found 8 tests in executable C:\Source\zenon\Supervisor\main\BIN\PC\UTests\PROGRAMFILES32\DebugNoUTest\Archiv_UTest.exe
Found 309 tests in executable C:\Source\zenon\Supervisor\main\BIN\PC\UTests\PROGRAMFILES32\DebugNoUTest\zenon32misc_net_UTest.exe
Running 317 tests...
Executing tests on 1 threads
Test execution completed.
========== Run test finished: 17 run (0:00:04,714) ==========
If I can help with future investigation please give me instructions.

Best regards
Alfred

[DominikGrabiec]

So I believe I have an error similar to this. I have 106 tests in 2 test exeutables in my project, but when I run all the tests, they all get run according to Google Test, but only 6 show up in the Test Explorer in Visual Studio 2015 (Community Edition).
[code]
------ Run test started ------
Found 8 tests in executable C:\Development\Galaxy\Build\Tests\Base\Debug\BaseTest.exe
Found 98 tests in executable C:\Development\Galaxy\Build\Tests\Math\Debug\MathTest.exe
Running 106 tests...
Test execution completed.
========== Run test finished: 6 run (0:00:07.4198016) ==========
[code]
I get this even with the delay variable set to 1.
I even tried to put "&& timeout 10" in the extra test parameters so that there would be extra time to wait between running the tests and reading the result files but to no avail.
The tests that do appear green and look like they have been run are the first 6 listed in the generated tmp files. I can sometimes run and get all the tests working correctly but it is a rare occurance.

[DominikGrabiec]

To add some more information it seems that this error occurs only when "Run All" is selected, since if the tests are sorted in any other way it runs all of them from that group successfully.

[csoltenborn]

Alfred and Dominik, thanks a lot for your feedback! I must admit that we were a bit lost with that issue, but your feedback certainly encourages us to look into it once more.

@DominikGrabiec Can you confirm that this only happens when executing tests in parallel on your machine? Your log output looks like you are executing tests sequentially (the "Executing tests on n threads" part is missing)...

@Alfred5020 We will come back to you as soon as we have any idea on what else you could try to help us understand what's going on...

[DominikGrabiec]

I am only running the tests sequentially, I have not enabled parallel execution of any kind.

Running any subset of tests runs successfully - so if I sort by class or by project (where one project has > 100 tests) the tests execute and the results are parsed successfully.

Since the initial comment I have continued working and added more tests and now there are more tests successfully scanned and shown in the Test Explorer window as completed, but they are a different set than before.

This happens regardless what value is put for the delay.

[csoltenborn]

Strange... The only difference between running all or a selection of tests is that VS provides the executables in the first case or the concrete test cases to be run in the second case. However, the code executing the tests and reporting the results is much later and does not differ at all (i.e., in the first case, we discover all tests and then execute the first code as in the second case). Stay tuned...

[DominikGrabiec]

Sometimes when I click Run All I do get all of the test results parsed correctly - just happened to me now - but I clicked it again straight after and it went back to 23 tests run after running 123 in total.

The temporary XML files do list that all of the tests had actually been run by Google Test.

I checked and I ran just the tests from one test project (In Test Explorer selecting project view and clicking run selected tests on that project), first time all 115 were run and recognised, subsequently only 15 were recognised, and it appears so going forward.

[csoltenborn]

Thanks once more for your feedback! I have just pushed a code change which produces debug output if you enable debug mode (i.e., it tells which tests have been passed to the VS test framework). Can you give it a try with this version by any chance? You can download it here:

https://ci.appveyor.com/api/buildjobs/a6wrlvm8aue89vbb/artifacts/GoogleTestExtension/GoogleTestAdapterVSIX/bin/Release/GoogleTestAdapter-0.2.3.vsix

[DominikGrabiec]

I tried it, and it spits out "Reported result of test" for each test that was run, but Visual Studio still only detects a subset of tests in most cases.

So when running all of the tests in one test project (it has 115 tests), it spits out the debug string for each test - all 115 of them - but at the end in the "Run test finished: # run" message it either prints 115 or 15.

[csoltenborn]

That's kind of what I expected...

@DominikGrabiec Do I understand from #18 that you have checked out our code and are able to build and execute it? If this is the case, please try to increase the WaitingPeriod in GoogleTestAdapter.VS/Framework/VSTestFrameworkReporter, e.g. to 10ms.

If this is not possible, please let me know, I will then prepare a version for you.

Why? The problem is that we send the test results to the VS test framework (method ReportTestResult()), but do not get any feedback from VS. Our guess is that under some circumstances, we send test results too fast for VS to process (the VS method does not appear to block). Since we have no idea on what "too fast" means, we provided the WaitingPeriod workaround. And maybe on your machine the slowest way of sending tests we support right now (i.e., "wait 1ms after each result") might still be too fast for whatever reason...

[jgefele]

Hi guys.

I can reproduce the issue (tests missing on "run all" but reliably showing up on "run selected" even with all tests selected). I used this simple test file. For me a waiting period around 35 is fine, but I guess that's machine and load dependent. I hope that for Dominik the problem will be gone after increasing the sleep time.

"Running 317 tests...17 run"
"Running 106 tests... 6 run"
"(where one project has > 100 tests)"
"23 tests run after running 123 in total."
"all 115 were run and recognised, subsequently only 15 were recognised"

I smell a pattern ;-) With my test file above I can reproduce this pattern. I think that if we cannot identify and eliminate the root cause, we should change the workaround to wait for a configurable duration after reporting 99 tests.

Cheers,
Jonas

[DominikGrabiec]

@jgefele I noticed that too but forgot to mention it.

@csoltenborn Despite posting issue #18 I haven't actually built or compiled the code - otherwise I would have submitted a patch I think - but I just ran a few trials on my computer and examined the source code on github.

I wouldn't mind having a go at fixing a few things with this code but I'm in the middle of moving half way around the world so it'll be a couple of weeks before I can get everything set up.

Do you have a link to the API documentation somewhere?

[csoltenborn]

Moving around the world - sounds interesting :-)

Which API docs do you mean? In case of the VS test framework: There is no official MS documentation, only a couple of blog entries (partly by MS guys). I will set up a wiki page with some links in the next couple of days.

[csoltenborn]

I have just pushed a branch with code to play with the VS API, the resulting VSIX file can be downloaded here. I hacked an additional option into the adapter which allows to influence the test reporting process. @Alfred5020 @DominikGrabiec @jgefele Could you guys maybe play with the options and see if you find configurations which work reliably on your machines?

Reporting variant is a 5 digit number abcde, where

• a decides which registration methods are called in which order (0-4)
• b decides whether to wait after reporting test start (0,1)
• c decides whether to wait after reporting test result (0,1)
• d decides whether to wait after reporting test end; no effect if a=2 (0,1)
• f is waiting time (same for b-d): 0=do not wait, n=wait for 2^(n-1) ms (0-9)

Waiting only happens if WaitPeriod > 0 and f > 0 and (b = 1 or c = 1 or d = 1).

Examples:

• 30105 with waiting period 7 means order 3, wait 2^(5-1)=16ms after reporting every 7th test result
• 11101 with waiting period 7 means order 1, wait 2^(1-1)=1ms after reporting every 7th test start and every 7th test result

The following variants should be particularly interesting: 0, 10000, 20000, 30000, 40000 (no waiting) and cases with waiting period=99 and waiting time > 0, e.g. 11001, 10101 or 10011. Let me know if you have any questions...

[Alfred5020]

Hi guys!
I did some tests with the reporting variants.
Here the results:
A: All tries done with “Run all”, several times, single threaded; Run selected test (whole project, 309 tests, all reported); Waiting period = 1
0: 9 tests of 309 are reported
10000: 9 test are reported
20000: 9 test are reported
30000: 9 test are reported
40000: 9 test are reported
1000: one time 109, several times 9 tests reported
1001: 9 test are reported
1009: 9 test are reported
100: 9 test are reported
101: all reported
109: all reported; it’s possible to watch the update of the tree in the testexplorer and the resorting of they.
10: 9 test are reported
11: all reported
19: all reported
111: all reported
119: all reported
1111: all reported
11111: all reported
21111: all reported
31111: all reported
41111: all reported
30105: one times 109 reported, 9 test are reported
11101: all reported
10100: 109 reported, 309 reported, 3 times 9 reported
10101: all reported
20101: 9 reported
20102: 109 reported, 9 reported
30101: 9 reported
30102: 9 reported
40101: 9 reported
31001: 9 reported
31002: 9 reported
30011: all reported
40011: all reported
11001: 9 reported
10101: all reported
10011: all reported

B. Test setup as in A described. different: waiting period = 99
11001: 9 reported
10101: 9 reported
10011; 3 times 9 reported, 2 times 109 reported

C. Test setup as in A described, different: execute tests in parallel; 8 Threads
40011: all reported ~6,5 seconds
30011: all reported ~4,3 seconds
30101: all reported ~4,6 seconds
40101: all reported ~5,8 seconds
10101: all reported ~4,6 seconds
10: 9 test are reported
11: all reported ~4,6 seconds
100: 9 test are reported
101: all reported ~4,6 seconds

Best regards
Alfred

[csoltenborn]

Thanks, Alfred! I will soon look at your results closely...

[jgefele]

Thank you for the detailed report. It looks like an issue in the Visual Studio test framework. I created a minimal example and asked in the MSDN forums for help (https://social.msdn.microsoft.com/Forums/en-US/be2a6228-8484-4770-b6ca-0ceb4f7b5cb9/unit-test-adapter-for-visual-studio-some-test-cases-get-lost?forum=vsunittest). Hopefully, some VS dev can give some guidance.

[jgefele]

I've found the issue in Visual Studio and should be able to provide a reliable workaround.

[jgefele]

Hi @Alfred5020 and @DominikGrabiec.

Could you please give this build a try? https://ci.appveyor.com/api/buildjobs/3tg46qnn9b4u60kk/artifacts/GoogleTestExtension/GoogleTestAdapterVSIX/bin/Release/GoogleTestAdapter-0.2.3.vsix

[jgefele]

https://connect.microsoft.com/VisualStudio/feedback/details/2288116/te-processhost-managed-exe-drops-some-test-results-when-reported-too-fast