Catch JSONDecodeError and printout some debug info

[brawner]

Attempting to debug a simple programming error led me to want some more information in the test results log file. Because the results file was incomplete after the test threw an exception, the json loads fails and throws an Python exception. By the nature of Python's helpful exception output, it makes it look like the error is the results file being the problem, but really it's just the test itself that failed to complete. I'm totally open to adjusting how this information looks though.

This is the new output if my test throws an exception:

Test command: /usr/bin/python3 "-u" "/home/brawner/workspace/ros2_master/install/ament_cmake_test/share/ament_cmake_test/cmake/run_test.py" "/home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.xml" "--package-name" "rclcpp" "--generate-result-on-success" "--output-file" "/home/brawner/workspace/ros2_master/build/rclcpp/ament_cmake_google_benchmark/benchmark_node__rmw_fastrtps_dynamic_cpp.txt" "--env" "LD_PRELOAD=/home/brawner/workspace/ros2_master/install/osrf_testing_tools_cpp/lib/libmemory_tools_interpose.so" "--command" "/usr/bin/python3" "-u" "/home/brawner/workspace/ros2_master/install/ament_cmake_google_benchmark/share/ament_cmake_google_benchmark/cmake/run_and_convert.py" "/home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.google_benchmark.json" "/home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.benchmark.json" "--package-name" "rclcpp" "--command" "/home/brawner/workspace/ros2_master/build/rclcpp/test/rclcpp/benchmark/benchmark_node__rmw_fastrtps_dynamic_cpp" "--benchmark_out_format=json" "--benchmark_out=/home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.google_benchmark.json"
92: Test timeout computed to be: 60
92: -- run_test.py: extra environment variables:
92:  - LD_PRELOAD=/home/brawner/workspace/ros2_master/install/osrf_testing_tools_cpp/lib/libmemory_tools_interpose.so
92: -- run_test.py: invoking following command in '/home/brawner/workspace/ros2_master/build/rclcpp/test/rclcpp/benchmark':
92:  - /usr/bin/python3 -u /home/brawner/workspace/ros2_master/install/ament_cmake_google_benchmark/share/ament_cmake_google_benchmark/cmake/run_and_convert.py /home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.google_benchmark.json /home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.benchmark.json --package-name rclcpp --command /home/brawner/workspace/ros2_master/build/rclcpp/test/rclcpp/benchmark/benchmark_node__rmw_fastrtps_dynamic_cpp --benchmark_out_format=json --benchmark_out=/home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.google_benchmark.json
92: Executing benchmark test command: /home/brawner/workspace/ros2_master/build/rclcpp/test/rclcpp/benchmark/benchmark_node__rmw_fastrtps_dynamic_cpp --benchmark_out_format=json --benchmark_out=/home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.google_benchmark.json
92: 
92: 
92: 2020-10-19T15:56:14-07:00
92: Running /home/brawner/workspace/ros2_master/build/rclcpp/test/rclcpp/benchmark/benchmark_node__rmw_fastrtps_dynamic_cpp
92: Run on (64 X 3700 MHz CPU s)
92: CPU Caches:
92:   L1 Data 32 KiB (x32)
92:   L1 Instruction 32 KiB (x32)
92:   L2 Unified 512 KiB (x32)
92:   L3 Unified 16384 KiB (x8)
92: Load Average: 8.05, 3.85, 3.20
92: ***WARNING*** CPU scaling is enabled, the benchmark real time measurements may be noisy and will incur extra overhead.
92: ***WARNING*** Library was built as DEBUG. Timings may be affected.
92: terminate called after throwing an instance of 'rclcpp::ContextAlreadyInitialized'
92:   what():  context is already initialized
92: 
92: 
92: Test command returned result status -6
92: Failure parsing performance results file at: /home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.google_benchmark.json
92: Expecting value: line 39 column 1 (char 868)
92: -- run_test.py: return code 1
92: -- run_test.py: generate result file '/home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.xml' with failed test
92: -- run_test.py: verify result file '/home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.xml'
9/9 Test #92: benchmark_node__rmw_fastrtps_dynamic_cpp ............***Failed    0.29 sec

