search

galaxyproject / planemo

Command-line utilities to assist in developing Galaxy and Common Workflow Language artifacts - including tools, workflows, and training materials.
https://planemo.readthedocs.io
MIT License
90 stars 85 forks source link

Planemo test intermittently passes and fails on same tool test with no changes #766

Closed gregvonkuster closed 2 years ago

gregvonkuster commented 6 years ago

I've run many tests on this tool https://github.com/gregvonkuster/galaxy_tools/tree/master/tools/epigenetics/ideas with no changes to the tool, the test data and the environment, and the test sometimes passes and sometimes fails.

From the directory in which the tool exists on disk (i.e., /home/greg/work/git_workspace/galaxy_tools/tools/epigenetics/ideas, the command I'm running is the following. The --galaxy_root value is a Galaxy instance that tracks the dev branch.

planemo test --galaxy_root /home/greg/work/git_workspace/galaxy --job_output_files /home/greg/work/job_output_files --no_cleanup --conda_dependency_resolution --conda_auto_install --conda_ensure_channels iuc,bioconda,defaults,conda-forge --conda_prefix /home/greg/_conda --conda_exec /home/greg/_conda/bin/conda --conda_debug --test_data /home/greg/work/git_workspace/galaxy_tools/tools/epigenetics/ideas/test-data/ .

Here is the functional test definition.

        <test>
            <param name="perform_training" value="yes"/>
            <param name="training_iterations" value="3"/>
            <param name="input" value="ideas_test1/input.html" dbkey="hg19" ftype="ideaspre">
                <!--
                    The order is critical here - it must be the same as is displayed on the upload form!
                    Also, there seems to be a bug with the composite upload form tab.  All datasets must
                    be selected whether they are optional or not.  
                -->
                <composite_data value='ideas_test1/chromosome_windows.txt'/>
                <composite_data value='ideas_test1/chromosomes.bed'/>
                <composite_data value='ideas_test1/IDEAS_input_config.txt'/>
                <composite_data value='ideas_test1/tmp.tar.gz'/>
            </param>
            <param name="output_heatmaps" value="yes"/>
            <param name="project_name" value="IDEAS_out"/>
            <output_collection name="output_training_collection" type="list">
                <element name="IDEAS_out.chr1.cluster" file="IDEAS_out.chr1.cluster" ftype="txt"/>
                <element name="IDEAS_out.chr2.cluster" file="IDEAS_out.chr2.cluster" ftype="txt"/>
                <element name="IDEAS_out.chr1.state" file="IDEAS_out.chr1.state" ftype="txt"/>
                <element name="IDEAS_out.chr2.state" file="IDEAS_out.chr2.state" ftype="txt"/>
                <element name="IDEAS_out.para0" file="IDEAS_out.para0" ftype="txt"/>
                <element name="IDEAS_out.profile0" file="IDEAS_out.profile0" ftype="txt" compare="contains"/>
            </output_collection>
            <output_collection name="output_pdf_collection" type="list">
                <element name="IDEAS_out.state.1.pdf" file="IDEAS_out.state.1.pdf" ftype="pdf" compare="contains"/>
            </output_collection>
        </test>

Here are sections of the log when the test passes.

2018-02-08 09:03:21,414 INFO  [galaxy.jobs.command_factory] Built script [/tmp/tmpX7nViv/job_working_directory/000/2/tool_script.sh] for tool command [[ "$CONDA_DEFAULT_ENV" = "/home/greg/_conda/envs/mulled-v1-fe5bbf2630381fba9bd71670ae97adab076ae124ccef977d8dc42b41f6da4ca6" ] ||
MAX_TRIES=3
COUNT=0
...
done ; tar -xzf /tmp/tmpX7nViv/job_working_directory/000/1/dataset_1_files/tmp.tar.gz &&  mkdir 'output_pdf_dir' && mkdir 'output_training_dir' &&  Rscript '/home/greg/work/git_workspace/galaxy_tools/tools/epigenetics/ideas/ideas.R' --burnin_num 20 --chrom_bed_input /tmp/tmpX7nViv/job_working_directory/000/1/dataset_1_files/chromosomes.bed --chromosome_windows /tmp/tmpX7nViv/job_working_directory/000/1/dataset_1_files/chromosome_windows.txt --initial_states 20 --ideas_input_config /tmp/tmpX7nViv/job_working_directory/000/1/dataset_1_files/IDEAS_input_config.txt --maxerr 1000000.0 --mcmc_num 20 --minerr 0.5 --output_dir output_training_dir --prior_concentration 1.0 --project_name 'IDEAS_out' --rseed 1234 --thread ${GALAXY_SLOTS:-4} --training_iterations 3 --training_windows 10000 && mv ./*.para0 'output_training_dir' && mv ./*.profile0 'output_training_dir' && echo `pwd` && mv ./*.cluster 'output_training_dir' && mv ./*.state 'output_training_dir' && Rscript '/home/greg/work/git_workspace/galaxy_tools/tools/epigenetics/ideas/create_heatmaps.R' --input_dir 'output_training_dir' --output_dir 'output_pdf_dir' --script_dir '/home/greg/work/git_workspace/galaxy_tools/tools/epigenetics/ideas' --in_training_mode true]
2018-02-08 09:03:21,445 DEBUG [galaxy.tools.deps] Using dependency bcftools version 1.5 of type conda
2018-02-08 09:03:21,446 DEBUG [galaxy.tools.deps] Using dependency bcftools version 1.5 of type conda
/home/greg/work/git_workspace/galaxy/.venv/local/lib/python2.7/site-packages/sqlalchemy/sql/sqltypes.py:185: SAWarning: Unicode type received non-unicode bind param value 'IDEAS_out.state.1.pdf'. (this warning may be suppressed after 10 occurrences)
  (util.ellipses_string(value),))
/home/greg/work/git_workspace/galaxy/.venv/local/lib/python2.7/site-packages/sqlalchemy/sql/sqltypes.py:185: SAWarning: Unicode type received non-unicode bind param value 'IDEAS_out.chr1.cluster'. (this warning may be suppressed after 10 occurrences)
  (util.ellipses_string(value),))
/home/greg/work/git_workspace/galaxy/.venv/local/lib/python2.7/site-packages/sqlalchemy/sql/sqltypes.py:185: SAWarning: Unicode type received non-unicode bind param value 'IDEAS_out.chr1.state'. (this warning may be suppressed after 10 occurrences)
  (util.ellipses_string(value),))
/home/greg/work/git_workspace/galaxy/.venv/local/lib/python2.7/site-packages/sqlalchemy/sql/sqltypes.py:185: SAWarning: Unicode type received non-unicode bind param value 'IDEAS_out.chr2.state'. (this warning may be suppressed after 10 occurrences)
  (util.ellipses_string(value),))
ok

----------------------------------------------------------------------
XML: /tmp/tmpX7nViv/xunit.xml
----------------------------------------------------------------------
Ran 1 test in 68.159s

OK

Here are sections of the log for 1 of several reasons the test fails.

done ; tar -xzf /tmp/tmpX7nViv/job_working_directory/000/1/dataset_1_files/tmp.tar.gz &&  mkdir 'output_pdf_dir' && mkdir 'output_training_dir' &&  Rscript '/home/greg/work/git_workspace/galaxy_tools/tools/epigenetics/ideas/ideas.R' --burnin_num 20 --chrom_bed_input /tmp/tmpX7nViv/job_working_directory/000/1/dataset_1_files/chromosomes.bed --chromosome_windows /tmp/tmpX7nViv/job_working_directory/000/1/dataset_1_files/chromosome_windows.txt --initial_states 20 --ideas_input_config /tmp/tmpX7nViv/job_working_directory/000/1/dataset_1_files/IDEAS_input_config.txt --maxerr 1000000.0 --mcmc_num 20 --minerr 0.5 --output_dir output_training_dir --prior_concentration 1.0 --project_name 'IDEAS_out' --rseed 1234 --thread ${GALAXY_SLOTS:-4} --training_iterations 3 --training_windows 10000 && mv ./*.para0 'output_training_dir' && mv ./*.profile0 'output_training_dir' && echo `pwd` && mv ./*.cluster 'output_training_dir' && mv ./*.state 'output_training_dir' && Rscript '/home/greg/work/git_workspace/galaxy_tools/tools/epigenetics/ideas/create_heatmaps.R' --input_dir 'output_training_dir' --output_dir 'output_pdf_dir' --script_dir '/home/greg/work/git_workspace/galaxy_tools/tools/epigenetics/ideas' --in_training_mode true]
...
FAIL

======================================================================
FAIL: IDEAS ( ideas ) > Test-1
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/greg/work/git_workspace/galaxy/test/functional/test_toolbox.py", line 316, in test_tool
    self.do_it(td)
  File "/home/greg/work/git_workspace/galaxy/test/functional/test_toolbox.py", line 82, in do_it
    raise e
JobOutputsError: Failed to find identifier [IDEAS_out.chr2.cluster] for testing, tool generated collection elements [[{u'element_index': 0, u'element_identifier': u'IDEAS_out.chr1.cluster', u'object': {u'visible': False, u'create_time': u'2018-02-08T14:12:42.073670', u'file_size': 9, u'file_ext': u'txt', u'id': u'54f2a3a23292eb07', u'misc_info': None, u'hda_ldda': u'hda', u'state': u'ok', u'misc_blurb': u'1 line', u'peek': u'<table cellspacing="0" cellpadding="3"><tr><td>id0 0:0</td></tr></table>', u'update_time': u'2018-02-08T14:12:42.602338', u'data_type': u'galaxy.datatypes.data.Text', u'tags': [], u'deleted': False, u'history_id': u'2891970512fa2d5a', u'genome_build': u'hg19', u'hid': 5, u'metadata_data_lines': 1, u'metadata_dbkey': u'hg19', u'history_content_type': u'dataset', u'name': u'IDEAS_out.chr1.cluster', u'uuid': u'122a6ec9-a156-4593-a121-97cf11b107c3', u'model_class': u'HistoryDatasetAssociation', u'purged': False}, u'element_type': u'hda', u'model_class': u'DatasetCollectionElement', u'id': u'5729865256bc2525'}, {u'element_index': 1, u'element_identifier': u'IDEAS_out.chr1.state', u'object': {u'visible': False, u'create_time': u'2018-02-08T14:12:42.167912', u'file_size': 179, u'file_ext': u'txt', u'id': u'8155e4b4bf1581ff', u'misc_info': None, u'hda_ldda': u'hda', u'state': u'ok', u'misc_blurb': u'5 lines', u'peek': u'<table cellspacing="0" cellpadding="3"><tr><td>#ID CHR POSst POSed e001 PosClass</td></tr><tr><td>0 chr1 0 50000000 0 0</td></tr><tr><td>1 chr1 50000000 100000000 0 1</td></tr><tr><td>2 chr1 100000000 150000000 0 1</td></tr><tr><td>3 chr1 150000000 200000000 0 1</td></tr></table>', u'update_time': u'2018-02-08T14:12:42.602342', u'data_type': u'galaxy.datatypes.data.Text', u'tags': [], u'deleted': False, u'history_id': u'2891970512fa2d5a', u'genome_build': u'hg19', u'hid': 6, u'metadata_data_lines': 5, u'metadata_dbkey': u'hg19', u'history_content_type': u'dataset', u'name': u'IDEAS_out.chr1.state', u'uuid': u'9c1b2ad7-7d19-47b0-97e7-486b2c5f48d0', u'model_class': u'HistoryDatasetAssociation', u'purged': False}, u'element_type': u'hda', u'model_class': u'DatasetCollectionElement', u'id': u'54f2a3a23292eb07'}, {u'element_index': 2, u'element_identifier': u'IDEAS_out.chr2.state', u'object': {u'visible': False, u'create_time': u'2018-02-08T14:12:42.255794', u'file_size': 179, u'file_ext': u'txt', u'id': u'7b55dbb89df8f4e5', u'misc_info': None, u'hda_ldda': u'hda', u'state': u'ok', u'misc_blurb': u'5 lines', u'peek': u'<table cellspacing="0" cellpadding="3"><tr><td>#ID CHR POSst POSed e001 PosClass</td></tr><tr><td>0 chr2 0 50000000 0 0</td></tr><tr><td>1 chr2 50000000 100000000 0 1</td></tr><tr><td>2 chr2 100000000 150000000 0 1</td></tr><tr><td>3 chr2 150000000 200000000 0 1</td></tr></table>', u'update_time': u'2018-02-08T14:12:42.602343', u'data_type': u'galaxy.datatypes.data.Text', u'tags': [], u'deleted': False, u'history_id': u'2891970512fa2d5a', u'genome_build': u'hg19', u'hid': 7, u'metadata_data_lines': 5, u'metadata_dbkey': u'hg19', u'history_content_type': u'dataset', u'name': u'IDEAS_out.chr2.state', u'uuid': u'cd7213f2-c526-4798-9545-bc33e2fe8b4f', u'model_class': u'HistoryDatasetAssociation', u'purged': False}, u'element_type': u'hda', u'model_class': u'DatasetCollectionElement', u'id': u'8155e4b4bf1581ff'}, {u'element_index': 3, u'element_identifier': u'IDEAS_out.para0', u'object': {u'visible': False, u'create_time': u'2018-02-08T14:12:42.342670', u'file_size': 40, u'file_ext': u'txt', u'id': u'fa6d20d0fb68383f', u'misc_info': None, u'hda_ldda': u'hda', u'state': u'ok', u'misc_blurb': u'1 line', u'peek': u'<table cellspacing="0" cellpadding="3"><tr><td>#count\th3k4me3\th3k4me3*h3k4me3</td></tr><tr><td>60 0 30</td></tr></table>', u'update_time': u'2018-02-08T14:12:42.602344', u'data_type': u'galaxy.datatypes.data.Text', u'tags': [], u'deleted': False, u'history_id': u'2891970512fa2d5a', u'genome_build': u'hg19', u'hid': 8, u'metadata_data_lines': 1, u'metadata_dbkey': u'hg19', u'history_content_type': u'dataset', u'name': u'IDEAS_out.para0', u'uuid': u'a1a5a39f-e5e6-4802-86bc-da6bc8d3a8d2', u'model_class': u'HistoryDatasetAssociation', u'purged': False}, u'element_type': u'hda', u'model_class': u'DatasetCollectionElement', u'id': u'7b55dbb89df8f4e5'}, {u'element_index': 4, u'element_identifier': u'IDEAS_out.profile0', u'object': {u'visible': False, u'create_time': u'2018-02-08T14:12:42.427110', u'file_size': 42, u'file_ext': u'txt', u'id': u'683bc220e21425bb', u'misc_info': None, u'hda_ldda': u'hda', u'state': u'ok', u'misc_blurb': u'2 lines', u'peek': u'<table cellspacing="0" cellpadding="3"><tr><td>20 0.999999999876308</td></tr><tr><td>10 0.999999999876541</td></tr></table>', u'update_time': u'2018-02-08T14:12:42.602695', u'data_type': u'galaxy.datatypes.data.Text', u'tags': [], u'deleted': False, u'history_id': u'2891970512fa2d5a', u'genome_build': u'hg19', u'hid': 9, u'metadata_data_lines': 2, u'metadata_dbkey': u'hg19', u'history_content_type': u'dataset', u'name': u'IDEAS_out.profile0', u'uuid': u'ab32af66-f978-485a-9976-35f2498c08ad', u'model_class': u'HistoryDatasetAssociation', u'purged': False}, u'element_type': u'hda', u'model_class': u'DatasetCollectionElement', u'id': u'fa6d20d0fb68383f'}]]

----------------------------------------------------------------------
XML: /tmp/tmpIWgZAT/xunit.xml
----------------------------------------------------------------------
Ran 1 test in 57.914s

FAILED (failures=1)

Here is a different test failure. I have not seen a pattern of particular test failures. They seem to be random as far as I can tell. Failures seem to occur more often than successes. For this test, the working directory is specified in this log statement.

2018-02-08 09:57:13,475 INFO  [galaxy.jobs.command_factory] Built script [/tmp/tmpX4hxAM/job_working_directory/000/2/tool_script.sh] for tool command

Here are the contents of the working directory for the test.

$ pwd
/tmp/tmpX4hxAM/job_working_directory/000/2/working
$ ll
total 52
drwxrwxr-x 5 greg greg 4096 Feb  8 09:57 .
drwxrwxr-x 6 greg greg 4096 Feb  8 09:57 ..
-rw-rw-r-- 1 greg greg    0 Feb  8 09:57 conda_activate.log
-rw-rw-r-- 1 greg greg    0 Feb  8 09:57 ideas_log.txt
-rw-rw-r-- 1 greg greg    9 Feb  8 09:57 IDEAS_out.chr1.cluster
-rw-rw-r-- 1 greg greg   62 Feb  8 09:57 IDEAS_out.chr1.para
-rw-rw-r-- 1 greg greg   24 Feb  8 09:57 IDEAS_out.chr1.profile
-rw-rw-r-- 1 greg greg  179 Feb  8 09:57 IDEAS_out.chr1.state
-rw-rw-r-- 1 greg greg    9 Feb  8 09:57 IDEAS_out.chr2.cluster
-rw-rw-r-- 1 greg greg   62 Feb  8 09:57 IDEAS_out.chr2.para
-rw-rw-r-- 1 greg greg   24 Feb  8 09:57 IDEAS_out.chr2.profile
-rw-rw-r-- 1 greg greg  179 Feb  8 09:57 IDEAS_out.chr2.state
drwxrwxr-x 2 greg greg 4096 Feb  8 09:57 output_pdf_dir
drwxrwxr-x 2 greg greg 4096 Feb  8 09:57 output_training_dir
drwxrwxr-x 2 greg greg 4096 Feb  6 09:18 tmp

Here is the section of the test log stating the error. For some reason the .cluster files shown above are not found.

| Dataset Job Standard Error:
|  Fatal error: Exit code 1 ()
|  mv: cannot stat './*.cluster': No such file or directory
|
--------------------------------------

--------------------- >> end captured stdout << ----------------------

----------------------------------------------------------------------
XML: /tmp/tmpPUrDeL/xunit.xml
----------------------------------------------------------------------
Ran 1 test in 32.645s

FAILED (failures=1)
jmchilton commented 6 years ago

This isn't a Planemo issue right? It may be a Galaxy issue but it seems like a tool issue or a file system caching issue. Is this happening on fast local disc or on some mounted filesystem?

gregvonkuster commented 6 years ago

This is on fast local disk - I was running it on my Linux desktop. I cannot guarantee that planemo is the cause, but I never see this behavior when running the tool in Galaxy itself. I'm not seeing how it could be a tool issue. Sometimes the planemo test passes and sometimes it doesn't, and there is no difference in the environment. I'm just running the planemo test command. When it fails, I run it again and keep running it until it passes. So it is definitely intermittent behavior.

mvdbeek commented 2 years ago

Seeing as this isn't likely to be a planemo issue I'll close this