gtest results file problem.

[Dennis Young]

I am running into an issue where the 'ament test' is indicating an error, although, there is no error from what I can tell.  When running the test, it displays 'The test did not generate a result file' although it really does.  In addition, this is only reproducible with our continuous integration server but only some of the time.  

I am not very familiar with python, but looking into run_test.py I am seeing that it will generate that error statement, if it believes the test is either timed out or throws an exception.  I have not setup a timeout, so I believe it should use the default with is 60 seconds.  From the logs below, I am just shy of 300 ms for the test.  Here is the results that I have captures thus far.

[10:09:46][Step 3/3] /home/utilite/BuildAgent/work/6fb3b0969bfa563f/PerceptionStack/build/velodyne_pointcloud/test_results/velodyne_pointcloud/test_Convert.gtest.xml report processed: 2 suites, 8 tests

[10:09:46][Step 3/3] 2: -- run_test.py: invoking following command in '/home/utilite/BuildAgent/work/6fb3b0969bfa563f/PerceptionStack/src/sensors/velodyne/velodyne_pointcloud':

[10:09:46][Step 3/3] 2: - /home/utilite/BuildAgent/work/6fb3b0969bfa563f/PerceptionStack/build/velodyne_pointcloud/test_VelodynePacket2PointCloud --gtest_output=xml:/home/utilite/BuildAgent/work/6fb3b0969bfa563f/PerceptionStack/build/velodyne_pointcloud/test_results/velodyne_pointcloud/test_VelodynePacket2PointCloud.gtest.xml

[10:09:46][Step 3/3] 2: Running main() from gmock_main.cc

[10:09:46][Step 3/3] 2: [==========] Running 5 tests from 1 test case.

[10:09:46][Step 3/3] 2: [----------] Global test environment set-up.

[10:09:46][Step 3/3] 2: [----------] 5 tests from TestVelodynePacket2PointCloud

[10:09:46][Step 3/3] 2: [ RUN ] TestVelodynePacket2PointCloud.Constructor_invalidParameter

[10:09:46][Step 3/3] 2: /home/utilite/BuildAgent/work/6fb3b0969bfa563f/PerceptionStack/src/sensors/velodyne/velodyne_pointcloud/src/lib/VelodynePacket2PointCloud.cpp:58

[10:09:46][Step 3/3] 2: [ OK ] TestVelodynePacket2PointCloud.Constructor_invalidParameter (13 ms)

[10:09:46][Step 3/3] 2: [ RUN ] TestVelodynePacket2PointCloud.unpack_invalidLaserCount

[10:09:46][Step 3/3] 2: [ OK ] TestVelodynePacket2PointCloud.unpack_invalidLaserCount (13 ms)

[10:09:46][Step 3/3] 2: [ RUN ] TestVelodynePacket2PointCloud.unpack_validLaserCount_butInvalidAzimuth

[10:09:47][Step 3/3] 2: [ OK ] TestVelodynePacket2PointCloud.unpack_validLaserCount_butInvalidAzimuth (264 ms)

[10:09:47][Step 3/3] 2: [ RUN ] TestVelodynePacket2PointCloud.unpack_validLaserCount_and_validAzimuth_and_validDistance

[10:09:47][Step 3/3] 2: [ OK ] TestVelodynePacket2PointCloud.unpack_validLaserCount_and_validAzimuth_and_validDistance (299 ms)

[10:09:47][Step 3/3] 2: [ RUN ] TestVelodynePacket2PointCloud.unpack_validLaserCount_and_validAzimuth_but_invalidDistance

[10:09:47][Step 3/3] velodyne_pointcloud

[10:09:47][velodyne_pointcloud] test_VelodynePacket2PointCloud.gtest.missing_result

[10:09:47][test_VelodynePacket2PointCloud.gtest.missing_result] The test did not generate a result file.

[10:09:47][Step 3/3] /home/utilite/BuildAgent/work/6fb3b0969bfa563f/PerceptionStack/build/velodyne_pointcloud/test_results/velodyne_pointcloud/test_VelodynePacket2PointCloud.gtest.xml report processed: 1 suite, 1 test

[10:09:47][Step 3/3] 2: [ OK ] TestVelodynePacket2PointCloud.unpack_validLaserCount_and_validAzimuth_but_invalidDistance (299 ms)

[10:09:47][Step 3/3] 2: [----------] 5 tests from TestVelodynePacket2PointCloud (889 ms total)

[10:09:47][Step 3/3] 2:

[10:09:47][Step 3/3] 2: [----------] Global test environment tear-down

[10:09:47][Step 3/3] 2: [==========] 5 tests from 1 test case ran. (891 ms total)

[10:09:47][Step 3/3] 2: [ PASSED ] 5 tests.

[10:09:47][Step 3/3] 2: -- run_test.py: return code 0

[10:09:47][Step 3/3] 2: -- run_test.py: verify result file '/home/utilite/BuildAgent/work/6fb3b0969bfa563f/PerceptionStack/build/velodyne_pointcloud/test_results/velodyne_pointcloud/test_VelodynePacket2PointCloud.gtest.xml'

I did notice in the script, there was some coupling to Jenkins for the results, so I am curious if there is some integration issues with 'Team City'.  

Also, it looks like it is printing out the error before the command is even executed, however, my python skills could be misleading me to that conclusion.  

I have replaced the command ament test with just running ctest in the appropriate directories and have not seen an issue up to this point, which makes me believe the python scripts have an issue.

Any ideas of what should be investigated?

Thanks,

Dennis

[Dirk Thomas]

Hi Dennis,

each test command invocation is wrapped in the Python script `run_test.py` (https://github.com/ament/ament_cmake/blob/1ed12b23a478a54376f23d02e17e8c6ffe0dbc7c/ament_cmake_test/cmake/run_test.py). This wrapper will:

* first remove an old result file if found

* generate a result file indicating that the subsequent test command did not create the expected result file

* invoke the actual test

  * generates a result file based on the exit code if the test itself can't do it (and this is explicitly requested)

* check if the result file was written as expected

This is being done to catch cases in which a test doesn't write a result file correctly but returns zero. Are you sure that your test has generated the expected result file? The error message indicates that it has not overwritten the file generated before (bullet 2). If you can share a reproducible example and / or more information I could take a closer look. Otherwise I can only suggest to check the exact commands, the names and content of the expected result files and adding debug output / sleeps to trace the chain of events.

While the content of the result files is being interpreted by Jenkins it can also be read by any other xUnit compliant program. I don't know anything about Team City.

Cheers,

- Dirk

--
You received this message because you are subscribed to the Google Groups "ROS SIG NG ROS" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ros-sig-ng-ro...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Dennis Young]

Thanks for the reply.  I had assumed that the file would not be generated until the Test.exe completed or at least the entire gtest test fixture completed which the error is being thrown before either of those.  However, my assumption may be bad and I need to determine if that is true.

I am definitely seeing a file after the ament test, but as you indicated, the ament scripts will generate that for me if the test fails to do so.  

[Dennis Young]

Upon doing further digging, I am still confused.  

First of all, I have determined it is dealing with timing.  So I have stripped down the test to:

class TestVelodynePacket2PointCloud : public testing::Test

{

public:

  void SetUp()

  {

  }

  void TearDown()

  {

  }

};

TEST_F(TestVelodynePacket2PointCloud, unpack_validLaserCount_and_validAzimuth_but_invalidDistance) {

  std::this_thread::sleep_for(std::chrono::seconds(20));

}

However, I still can't duplicate by issuing Ament Test from the command line, it has to be issued from the continuous integration server from either a .bat or bash file.  In addition, I added some logging information to the python script, see below for further information.

run_test.py

    try:

        log("-- run_test.py: opening process:")

        proc = subprocess.Popen(

            args.command, stdout=subprocess.PIPE, stderr=subprocess.STDOUT,

            env=env

        )

        while True:

            line = proc.stdout.readline()

            if not line:

                break

            decoded_line = line.decode()

            print(decoded_line, end='')

            output += decoded_line

            if output_handle:

                output_handle.write(line)

                output_handle.flush()

        log('-- run_test.py: waiting\n')

        proc.wait()

        log('-- run_test.py: done waiting\n')

        rc = proc.returncode

        if output_handle:

            # separate progress of this script from subprocess output

            output_handle.write('\n\n'.encode())

        log('-- run_test.py: return code ' + str(rc), file=sys.stderr if rc else sys.stdout)

What is interesting is that when the test fails I get the error message from the python script before the proc.wait returns.  See below.

[12:53:03][Step 3/3] 2: Test command: C:\ProgramData\chocolatey\bin\python.exe "-u" "C:/Asi/ros2-windows/share/ament_cmake_test/cmake/run_test.py" "C:/BuildAgent/work/6fb3b0969bfa563f/PerceptionStack/build/velodyne_pointcloud/test_results/velodyne_pointcloud/test_VelodynePacket2PointCloud.gtest.xml" "--output-file" "C:/BuildAgent/work/6fb3b0969bfa563f/PerceptionStack/build/velodyne_pointcloud/ament_cmake_gmock/test_VelodynePacket2PointCloud.txt" "--command" "C:/BuildAgent/work/6fb3b0969bfa563f/PerceptionStack/build/velodyne_pointcloud/Release/test_VelodynePacket2PointCloud.exe" "--gtest_output=xml:C:/BuildAgent/work/6fb3b0969bfa563f/PerceptionStack/build/velodyne_pointcloud/test_results/velodyne_pointcloud/test_VelodynePacket2PointCloud.gtest.xml"

