reduce rostest output but print result summary

[floweisshardt]

currently the travis job is spammed by a lot of terminal output from ATF

• rosparameters printed by roslaunch/rostest
• test result in case of failure in atf_results.txt

[fmessmer]

maybe we can set the logger.level to WARN in order to only see the WARN and ERROR logs from during a test run...then, all INFO output - and ideally also the rosparam stuff - is suppressed

[fmessmer]

I'd also would like to see some kind of summary - even if the test succeeds...

[floweisshardt]

would that be a good (and short) summary?

**********************
*** result summary ***
**********************
test 'ts0_c0_r0_e0_s0_0' (robot1, env1, test1, testblockset1): succeeded
test 'ts0_c0_r0_e0_s1_0' (robot1, env1, test1, testblockset2): failed
test 'ts0_c0_r1_e0_s0_0' (robot2, env1, test1, testblockset1): failed
test 'ts0_c0_r1_e0_s1_0' (robot2, env1, test1, testblockset2): failed
test 'ts0_c1_r0_e0_s0_0' (robot1, env1, test2, testblockset1): failed
test 'ts0_c1_r0_e0_s1_0' (robot1, env1, test2, testblockset2): failed
test 'ts0_c1_r1_e0_s0_0' (robot2, env1, test2, testblockset1): failed
test 'ts0_c1_r1_e0_s1_0' (robot2, env1, test2, testblockset2): failed
test 'ts1_c0_r0_e0_s0_0' (robot1, env1, test1, testblockset1): succeeded
test 'ts1_c0_r0_e0_s0_1' (robot1, env1, test1, testblockset1): failed

[floweisshardt]

there is a print for the test summary now in #124 but that's not printed to terminal in travis.

Locally you can get this printed via

rosrun atf_core analyser.py atf_test standalone

or via rostest using the text mode with

rostest build/atf_test/test_generated/analysing.test --text

[fmessmer]

this could be handy: http://wiki.ros.org/rosconsole#Configuration
I guess this could be added to the launch file generated in the atf cmake macro

[fmessmer]

testing in https://github.com/mojin-robotics/mojin_atf/pull/6

[floweisshardt]

terminal is only spammed for failing tests (confirmed in https://travis-ci.com/floweisshardt/atf_test_apps/jobs/290927849), which IMHO is ok to get more debug information. succeeding tests will only show minimal terminal output.

So this issue is a won't fix.

[fmessmer]

this is not true....there is also a lot of terminal spam from various nodes...while running the test...
to suppress this, I tried https://github.com/mojin-robotics/mojin_atf/pull/6

[fmessmer]

we don't want any output while the atf tests are running, i.e. during catkin run_test phase of travis
however atm, there still are logs from e.g. https://github.com/mojin-robotics/mbl/issues/153 or https://github.com/ipa320/cob_command_tools/issues/279

while these issues should be fixed, the error logs should not be suppressed by changing the debug level in the code directly....we should rather find a way for not logging any output for those nodes used during atf recording...

a possible approach is https://github.com/mojin-robotics/mojin_atf/pull/6

in the end, what we want is:

• atf test succeeds: no output in the catkin run_test section and no output in the catkin_test_result section
• atf test fails: no output in the catkin run_test section but atf failure summary in the catkin_test_result section

debugging a failing test needs to be run locally with output from all nodes...this is why we should not suppress any output just because we see it in the travis log...

[fmessmer]

also, for the testblocks you see the huge print of all ROS parameters and nodes being started and killed (see below) - would there be a way to not have this printed?

also, we don't want the kind of output during catkin_test_results as described in #134 (comment), i.e. all the ROS parameters and nodes during atf test summary

[fmessmer]

fmw 5:22 PM
Die *.rostest Files werden generiert und landen dann z.B. in /git/atf/build/atf_test/test_generated/atf_test_generation_config.yaml
in https://github.com/floweisshardt/atf/blob/master/atf_core/cmake/atf_core-extras.cmake.em#L72 wird das CMake Macro für das Starten eines rostests aufgerufen
ein recording*.test sieht z.B. so aus

<?xml version="1.0" ?>
<launch>
  <arg default="true" name="execute_as_test"/>
  <param name="/atf/package_name" value="atf_test"/>
  <param name="/atf/test_generation_config_file" value="atf/test_generation_config.yaml"/>
  <param name="/atf/test_name" value="ts0_c0_r0_e0_s0_0"/>
  <include file="$(find atf_test)/launch/application.launch"/>
  <node name="$(anon atf_application)" output="screen" pkg="atf_test" required="true" type="application.py"/>
  <test args="execute_as_test" if="$(arg execute_as_test)" pkg="atf_core" required="true" test-name="atf_recording_ts0_c0_r0_e0_s0_0" time-limit="180.0" type="sm_test.py"/>
  <node name="atf_recording_ts0_c0_r0_e0_s0_0" output="screen" pkg="atf_core" required="true" type="sm_test.py" unless="$(arg execute_as_test)"/>
</launch>

Was wir auf der Konsole sehen ist der Output dieses rostests (nicht hilfreich, muss weg)
Für das Debugging interessanter wäre der Output von sm_test.py dem eigentlichen python Unittest. Dieser landet dann z.B. in /home/fmw/git/atf/build/atf_test/test_results/atf_test/rosunit-atf_recording_ts0_c0_r1_e0_s1_0.xml (ist glaube ich nicht in Travis zu sehen, wäre aber hilfreich)
Am Ende wird durch den Analysis Job von ATF eine Ausgabe generiert, die die Zusammenfassung der Testblöcke in das Testergebnis des Analysis Tests schreibt und ausgibt: https://github.com/floweisshardt/atf/blob/master/atf_core/scripts/analyser.py#L187 (passt ja soweit)
Dann wird ein catkin_test_results aufgerufen, dass dann eine Zusammenfassung aller Testergebnisse aus /home/fmw/git/atf/build/atf_test/test_results/atf_test/ ausgibt (passt ja soweit)

---

fxm 10:11 AM

fxm@alpamayo:~/projects/default/app_ws/build/mojin_atf_manipulation_pick_place/test_results/mojin_atf_manipulation_pick_place$ catkin_test_results --all
Skipping "rosunit-atf_recording_ts0_c0_r1_e0_s0_0.xml": no element found: line 2, column 0
roslaunch-check__home_fxm_projects_default_app_ws_build_mojin_atf_manipulation_pick_place_test_generated_analysing.test.xml: 1 tests
roslaunch-check__home_fxm_projects_default_app_ws_build_mojin_atf_manipulation_pick_place_test_generated_cleaning.test.xml: 1 tests
roslaunch-check__home_fxm_projects_default_app_ws_build_mojin_atf_manipulation_pick_place_test_generated_merging.test.xml: 1 tests
roslaunch-check__home_fxm_projects_default_app_ws_build_mojin_atf_manipulation_pick_place_test_generated_recording_ts0_c0_r0_e0_s0_0.test.xml: 1 tests
roslaunch-check__home_fxm_projects_default_app_ws_build_mojin_atf_manipulation_pick_place_test_generated_recording_ts0_c0_r1_e0_s0_0.test.xml: 1 tests
roslaunch-check__home_fxm_projects_default_app_ws_build_mojin_atf_manipulation_pick_place_test_generated_recording_ts0_c0_r2_e0_s0_0.test.xml: 1 tests
roslaunch-check__home_fxm_projects_default_app_ws_build_mojin_atf_manipulation_pick_place_test_generated_uploading.test.xml: 1 tests
rostest-test_generated_analysing.xml: 1 tests
rostest-test_generated_cleaning.xml: 1 tests
rostest-test_generated_recording_ts0_c0_r0_e0_s0_0.xml: 1 tests
rostest-test_generated_recording_ts0_c0_r1_e0_s0_0.xml: 1 tests, 1 errors, 0 failures, 0 skipped
rostest-test_generated_recording_ts0_c0_r2_e0_s0_0.xml: 1 tests
rostest-test_generated_uploading.xml: 0 tests
rosunit-analysing.xml: 1 tests, 0 errors, 1 failures, 0 skipped
rosunit-atf_recording_ts0_c0_r0_e0_s0_0.xml: 1 tests
rosunit-atf_recording_ts0_c0_r2_e0_s0_0.xml: 1 tests
rosunit-cleaning.xml: 1 tests
Summary: 16 tests, 1 errors, 1 failures, 0 skipped

wenn wir irgendwie hinbekommen könnten, dass catkin_test_results nur den output der rosunit-* und roslaunch-* files anzeigt, dann hätten wir, was wir wollen
würde man hinkriegen, wenn man die einfach aus dem folder löscht vorher...
also quasi als letzter schritt im catkin run_tests
aber gibts irgend nen fall, wo mal was sinnvolles/hilfreiches im rostest-* file steht?
evtl. sollte man nur die rostest files löschen, von den tests, die in den timeout gelaufen sind oder so...
evtl. könnte man auch im analysing noch etwas klarer darstellen, dass z.B.

 - test 'ts0_c0_r1_e0_s0_0' (mrl-f, shelf, test_default, testblockset_minimal): 
   - testblock 'testblock_all_boxes': 
     - metric 'user_result': no result
   - testblock 'testblock_expected_boxes': 
     - metric 'user_result': no result
   - testblock 'testblock_manipulation': 
     - metric 'user_result': no result
     - metric 'time': no result

bedeutet, dass das recording nicht funktioniert hat....wegen timeout
aber so sieht es vermutlich immer aus, wenn irgend was gecrashed ist im rostest vorher, oder?

[floweisshardt]

here's an interessting issue describing the logging mechanism (and differences) in logging to xml file or terminal or nothing: ros/ros#110 (comment)