Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Catch JSONDecodeError and printout some debug info #291

Merged

Conversation

brawner
Copy link
Contributor

@brawner brawner commented Oct 19, 2020

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

Signed-off-by: Stephen Brawner <brawner@gmail.com>
@brawner
Copy link
Contributor Author

brawner commented Oct 19, 2020

@cottsay @ahcorde pinging for review

Copy link
Contributor

@cottsay cottsay left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One suggestion, but looks good other than that.

'Failure parsing performance results file at: %s' % args.result_file_in,
file=sys.stderr)
print(e)
res.returncode = 1
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

Signed-off-by: Stephen Brawner <brawner@gmail.com>
@brawner
Copy link
Contributor Author

brawner commented Oct 20, 2020

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

  • Linux Build Status
  • Linux-aarch64 Build Status
  • macOS Build Status
  • Windows Build Status

@cottsay
Copy link
Contributor

cottsay commented Oct 20, 2020

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
Copy link
Contributor Author

brawner commented Oct 20, 2020

  • Linux Build Status
  • Linux-aarch64 Build Status
  • macOS Build Status
  • Windows Build Status

@brawner
Copy link
Contributor Author

brawner commented Oct 20, 2020

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.

@cottsay cottsay merged commit a5fb311 into ament:master Oct 20, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants