Another issue discovering tests

[ldwren]

I have a utility library with a set of unit tests. Alongside this I have a simple application to execute the tests.

The issue sounds similar to bug reports #148 and #164 in that everything appears to be OK, but the tests are not discovered.

There are currently 34 tests in the library, with one in the test runner application as an additional validation test.
If I run the application from either VS or the command line with --gtest_list_tests I see all the 35 tests, over 5 test groups. Test are listed with groups in the first column, and tests indented two spaces.

When I rebuild the solution I get the error:
"ERROR: Could not list test cases of executable .... executing process failed with return code 3"

The output log (see below) suggests that 35 tests have been discovered, but none are returned.

Return code 3 suggests "The system cannot find the path specified". If I copy the executable full name from the output log and paste it direclty into a command window my tests run, suggesting that it's not my application that cannot be found.

If I debug through VS, with --gtest_list_tests, I see the return value from main() set to zero on exit, again suggesting the error code of 3 is not from my application.

I have tried both new and old test execution framework options and have my regex for test discovery set as ".*.exe"

Is there anything else I can try to track this issue down?

My current setup is small and quick to build, but I can only get the test discovery to run if I "Rebuild Solution". I can see this becoming an issue for larger solutions. Is there a method to run test discovery on a "Build Solution", or better still a "Build Project" - even if that means running a post-build command?

===============================================================================

VS Professional 2017 15.3.5
GTA: 0.10.2.874 (Installed through VS Extension manager)
GTest: Revision: bfc0ffc8a698072c794ae7299db9cb6866f4c0bc Date: 21/09/2017 15:54:35

===============================================================================
Note: The paths here have been modifid to make easier to read!

[23/09/2017 18:11:51 Informational] ------ Discover test started ------
[23/09/2017 18:11:51 Informational] Visual Studio Version: VS2017
[23/09/2017 18:11:51 Informational] Google Test Adapter: Test discovery starting...
[23/09/2017 18:11:51 Informational] Solution settings: AdditionalTestExecutionParam: '', BatchForTestSetup: '', BatchForTestTeardown: '', BreakOnFailure: False, CatchExceptions: False, DebugMode: True, KillProcessesOnCancel: False, MaxNrOfThreads: 8, NrOfTestRepetitions: 1, ParallelTestExecution: False, ParseSymbolInformation: True, PathExtension: '', PrintTestOutput: False, RunDisabledTests: False, ShowReleaseNotes: False, ShuffleTests: False, ShuffleTestsSeed: 0, TestDiscoveryRegex: '..exe', TestDiscoveryTimeoutInSeconds: 10, TestNameSeparator: '', TimestampOutput: False, TraitsRegexesAfter: {}, TraitsRegexesBefore: {}, UseNewTestExecutionFramework: True, WorkingDir: '$(ExecutableDir)'
[23/09/2017 18:11:51 Informational] No settings configured for test executable 'D:\Dev\TestApp\Utils\x64\Debug\UT_Utils.exe'; running with solution settings: AdditionalTestExecutionParam: '', BatchForTestSetup: '', BatchForTestTeardown: '', BreakOnFailure: False, CatchExceptions: False, DebugMode: True, KillProcessesOnCancel: False, MaxNrOfThreads: 8, NrOfTestRepetitions: 1, ParallelTestExecution: False, ParseSymbolInformation: True, PathExtension: '', PrintTestOutput: False, RunDisabledTests: False, ShowReleaseNotes: False, ShuffleTests: False, ShuffleTestsSeed: 0, TestDiscoveryRegex: '..exe', TestDiscoveryTimeoutInSeconds: 10, TestNameSeparator: '', TimestampOutput: False, TraitsRegexesAfter: {}, TraitsRegexesBefore: {}, UseNewTestExecutionFramework: True, WorkingDir: '$(ExecutableDir)'
[23/09/2017 18:11:51 Informational] No Google Test indicator file found for executable D:\Dev\TestApp\Utils\x64\Debug\UT_Utils.exe
[23/09/2017 18:11:51 Informational] 'D:\Dev\TestApp\Utils\x64\Debug\UT_Utils.exe' matches custom regex '..exe'
[23/09/2017 18:11:51 Informational] No settings configured for test executable 'D:\Dev\TestApp\Utils\x64\Debug\UT_Utils.exe'; running with solution settings: AdditionalTestExecutionParam: '', BatchForTestSetup: '', BatchForTestTeardown: '', BreakOnFailure: False, CatchExceptions: False, DebugMode: True, KillProcessesOnCancel: False, MaxNrOfThreads: 8, NrOfTestRepetitions: 1, ParallelTestExecution: False, ParseSymbolInformation: True, PathExtension: '', PrintTestOutput: False, RunDisabledTests: False, ShowReleaseNotes: False, ShuffleTests: False, ShuffleTestsSeed: 0, TestDiscoveryRegex: '..exe', TestDiscoveryTimeoutInSeconds: 10, TestNameSeparator: '', TimestampOutput: False, TraitsRegexesAfter: {}, TraitsRegexesBefore: {}, UseNewTestExecutionFramework: True, WorkingDir: '$(ExecutableDir)'
[23/09/2017 18:11:51 Informational] Parsing pdb file "D:\Dev\TestApp\Utils\x64\Debug\UT_Utils.pdb"
[23/09/2017 18:11:51 Informational] Found 35 test method symbols and 0 trait symbols in binary D:\Dev\TestApp\Utils\x64\Debug\UT_Utils.exe
[23/09/2017 18:12:01 Informational] Killed process System.Diagnostics.Process (UT_Utils) with startTime=18:11
[23/09/2017 18:12:01 Error] ERROR: Test discovery was cancelled after 10s for executable D:\Dev\TestApp\Utils\x64\Debug\UT_Utils.exe
[23/09/2017 18:12:01 Error] ERROR: Test whether the following commands can be executed sucessfully on the command line (make sure all required binaries are on the PATH):
cd "D:\Dev\TestApp\Utils\x64\Debug"
UT_Utils.exe --gtest_list_tests
[23/09/2017 18:12:01 Informational] Found 0 tests in executable D:\Dev\TestApp\Utils\x64\Debug\UT_Utils.exe
[23/09/2017 18:12:01 Informational] Test discovery completed, overall duration: 00:00:10.0641990
[23/09/2017 18:12:01 Error] ERROR:

The following errors and warnings occured during test discovery:
ERROR: Test discovery was cancelled after 10s for executable D:\Dev\TestApp\Utils\x64\Debug\UT_Utils.exe
ERROR: Test whether the following commands can be executed sucessfully on the command line (make sure all required binaries are on the PATH):
cd "D:\Dev\TestApp\Utils\x64\Debug"
UT_Utils.exe --gtest_list_tests
[23/09/2017 18:12:01 Informational] ========== Discover test finished: 0 found (0:00:10.1555372) ==========

[csoltenborn]

The log file you included does not talk about an error code , but about a timeout of test discovery - you appear to have set the TestDiscoveryTimeoutInSeconds option to 10s (default is 30s), and after that time span, running the executable with the --gtest_list_tests option is canceled.

Concerning discovery time: We do not have any influence on when our code is triggered and with which executables - this is Visual Studio's responsibility. However, my experience is that rebuilding the solution is not necessary at all - if a single project has been built, and that project has an .exe as output, test discovery should be triggered by VS for that single executable. GTA will report all executables it receives from VS if debugging is enabled - in your log file, only that single UT_Utils.exe file has been provided. If you have to do a Rebuild all to trigger test discovery, my guess would be that your solution setup is somehow broken...

[ldwren]

Thanks for the quick reply.

I have now resolved the issue, but without understanding exactly why.

I increased the Timeout to 120 seconds (as an extreme value to see how that changes things). GTA pops up a MSVC Runtime error dialog as soon as the build finishes (<1 second), so that wasn't the issue. I then started unhooking my Utils library until I got GTA to discover my tests. Eventually I tracked it down to a single line of code in my application.

My utils library has a logging class (based off https://github.com/gabime/spdlog). This library, and my logging class allows for multiple logging streams that can be directed to multiple sinks. My application creates a stream that logs to the MSVC output window and to a file, in my case UT_Utils.dbglog in my project folder. If I remove the file option on the logger GTA discovers the tests. It doesn't matter what the log file is called, if I specify it as a sink GTA fails (even though the file is not created).

My workaround is to only create the logger if the command arguement is not --gtest_list_tests

The issue only appears to affect the list_tests option, I can run tests successfully.

On the subject of having to rebuild: Because I'm trying to get GTA to discover tests my code isn't changing and therefore a simple build is not generating any output. If the code changes, the EXE builds and GTA runs.

As far as I'm concerned this issue is closed. If I get round to tracking down why the issue came about I'll pass the details on to you.

Thanks for your help.

[csoltenborn]

Ok, glad that you solved the problem!

After all, GTA only executes the test executable and interpretes its output. Thus, I'm tempted to think that this might be a gtest problem (or a problem of your code base)... If you are able to provide a minimal non-working example (and it sounds like you would ;-) ), maybe it's an idea to file an issue for gtest?

[ldwren]

Quick followup in case someone else has a similar issue - I hate to find threads that do not have a proper conclusion. The attached file demonstrates the problem, and resoloution.

If you attempt to open a file when running an application in GTA discovery mode it appears the file fails to open, and any unprotected fclose will throw an exception causing GTA test discovery to fail. If you protect the fclose GTA test discovery works.

The attached when debugging through VS or from the command line works as expected. It appears the environment it's being run in through the VS extension causes an issue with fopen.

I can't find any unprotected fclose function calls in my original project, but I guess they're there somewhere.

GTADemo.zip

[csoltenborn]

Interesting... Running an executable via console, within VS with F5, by test discovery, and by test execution is done within different processes for each case. In particular, VS spawns processes for the latter two.

I can reproduce the problem with your example code. Checking errno after fopen_s() results in error message Access denied. My assumption is that the test discovery process does not have sufficient rights for this kind of stuff, probably for security reasons (running an executable without further notice at build completion time certainly poses some risk). This would explain why the other approaches run just fine. I will check back with Microsoft on this and update the documentation accordingly.

However, here's my guess: Is it possible that the root cause is a design smell of your tests or system under test? Try to have the tests' main() methods as simple as possible. Move the problematic code into test setup; gtest provides hooks for executing that code at several stages of test execution (from "once before all tests" to "once per test method"). This makes sure that the code will only be run at test execution time (when there are sufficient rights for file operations).