67% tests passed�[0;0m, �[0;31m3 tests failed�[0;0m out of 9

Example of old output:

Test command: /usr/bin/python3 "-u" "/home/brawner/workspace/ros2_master/install/ament_cmake_test/share/ament_cmake_test/cmake/run_test.py" "/home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.xml" "--package-name" "rclcpp" "--generate-result-on-success" "--output-file" "/home/brawner/workspace/ros2_master/build/rclcpp/ament_cmake_google_benchmark/benchmark_node__rmw_fastrtps_dynamic_cpp.txt" "--env" "LD_PRELOAD=/home/brawner/workspace/ros2_master/install/osrf_testing_tools_cpp/lib/libmemory_tools_interpose.so" "--command" "/usr/bin/python3" "-u" "/home/brawner/workspace/ros2_master/install/ament_cmake_google_benchmark/share/ament_cmake_google_benchmark/cmake/run_and_convert.py" "/home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.google_benchmark.json" "/home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.benchmark.json" "--package-name" "rclcpp" "--command" "/home/brawner/workspace/ros2_master/build/rclcpp/test/rclcpp/benchmark/benchmark_node__rmw_fastrtps_dynamic_cpp" "--benchmark_out_format=json" "--benchmark_out=/home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.google_benchmark.json"
92: Test timeout computed to be: 60
92: -- run_test.py: extra environment variables:
92:  - LD_PRELOAD=/home/brawner/workspace/ros2_master/install/osrf_testing_tools_cpp/lib/libmemory_tools_interpose.so
92: -- run_test.py: invoking following command in '/home/brawner/workspace/ros2_master/build/rclcpp/test/rclcpp/benchmark':
92:  - /usr/bin/python3 -u /home/brawner/workspace/ros2_master/install/ament_cmake_google_benchmark/share/ament_cmake_google_benchmark/cmake/run_and_convert.py /home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.google_benchmark.json /home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.benchmark.json --package-name rclcpp --command /home/brawner/workspace/ros2_master/build/rclcpp/test/rclcpp/benchmark/benchmark_node__rmw_fastrtps_dynamic_cpp --benchmark_out_format=json --benchmark_out=/home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.google_benchmark.json
92: 2020-10-19T15:15:56-07:00
92: Running /home/brawner/workspace/ros2_master/build/rclcpp/test/rclcpp/benchmark/benchmark_node__rmw_fastrtps_dynamic_cpp
92: Run on (64 X 3700 MHz CPU s)
92: CPU Caches:
92:   L1 Data 32 KiB (x32)
92:   L1 Instruction 32 KiB (x32)
92:   L2 Unified 512 KiB (x32)
92:   L3 Unified 16384 KiB (x8)
92: Load Average: 1.40, 5.13, 9.00
92: ***WARNING*** CPU scaling is enabled, the benchmark real time measurements may be noisy and will incur extra overhead.
92: ***WARNING*** Library was built as DEBUG. Timings may be affected.
92: terminate called after throwing an instance of 'rclcpp::ContextAlreadyInitialized'
92:   what():  context is already initialized
92: Traceback (most recent call last):
92:   File "/home/brawner/workspace/ros2_master/install/ament_cmake_google_benchmark/share/ament_cmake_google_benchmark/cmake/run_and_convert.py", line 23, in <module>
92:     sys.exit(ament_cmake_google_benchmark.main())
92:   File "/home/brawner/workspace/ros2_master/install/ament_cmake_google_benchmark/lib/python3.8/site-packages/ament_cmake_google_benchmark/__init__.py", line 97, in main
92:     in_data = json.loads(in_text)
92:   File "/usr/lib/python3.8/json/__init__.py", line 357, in loads
92:     return _default_decoder.decode(s)
92:   File "/usr/lib/python3.8/json/decoder.py", line 337, in decode
92:     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
92:   File "/usr/lib/python3.8/json/decoder.py", line 355, in raw_decode
92:     raise JSONDecodeError("Expecting value", s, err.value) from None
92: json.decoder.JSONDecodeError: Expecting value: line 39 column 1 (char 865)
92: -- run_test.py: return code 1
92: -- run_test.py: generate result file '/home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.xml' with failed test
92: -- run_test.py: verify result file '/home/brawner/workspace/ros2_master/build/rclcpp/test_results/rclcpp/benchmark_node__rmw_fastrtps_dynamic_cpp.xml'
9/9 Test #92: benchmark_node__rmw_fastrtps_dynamic_cpp ............***Failed    0.39 sec

Signed-off-by: Stephen Brawner brawner@gmail.com

[brawner]

@cottsay @ahcorde pinging for review

[cottsay]

One suggestion, but looks good other than that.

[cottsay]

Suggested change

	res.returncode = 1
	if res.returncode == 0:
	res.returncode = 1

[brawner]

Done

[brawner]

Is there a appropriate way to test this other than a quick CI job?
Testing --packages-select ament_cmake_google_benchmark

• Linux
• Linux-aarch64
• macOS
• Windows

[cottsay]

Is there a appropriate way to test this other than a quick CI job?

It would be nice to test at least one package with performance tests enabled just to ensure that this didn't regress normal builds.
Something like:
--packages-up-to libstatistics_collector --cmake-args -DAMENT_RUN_PERFORMANCE_TESTS=ON
--packages-select libstatistics_collector --ctest-args -L performance

[brawner]

• Linux
• Linux-aarch64
• macOS
• Windows

[brawner]

The cmake warning in these last tests is just cmake complaining about packages not making use of AMENT_RUN_PERFORMANCE_TESTS=ON. In this case that should be expected.