A couple things need to occur while the jobs are "running" and it seems that 60 seconds wasn't enough time to sleep for all that to happen on Jenkins.
I checked the timing in the raw logs (they are for some reasons being filtered out in the Jenkins display of the XUnit) - and indeed the jobs are properly sleeping the correct amount of time but the client API calls need some more time it seems. My initial thought was maybe the jobs were being interrupted or something - and that does not appear to be the case.
For instance, fixes#3859 restoring the correct ``element_identifier`` for reduces collections in conditionals. Add tests for combinations of repeats and conditionals.
Currently the logs contain fairly uninformative step delayed messages that don't allow admins to understand why parts of the workflow are being delayed during scheduling.
Here are some examples of before and after.
When running the test:
```
./run_tests.sh -api test/api/test_workflows.py:WorkflowsApiTestCase.test_workflow_pause
```
Before these lines would show up:
```
galaxy.workflow.run DEBUG 2017-03-30 09:23:47,327 Workflow step 2 of invocation 1 invoked (174.149 ms)
galaxy.workflow.run DEBUG 2017-03-30 09:23:47,347 Workflow step 3 of invocation 1 invoked (19.355 ms)
galaxy.workflow.run DEBUG 2017-03-30 09:23:47,364 Workflow step 4 of invocation 1 delayed (16.262 ms)
```
Now these same lines are as follows:
```
galaxy.workflow.run DEBUG 2017-03-30 09:19:28,601 Workflow step 2 of invocation 1 invoked (172.849 ms)
galaxy.workflow.run DEBUG 2017-03-30 09:19:28,619 Marking step 3 outputs delayed (executing pause step)
galaxy.workflow.run DEBUG 2017-03-30 09:19:28,620 Workflow step 3 of invocation 1 invoked (17.999 ms)
galaxy.workflow.run DEBUG 2017-03-30 09:19:28,633 Workflow step 4 of invocation 1 delayed (dependent step [3] delayed, so this step must be delayed) (13.398 ms)
```
Also, when running the test:
```
./run_tests.sh -api test/api/test_workflows.py:WorkflowsApiTestCase.test_workflow_run_dynamic_output_collections_3
```
Before these lines would be printed:
```
galaxy.workflow.run DEBUG 2017-03-30 09:25:35,910 Workflow step 4 of invocation 1 invoked (281.479 ms)
galaxy.workflow.run DEBUG 2017-03-30 09:25:35,937 Workflow step 5 of invocation 1 delayed (25.904 ms)
galaxy.workflow.run DEBUG 2017-03-30 09:25:35,970 Workflow step 6 of invocation 1 delayed (32.597 ms)
```
Now these same lines are as follows:
```
galaxy.workflow.run DEBUG 2017-03-30 09:27:54,270 Workflow step 4 of invocation 1 invoked (295.826 ms)
galaxy.workflow.run DEBUG 2017-03-30 09:27:54,315 Workflow step 5 of invocation 1 delayed (dependent collection [1] not yet populated with datasets) (44.581 ms)
galaxy.workflow.run DEBUG 2017-03-30 09:27:54,326 Workflow step 6 of invocation 1 delayed (dependent step [5] delayed, so this step must be delayed) (10.804 ms)
```
When running workflows with steps that depend explicitly on other steps (instead of implicitly between dataset connections), lines such as:
```
galaxy.workflow.run DEBUG 2017-03-30 09:33:52,966 Marking step 3 outputs delayed (workflow paused at this step waiting for review)
galaxy.workflow.run DEBUG 2017-03-30 09:33:53,001 Workflow step 4 of invocation 1 delayed (dependent step [3] delayed, so this step must be delayed) (0.157 ms)
galaxy.workflow.run DEBUG 2017-03-30 09:33:53,001 Workflow step 5 of invocation 1 delayed (depends on step [4] but that step has not been invoked yet) (0.084 ms)
```
and
```
galaxy.workflow.run DEBUG 2017-03-30 09:33:57,090 Workflow step 5 of invocation 1 delayed (depends on step [4] but one or more jobs created from that step have not finished yet) (0.144 ms)
```
now may appear.
There are two basic behavior changes here and bunch of testing to verify the new behaviors.
1) Previously purging a dataset would cause a creating job to be cancelled but all outputs would need to be "deleted" in order to cause the creating job to be cancelled. After this change the behavior is the same for both deletion and purging - the job will run until all outputs are deleted or purged.
2) Previously Galaxy jobs wouldn't attempt to cleanup purged datasets that were created by a running tool - this cleanup now occurs.
These are tackled as a pair because I assume the difference in the behaviors between deletion and purging was a hack around tools populating datasets that had been purged while running. Cancelling the job wasn't a sure fix - but it would reduce the likelihood of such problems. I think the new approach is a bit more robust and explicit.
The history can be complete before a workflow has fully scheduled if the workflow still has more jobs to schedule but all the current ones are complete.
It may seem like this is testing less since fewer API calls are being made - but when you use the backend to generate the data you trust in the test case - the correlation lands up meaning relatively less is tested. For instance, if there is some problem arises in the to_dict method of a webhook - it is going to arise in both the implementation and in the test case and so the test case will just be asserting that the response is broken ... and it will be. Testing more concrete things is also good for ensuring backward compatibility.
- Move api.helpers to base.populators.
- Refactor helper subclasses adapted to use bioblend instead of test framework stuff into base.populators for greater visibility.
- Refactor workflow format 2 testing stuff for reuse by Selenium.
Martin Cech