Inconsistent planemo test output (claiming all tests passed) #415
Description
Just got an interesting result from https://github.com/peterjc/pico_galaxy/blob/a21226bd33be351af1a8e3e49b2de8c7f867ea9a/tools/count_roi_variants/count_roi_variants.xml which looks a bit like #306 although here I'm only looking at the terminal output:
$ planemo --version
planemo, version 0.24.0.dev0
$ planemo test tools/count_roi_variants/
...
galaxy.jobs.runners DEBUG 2016-02-17 16:59:37,619 (8) command is: python /mnt/galaxy/repositories/pico_galaxy/tools/count_roi_variants/count_roi_variants.py --version > /tmp/tmpCWU4jz/tmp/GALAXY_VERSION_STRING_8 2>&1; python /mnt/galaxy/repositories/pico_galaxy/tools/count_roi_variants/count_roi_variants.py "/tmp/tmpCWU4jz/files/000/dataset_7.dat" "/tmp/tmpCWU4jz/files/_metadata_files/000/metadata_4.dat" "/tmp/tmpCWU4jz/files/000/dataset_8.dat" "ref:1695-1725"; return_code=$?; python "/tmp/tmpCWU4jz/job_working_directory/000/8/set_metadata_3X7LN5.py" "/tmp/tmpCWU4jz/tmp/tmpkz8W3a" "/tmp/tmpCWU4jz/job_working_directory/000/8/galaxy.json" "/tmp/tmpCWU4jz/job_working_directory/000/8/metadata_in_HistoryDatasetAssociation_8_PJLbWn,/tmp/tmpCWU4jz/job_working_directory/000/8/metadata_kwds_HistoryDatasetAssociation_8_JdqNBA,/tmp/tmpCWU4jz/job_working_directory/000/8/metadata_out_HistoryDatasetAssociation_8_vjJvgt,/tmp/tmpCWU4jz/job_working_directory/000/8/metadata_results_HistoryDatasetAssociation_8_heFepS,/tmp/tmpCWU4jz/files/000/dataset_8.dat,/tmp/tmpCWU4jz/job_working_directory/000/8/metadata_override_HistoryDatasetAssociation_8_zziBxs" 5242880; sh -c "exit $return_code"
requests.packages.urllib3.connectionpool INFO 2016-02-17 16:59:37,637 Starting new HTTP connection (1): localhost
requests.packages.urllib3.connectionpool DEBUG 2016-02-17 16:59:37,843 "GET /api/jobs/a90a30fafe298e1e?key=704827eebf4c47bb682f2ffa276a89a9 HTTP/1.1" 200 None
galaxy.jobs.runners.local DEBUG 2016-02-17 16:59:37,934 (8) executing job script: /tmp/tmpCWU4jz/job_working_directory/000/8/galaxy_8.sh
galaxy.jobs DEBUG 2016-02-17 16:59:38,006 (8) Persisting job destination (destination id: local:///)
requests.packages.urllib3.connectionpool INFO 2016-02-17 16:59:39,448 Starting new HTTP connection (1): localhost
requests.packages.urllib3.connectionpool DEBUG 2016-02-17 16:59:39,697 "GET /api/jobs/a90a30fafe298e1e?key=704827eebf4c47bb682f2ffa276a89a9 HTTP/1.1" 200 None
galaxy.jobs.runners.local DEBUG 2016-02-17 16:59:41,160 execution finished: /tmp/tmpCWU4jz/job_working_directory/000/8/galaxy_8.sh
galaxy.jobs.output_checker INFO 2016-02-17 16:59:41,216 Job 8: Fatal error: Exit code 1 ()
galaxy.jobs DEBUG 2016-02-17 16:59:41,295 setting dataset state to ERROR
galaxy.jobs DEBUG 2016-02-17 16:59:41,839 job 8 ended (finish() executed in (679.140 ms))
requests.packages.urllib3.connectionpool INFO 2016-02-17 16:59:42,903 Starting new HTTP connection (1): localhost
requests.packages.urllib3.connectionpool DEBUG 2016-02-17 16:59:43,085 "GET /api/jobs/a90a30fafe298e1e?key=704827eebf4c47bb682f2ffa276a89a9 HTTP/1.1" 200 None
requests.packages.urllib3.connectionpool INFO 2016-02-17 16:59:43,088 Starting new HTTP connection (1): localhost
requests.packages.urllib3.connectionpool DEBUG 2016-02-17 16:59:43,157 "GET /api/histories/8155e4b4bf1581ff/contents?key=704827eebf4c47bb682f2ffa276a89a9 HTTP/1.1" 200 None
requests.packages.urllib3.connectionpool INFO 2016-02-17 16:59:43,159 Starting new HTTP connection (1): localhost
requests.packages.urllib3.connectionpool DEBUG 2016-02-17 16:59:43,349 "GET /api/histories/8155e4b4bf1581ff/contents/a90a30fafe298e1e?key=704827eebf4c47bb682f2ffa276a89a9 HTTP/1.1" 200 None
requests.packages.urllib3.connectionpool INFO 2016-02-17 16:59:43,354 Starting new HTTP connection (1): localhost
requests.packages.urllib3.connectionpool DEBUG 2016-02-17 16:59:43,728 "GET /api/histories/8155e4b4bf1581ff/contents/a90a30fafe298e1e/provenance?key=704827eebf4c47bb682f2ffa276a89a9 HTTP/1.1" 200 None
requests.packages.urllib3.connectionpool INFO 2016-02-17 16:59:43,731 Starting new HTTP connection (1): localhost
requests.packages.urllib3.connectionpool DEBUG 2016-02-17 16:59:43,999 "GET /api/jobs/a90a30fafe298e1e?full=true&key=704827eebf4c47bb682f2ffa276a89a9 HTTP/1.1" 200 None
ok
----------------------------------------------------------------------
XML: /tmp/tmpCWU4jz/xunit.xml
----------------------------------------------------------------------
Ran 4 tests in 99.644s
OK
functional_tests.py INFO 2016-02-17 16:59:44,006 Shutting down
functional_tests.py INFO 2016-02-17 16:59:44,006 Shutting down embedded web server
functional_tests.py INFO 2016-02-17 16:59:44,009 Embedded web server stopped
functional_tests.py INFO 2016-02-17 16:59:44,009 Shutting down app
galaxy.jobs.handler INFO 2016-02-17 16:59:44,009 sending stop signal to worker thread
galaxy.jobs.handler INFO 2016-02-17 16:59:44,010 job handler queue stopped
galaxy.jobs.runners INFO 2016-02-17 16:59:44,010 LWRRunner: Sending stop signal to monitor thread
galaxy.jobs.runners INFO 2016-02-17 16:59:44,010 LWRRunner: Sending stop signal to 3 worker threads
galaxy.jobs.runners INFO 2016-02-17 16:59:44,010 TaskRunner: Sending stop signal to 2 worker threads
galaxy.jobs.runners INFO 2016-02-17 16:59:44,011 LocalRunner: Sending stop signal to 5 worker threads
galaxy.jobs.handler INFO 2016-02-17 16:59:44,012 sending stop signal to worker thread
galaxy.jobs.handler INFO 2016-02-17 16:59:44,012 job handler stop queue stopped
functional_tests.py INFO 2016-02-17 16:59:44,013 Embedded Universe application stopped
functional_tests.py INFO 2016-02-17 16:59:44,013 Cleaning up temporary files in /tmp/tmplyCLhM/tmp6E_Bhc
galaxy.jobs.handler INFO 2016-02-17 16:59:44,734 sending stop signal to worker thread
galaxy.jobs.handler INFO 2016-02-17 16:59:44,734 job handler queue stopped
galaxy.jobs.runners INFO 2016-02-17 16:59:44,734 LWRRunner: Sending stop signal to monitor thread
galaxy.jobs.runners INFO 2016-02-17 16:59:44,734 LWRRunner: Sending stop signal to 3 worker threads
galaxy.jobs.runners INFO 2016-02-17 16:59:44,735 TaskRunner: Sending stop signal to 2 worker threads
galaxy.jobs.runners INFO 2016-02-17 16:59:44,735 LocalRunner: Sending stop signal to 5 worker threads
galaxy.jobs.handler INFO 2016-02-17 16:59:44,735 sending stop signal to worker thread
galaxy.jobs.handler INFO 2016-02-17 16:59:44,735 job handler stop queue stopped
All 4 test(s) executed passed.
count_roi_variants[0]: passed
count_roi_variants[1]: passed
count_roi_variants[2]: passed
count_roi_variants[3]: failed
Note the contradiction All 4 test(s) executed passed. yet the last line count_roi_variants[3]: failed
Interestingly the final test is a "negative test",
<test expect_failure="true" expect_exit_code="1">
<param name="input_bam" value="SRR639755_mito_pairs_vs_NC_010642_clc.bam" ftype="bam" />
<param name="region" value="ref:1695-1725" />
<assert_stderr>
<has_line line="ERROR: samtools did not recognise the region requested, can't count any variants." />
</assert_stderr>
</test>
Could that explain the confusion about if the test passed or failed?