[12:53:03][Step 3/3] 2: Test timeout computed to be: 60

[12:53:03][Step 3/3] 2: -- run_test.py: invoking following command in 'C:\BuildAgent\work\6fb3b0969bfa563f\PerceptionStack\src\sensors\velodyne\velodyne_pointcloud':

[12:53:03][Step 3/3] 2: - C:/BuildAgent/work/6fb3b0969bfa563f/PerceptionStack/build/velodyne_pointcloud/Release/test_VelodynePacket2PointCloud.exe --gtest_output=xml:C:/BuildAgent/work/6fb3b0969bfa563f/PerceptionStack/build/velodyne_pointcloud/test_results/velodyne_pointcloud/test_VelodynePacket2PointCloud.gtest.xml

[12:53:03][Step 3/3] 2: -- run_test.py: opening process:

[12:53:03][Step 3/3] 2: Running main() from gmock_main.cc

[12:53:03][Step 3/3] 2: [==========] Running 1 test from 1 test case.

[12:53:03][Step 3/3] 2: [----------] Global test environment set-up.

[12:53:03][Step 3/3] 2: [----------] 1 test from TestVelodynePacket2PointCloud

[12:53:03][Step 3/3] 2: [ RUN ] TestVelodynePacket2PointCloud.unpack_validLaserCount_and_validAzimuth_but_invalidDistance

[12:53:04][Step 3/3] velodyne_pointcloud

[12:53:04][velodyne_pointcloud] test_VelodynePacket2PointCloud.gtest.missing_result

[12:53:04][test_VelodynePacket2PointCloud.gtest.missing_result] The test did not generate a result file.

[12:53:23][Step 3/3] 2: [ OK ] TestVelodynePacket2PointCloud.unpack_validLaserCount_and_validAzimuth_but_invalidDistance (20000 ms)

[12:53:23][Step 3/3] 2: [----------] 1 test from TestVelodynePacket2PointCloud (20000 ms total)

[12:53:23][Step 3/3] 2:

[12:53:23][Step 3/3] 2: [----------] Global test environment tear-down

[12:53:23][Step 3/3] 2: [==========] 1 test from 1 test case ran. (20000 ms total)

[12:53:23][Step 3/3] 2: [ PASSED ] 1 test.

[12:53:23][Step 3/3] 2: -- run_test.py: waiting

[12:53:23][Step 3/3] 2:

[12:53:23][Step 3/3] 2: -- run_test.py: done waiting

[12:53:23][Step 3/3] 2:

[12:53:23][Step 3/3] 2: -- run_test.py: return code 0

[12:53:23][Step 3/3] 2: -- run_test.py: verify result file 'C:/BuildAgent/work/6fb3b0969bfa563f/PerceptionStack/build/velodyne_pointcloud/test_results/velodyne_pointcloud/test_VelodynePacket2PointCloud.gtest.xml'

I was expecting the output to be thrown latter in the script where it checks to see if the file has changed.

So I am not understanding why the error is being displayed when it is, the test should complete before it checks that a file was not created.  I have managed to get pass this issue by not opening the file in the run_test.py before the command is issued, see below.  I did verify that the .xml file was created successfully with all the information that I needed.

    failure_result_file = _generate_result(

        args.result_file,

        'The test did not generate a result file.'

    )

    #with open(args.result_file, 'w') as h:

    #    h.write(failure_result_file)

So I know that there is timeouts for the testing, which defaults to 60 seconds.  Something I have not changed, when I change the timeout to exceed that, I do see a timeout error displayed.  So I don't think a timeout is occurring, somehow when the process is being split, one is going off and doing something that I am not expecting.

Thanks for any other help that you can provide on this issue.

Dennis

On Thursday, May 12, 2016 at 1:54:39 PM UTC-6, Dirk Thomas wrote:

[Dirk Thomas]

The order of printed messages might be misleading. There are several entities involved which pass along the output. Especially separate output to `stdout` and `stderr` are susceptible to ordering problems.

The question currently is if the gtest executable is actually generating a result file or not. `run_test.py` seems to think that it doesn't. Can you run the command (`path/to/test_VelodynePacket2PointCloud.exe --gtest_output=xml:...`) manually and check if it generates the result file?

Cheers,

- Dirk

[Dennis Young]

That does work correctly.