[2019-04-09 13:47:25,12] [info] Running with database db.url = jdbc:hsqldb:mem:cefbb40f-8591-4d5a-86c4-01fe9c139814;shutdown=false;hsqldb.tx=mvcc [2019-04-09 13:47:31,72] [info] Running migration RenameWorkflowOptionsInMetadata with a read batch size of 100000 and a write batch size of 100000 [2019-04-09 13:47:31,74] [info] [RenameWorkflowOptionsInMetadata] 100% [2019-04-09 13:47:31,84] [info] Running with database db.url = jdbc:hsqldb:mem:5f46834b-3810-4dbc-951c-9060a129a279;shutdown=false;hsqldb.tx=mvcc [2019-04-09 13:47:32,26] [info] Slf4jLogger started [2019-04-09 13:47:32,58] [info] Workflow heartbeat configuration: { "cromwellId" : "cromid-0c449ef", "heartbeatInterval" : "2 minutes", "ttl" : "10 minutes", "writeBatchSize" : 10000, "writeThreshold" : 10000 } [2019-04-09 13:47:32,65] [info] Metadata summary refreshing every 2 seconds. [2019-04-09 13:47:32,67] [warn] 'docker.hash-lookup.gcr-api-queries-per-100-seconds' is being deprecated, use 'docker.hash-lookup.gcr.throttle' instead (see reference.conf) [2019-04-09 13:47:32,69] [info] CallCacheWriteActor configured to flush with batch size 100 and process rate 3 seconds. [2019-04-09 13:47:32,70] [info] KvWriteActor configured to flush with batch size 200 and process rate 5 seconds. [2019-04-09 13:47:32,70] [info] WriteMetadataActor configured to flush with batch size 200 and process rate 5 seconds. [2019-04-09 13:47:32,80] [info] JobExecutionTokenDispenser - Distribution rate: 50 per 1 seconds. [2019-04-09 13:47:32,86] [info] SingleWorkflowRunnerActor: Version 39 [2019-04-09 13:47:32,88] [info] SingleWorkflowRunnerActor: Submitting workflow [2019-04-09 13:47:32,95] [info] Unspecified type (Unspecified version) workflow aab0f674-d28f-4eb4-bb20-2def0b1b4f9a submitted [2019-04-09 13:47:32,98] [info] SingleWorkflowRunnerActor: Workflow submitted aab0f674-d28f-4eb4-bb20-2def0b1b4f9a [2019-04-09 13:47:32,98] [info] 1 new workflows fetched by cromid-0c449ef: aab0f674-d28f-4eb4-bb20-2def0b1b4f9a [2019-04-09 13:47:32,99] [info] WorkflowManagerActor Starting workflow aab0f674-d28f-4eb4-bb20-2def0b1b4f9a [2019-04-09 13:47:33,00] [info] WorkflowManagerActor Successfully started WorkflowActor-aab0f674-d28f-4eb4-bb20-2def0b1b4f9a [2019-04-09 13:47:33,00] [info] Retrieved 1 workflows from the WorkflowStoreActor [2019-04-09 13:47:33,01] [info] WorkflowStoreHeartbeatWriteActor configured to flush with batch size 10000 and process rate 2 minutes. [2019-04-09 13:47:33,15] [info] MaterializeWorkflowDescriptorActor [aab0f674]: Parsing workflow as WDL draft-2 [2019-04-09 13:47:33,92] [info] MaterializeWorkflowDescriptorActor [aab0f674]: Call-to-Backend assignments: tangent_workflow.tangent -> Local [2019-04-09 13:47:35,21] [info] WorkflowExecutionActor-aab0f674-d28f-4eb4-bb20-2def0b1b4f9a [aab0f674]: Starting tangent_workflow.tangent [2019-04-09 13:47:35,82] [info] Assigned new job execution tokens to the following groups: aab0f674: 1 [2019-04-09 13:47:36,71] [warn] BackendPreparationActor_for_aab0f674:tangent_workflow.tangent:-1:1 [aab0f674]: Docker lookup failed java.lang.Exception: Unauthorized to get docker hash lwestlak/tangent-repo:latest at cromwell.engine.workflow.WorkflowDockerLookupActor.cromwell$engine$workflow$WorkflowDockerLookupActor$$handleLookupFailure(WorkflowDockerLookupActor.scala:194) at cromwell.engine.workflow.WorkflowDockerLookupActor$$anonfun$3.applyOrElse(WorkflowDockerLookupActor.scala:86) at cromwell.engine.workflow.WorkflowDockerLookupActor$$anonfun$3.applyOrElse(WorkflowDockerLookupActor.scala:70) at scala.runtime.AbstractPartialFunction.apply(AbstractPartialFunction.scala:34) at akka.actor.FSM.processEvent(FSM.scala:684) at akka.actor.FSM.processEvent$(FSM.scala:681) at cromwell.engine.workflow.WorkflowDockerLookupActor.akka$actor$LoggingFSM$$super$processEvent(WorkflowDockerLookupActor.scala:37) at akka.actor.LoggingFSM.processEvent(FSM.scala:820) at akka.actor.LoggingFSM.processEvent$(FSM.scala:802) at cromwell.engine.workflow.WorkflowDockerLookupActor.processEvent(WorkflowDockerLookupActor.scala:37) at akka.actor.FSM.akka$actor$FSM$$processMsg(FSM.scala:678) at akka.actor.FSM$$anonfun$receive$1.applyOrElse(FSM.scala:672) at scala.runtime.AbstractPartialFunction.apply(AbstractPartialFunction.scala:34) at cromwell.docker.DockerClientHelper$$anonfun$dockerResponseReceive$1.applyOrElse(DockerClientHelper.scala:16) at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:171) at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:172) at akka.actor.Actor.aroundReceive(Actor.scala:517) at akka.actor.Actor.aroundReceive$(Actor.scala:515) at cromwell.engine.workflow.WorkflowDockerLookupActor.aroundReceive(WorkflowDockerLookupActor.scala:37) at akka.actor.ActorCell.receiveMessage(ActorCell.scala:588) at akka.actor.ActorCell.invoke(ActorCell.scala:557) at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:258) at akka.dispatch.Mailbox.run(Mailbox.scala:225) at akka.dispatch.Mailbox.exec(Mailbox.scala:235) at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) [2019-04-09 13:47:36,83] [info] BackgroundConfigAsyncJobExecutionActor [aab0f674tangent_workflow.tangent:NA:1]:  echo hi ls /opt/result//run/tangent_output_run/ bash /opt/wrapper_overall.sh -i /opt/data \ -o /opt/result/ \ -s /cromwell-executions/tangent_workflow/aab0f674-d28f-4eb4-bb20-2def0b1b4f9a/call-tangent/inputs/871759661/example.mysif.txt \ -d /cromwell-executions/tangent_workflow/aab0f674-d28f-4eb4-bb20-2def0b1b4f9a/call-tangent/inputs/871759661/example.mydata.DOC_interval.avg_cvg.txt \ -r None \ -t run \ -p exome \ -c 0.18 \ -a 0.01 \ -n 3 \ -e 150 \ -x false \ -y true \ -z false \ -m /opt/MATLAB/MATLAB_Compiler_Runtime/v714/ ls /opt/result//run/tangent_output_run/ [2019-04-09 13:47:36,85] [info] BackgroundConfigAsyncJobExecutionActor [aab0f674tangent_workflow.tangent:NA:1]: executing: # make sure there is no preexisting Docker CID file rm -f /Users/lwestlak/Documents/Tangent/test_tangent_github/for_firecloud/cromwell-executions/tangent_workflow/aab0f674-d28f-4eb4-bb20-2def0b1b4f9a/call-tangent/execution/docker_cid # run as in the original configuration without --rm flag (will remove later) docker run \ --cidfile /Users/lwestlak/Documents/Tangent/test_tangent_github/for_firecloud/cromwell-executions/tangent_workflow/aab0f674-d28f-4eb4-bb20-2def0b1b4f9a/call-tangent/execution/docker_cid \ -i \ \ --entrypoint /bin/bash \ -v /Users/lwestlak/Documents/Tangent/test_tangent_github/for_firecloud/cromwell-executions/tangent_workflow/aab0f674-d28f-4eb4-bb20-2def0b1b4f9a/call-tangent:/cromwell-executions/tangent_workflow/aab0f674-d28f-4eb4-bb20-2def0b1b4f9a/call-tangent \ lwestlak/tangent-repo:latest /cromwell-executions/tangent_workflow/aab0f674-d28f-4eb4-bb20-2def0b1b4f9a/call-tangent/execution/script # get the return code (working even if the container was detached) rc=$(docker wait cat /Users/lwestlak/Documents/Tangent/test_tangent_github/for_firecloud/cromwell-executions/tangent_workflow/aab0f674-d28f-4eb4-bb20-2def0b1b4f9a/call-tangent/execution/docker_cid) # remove the container after waiting docker rm cat /Users/lwestlak/Documents/Tangent/test_tangent_github/for_firecloud/cromwell-executions/tangent_workflow/aab0f674-d28f-4eb4-bb20-2def0b1b4f9a/call-tangent/execution/docker_cid # return exit code exit $rc [2019-04-09 13:47:37,73] [info] BackgroundConfigAsyncJobExecutionActor [aab0f674tangent_workflow.tangent:NA:1]: job id: 73463 [2019-04-09 13:47:37,73] [info] BackgroundConfigAsyncJobExecutionActor [aab0f674tangent_workflow.tangent:NA:1]: Status change from - to WaitingForReturnCode [2019-04-09 13:47:37,81] [info] Not triggering log of token queue status. Effective log interval = None [2019-04-09 13:49:51,31] [info] BackgroundConfigAsyncJobExecutionActor [aab0f674tangent_workflow.tangent:NA:1]: Status change from WaitingForReturnCode to Done [2019-04-09 13:49:51,93] [error] WorkflowManagerActor Workflow aab0f674-d28f-4eb4-bb20-2def0b1b4f9a failed (during ExecutingWorkflowState): java.io.FileNotFoundException: Could not process output, file not found: /opt/result/run/tangent_output_run/run_woCNV_hg19.catted.seg.txt at cromwell.backend.sfs.SharedFileSystem.mapJobWomFile(SharedFileSystem.scala:157) at cromwell.backend.sfs.SharedFileSystem.mapJobWomFile$(SharedFileSystem.scala:153) at cromwell.backend.sfs.SharedFileSystemJobCachingActorHelper$$anon$1.mapJobWomFile(SharedFileSystemJobCachingActorHelper.scala:13) at cromwell.backend.sfs.SharedFileSystemAsyncJobExecutionActor.mapOutputWomFile(SharedFileSystemAsyncJobExecutionActor.scala:272) at cromwell.backend.sfs.SharedFileSystemAsyncJobExecutionActor.mapOutputWomFile$(SharedFileSystemAsyncJobExecutionActor.scala:271) at cromwell.backend.impl.sfs.config.BackgroundConfigAsyncJobExecutionActor.mapOutputWomFile(ConfigAsyncJobExecutionActor.scala:200) at cromwell.backend.standard.StandardAsyncExecutionActor.$anonfun$outputValueMapper$1(StandardAsyncExecutionActor.scala:796) at wom.WomFileMapper$.$anonfun$mapWomFiles$1(WomFileMapper.scala:25) at scala.util.Try$.apply(Try.scala:209) at wom.WomFileMapper$.mapWomFiles(WomFileMapper.scala:25) at cromwell.backend.standard.StandardAsyncExecutionActor.outputValueMapper(StandardAsyncExecutionActor.scala:796) at cromwell.backend.standard.StandardAsyncExecutionActor.outputValueMapper$(StandardAsyncExecutionActor.scala:795) at cromwell.backend.impl.sfs.config.BackgroundConfigAsyncJobExecutionActor.outputValueMapper(ConfigAsyncJobExecutionActor.scala:200) at cromwell.backend.standard.StandardAsyncExecutionActor.$anonfun$evaluateOutputs$1(StandardAsyncExecutionActor.scala:818) at cromwell.backend.OutputEvaluator$.$anonfun$evaluateOutputs$5(OutputEvaluator.scala:66) at cats.data.EitherT.$anonfun$flatMap$1(EitherT.scala:93) at scala.util.Success.flatMap(Try.scala:247) at cats.instances.TryInstances$$anon$1.flatMap(try.scala:36) at cats.instances.TryInstances$$anon$1.flatMap(try.scala:15) at cats.data.EitherT.flatMap(EitherT.scala:91) at cromwell.backend.OutputEvaluator$.$anonfun$evaluateOutputs$4(OutputEvaluator.scala:65) at cats.data.EitherT.$anonfun$flatMap$1(EitherT.scala:93) at scala.util.Success.flatMap(Try.scala:247) at cats.instances.TryInstances$$anon$1.flatMap(try.scala:36) at cats.instances.TryInstances$$anon$1.flatMap(try.scala:15) at cats.data.EitherT.flatMap(EitherT.scala:91) at cromwell.backend.OutputEvaluator$.$anonfun$evaluateOutputs$1(OutputEvaluator.scala:64) at scala.util.Success.flatMap(Try.scala:247) at cromwell.backend.OutputEvaluator$.foldFunction$1(OutputEvaluator.scala:35) at cromwell.backend.OutputEvaluator$.$anonfun$evaluateOutputs$13(OutputEvaluator.scala:79) at scala.collection.LinearSeqOptimized.foldLeft(LinearSeqOptimized.scala:122) at scala.collection.LinearSeqOptimized.foldLeft$(LinearSeqOptimized.scala:118) at scala.collection.immutable.List.foldLeft(List.scala:86) at cromwell.backend.OutputEvaluator$.fromOutputPorts$1(OutputEvaluator.scala:79) at cromwell.backend.OutputEvaluator$.$anonfun$evaluateOutputs$17(OutputEvaluator.scala:115) at scala.util.Success.$anonfun$map$1(Try.scala:251) at scala.util.Success.map(Try.scala:209) at scala.concurrent.Future.$anonfun$map$1(Future.scala:288) at scala.concurrent.impl.Promise.liftedTree1$1(Promise.scala:29) at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:29) at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60) at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55) at akka.dispatch.BatchingExecutor$BlockableBatch.$anonfun$run$1(BatchingExecutor.scala:91) at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:12) at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:81) at akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:91) at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:40) at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(ForkJoinExecutorConfigurator.scala:44) at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) [2019-04-09 13:49:51,94] [info] WorkflowManagerActor WorkflowActor-aab0f674-d28f-4eb4-bb20-2def0b1b4f9a is in a terminal state: WorkflowFailedState [2019-04-09 13:49:57,71] [info] SingleWorkflowRunnerActor workflow finished with status 'Failed'. [2019-04-09 13:49:57,72] [info] Workflow polling stopped [2019-04-09 13:49:57,75] [info] Shutting down WorkflowStoreActor - Timeout = 5 seconds [2019-04-09 13:49:57,75] [info] 0 workflows released by cromid-0c449ef [2019-04-09 13:49:57,75] [info] Shutting down WorkflowLogCopyRouter - Timeout = 5 seconds [2019-04-09 13:49:57,75] [info] Shutting down JobExecutionTokenDispenser - Timeout = 5 seconds [2019-04-09 13:49:57,75] [info] JobExecutionTokenDispenser stopped [2019-04-09 13:49:57,75] [info] Aborting all running workflows. [2019-04-09 13:49:57,76] [info] WorkflowStoreActor stopped [2019-04-09 13:49:57,76] [info] WorkflowLogCopyRouter stopped [2019-04-09 13:49:57,76] [info] Shutting down WorkflowManagerActor - Timeout = 3600 seconds [2019-04-09 13:49:57,76] [info] WorkflowManagerActor All workflows finished [2019-04-09 13:49:57,76] [info] WorkflowManagerActor stopped [2019-04-09 13:49:57,94] [info] Connection pools shut down [2019-04-09 13:49:57,94] [info] Shutting down SubWorkflowStoreActor - Timeout = 1800 seconds [2019-04-09 13:49:57,94] [info] Shutting down JobStoreActor - Timeout = 1800 seconds [2019-04-09 13:49:57,94] [info] Shutting down CallCacheWriteActor - Timeout = 1800 seconds [2019-04-09 13:49:57,94] [info] SubWorkflowStoreActor stopped [2019-04-09 13:49:57,94] [info] Shutting down ServiceRegistryActor - Timeout = 1800 seconds [2019-04-09 13:49:57,94] [info] Shutting down DockerHashActor - Timeout = 1800 seconds [2019-04-09 13:49:57,94] [info] Shutting down IoProxy - Timeout = 1800 seconds [2019-04-09 13:49:57,94] [info] CallCacheWriteActor Shutting down: 0 queued messages to process [2019-04-09 13:49:57,94] [info] JobStoreActor stopped [2019-04-09 13:49:57,94] [info] WriteMetadataActor Shutting down: 0 queued messages to process [2019-04-09 13:49:57,94] [info] CallCacheWriteActor stopped [2019-04-09 13:49:57,94] [info] KvWriteActor Shutting down: 0 queued messages to process [2019-04-09 13:49:57,94] [info] IoProxy stopped [2019-04-09 13:49:57,94] [info] ServiceRegistryActor stopped [2019-04-09 13:49:57,95] [info] DockerHashActor stopped [2019-04-09 13:49:57,96] [info] Database closed [2019-04-09 13:49:57,96] [info] Stream materializer shut down [2019-04-09 13:49:57,97] [info] WDL HTTP import resolver closed [2019-04-09 13:49:57,98] [info] Shutting down connection pool: curAllocated=0 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false [2019-04-09 13:49:57,98] [info] Shutting down connection pool: curAllocated=0 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false [2019-04-09 13:49:57,98] [info] Shutting down connection pool: curAllocated=0 idleQueues.size=0 waitQueue.size=0 maxWaitQueueLimit=256 closed=false