Unable to dump output of process 'xxx' -- Cause: java.nio.file.NoSuchFileException .command.out/.command.err

[Tong-Chen]

I have a workflow RNAseq_salmon.nf, which could be run successfully in bash terminal manually in /path or through python module subprocess (based on Popen(RNAseq_salmon.nf, cwd="/path")). However, when running this process using Celery (which also uses Popen to run (RNAseq_salmon.nf internally), it fails.

The most explicit error is:

May-26 19:13:44.820 [Task monitor] DEBUG n.processor.TaskPollingMonitor - Task completed > TaskHandler[id: 8; name: SALMON_QUANT (trt_N061011); status: COMPLETED; exit: 1; error: -; workDir: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/b3/27c8e1eef9a76d2ba053753bb88d0a]
May-26 19:13:44.837 [Task monitor] DEBUG nextflow.processor.TaskRun - Unable to dump output of process 'SALMON_QUANT (trt_N061011)' -- Unable to dump output of process Cause: java.nio.file.NoSuchFileException .command.out: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/b3/27c8e1eef9a76d2ba053753bb88d0a/.command.out
May-26 19:13:44.838 [Task monitor] DEBUG nextflow.processor.TaskRun - Unable to dump error of process 'SALMON_QUANT (trt_N061011)' -- Cause: java.nio.file.NoSuchFileException: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/b3/27c8e1eef9a76d2ba053753bb88d0a/.command.err

When I move to the directory /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/b3/27c8e1eef9a76d2ba053753bb88d0a/ and run bash .command.run, it finished successfully.

Normally when I met java.nio.file.NoSuchFileException, it may be caused by the parent directory being uncreated. I wonder if there is one possibility that when dumping errors to .command.out, the dir work/b3/27c8e1eef9a76d2ba053753bb88d0a is missing. But when I check the errors, these directories are ready. I just do not know why.

Also, it is weird, since .command.run is generated, which means the directory work/b3/27c8e1eef9a76d2ba053753bb88d0a is created.

I have tried to change workDir to another directory and searched using Google and got no luck.

Could anyone please give some suggestions?

Thanks!

Chen Tong

Full logs below:

May-26 19:13:33.835 [main] INFO  nextflow.cli.CmdRun - N E X T F L O W  ~  version 22.04.5

May-26 19:13:36.263 [main] DEBUG nextflow.plugin.PluginsFacade - Setting up plugin manager > mode=prod; plugins-dir=/home/bogon/.nextflow/plugins; core-plugins: nf-amazon@1.7.2,nf-azure@0.13.2,nf-console@1.0.3,nf-ga4gh@1.0.3,nf-google@1.1.4,nf-sqldb@0.4.0,nf-tower@1.4.0
May-26 19:13:36.266 [main] DEBUG nextflow.plugin.PluginsFacade - Plugins default=[]
May-26 19:13:36.293 [main] INFO  org.pf4j.DefaultPluginStatusProvider - Enabled plugins: []
May-26 19:13:36.295 [main] INFO  org.pf4j.DefaultPluginStatusProvider - Disabled plugins: []
May-26 19:13:36.304 [main] INFO  org.pf4j.DefaultPluginManager - PF4J version 3.4.1 in 'deployment' mode
May-26 19:13:36.326 [main] INFO  org.pf4j.AbstractPluginManager - No plugins
May-26 19:13:36.452 [main] DEBUG nextflow.Session - Session uuid: 3c7f7171-96b7-418f-b6c6-4689ecfd822b
May-26 19:13:36.452 [main] DEBUG nextflow.Session - Run name: disturbed_saha
May-26 19:13:36.453 [main] DEBUG nextflow.Session - Executor pool size: 80
May-26 19:13:36.538 [main] DEBUG nextflow.cli.CmdRun - 
  Version: 22.04.5 build 5708
  Created: 15-07-2022 16:09 UTC (16-07-2022 00:09 CDT)
  System: Linux 4.18.0-305.10.2.el8_4.x86_64
  Runtime: Groovy 3.0.10 on OpenJDK 64-Bit Server VM 17.0.4+8
  Encoding: UTF-8 (UTF-8)
  Process: 2791252@bogon [192.168.0.102]
  CPUs: 80 - Mem: 361.8 GB (299.7 GB) - Swap: 119.2 GB (88.7 GB)
May-26 19:13:36.597 [main] DEBUG nextflow.Session - Work-dir: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work [ext2/ext3]
May-26 19:13:36.598 [main] DEBUG nextflow.Session - Script base path does not exist or is not a directory: /home/bogon/bin/bin
May-26 19:13:36.631 [main] DEBUG nextflow.executor.ExecutorFactory - Extension executors providers=[]
May-26 19:13:36.652 [main] DEBUG nextflow.Session - Observer factory: DefaultObserverFactory
May-26 19:13:36.751 [main] DEBUG nextflow.cache.CacheFactory - Using Nextflow cache factory: nextflow.cache.DefaultCacheFactory
May-26 19:13:36.771 [main] DEBUG nextflow.util.CustomThreadPool - Creating default thread pool > poolSize: 81; maxThreads: 1000
May-26 19:13:36.902 [main] DEBUG nextflow.Session - Session start invoked
May-26 19:13:36.909 [main] DEBUG nextflow.trace.TraceFileObserver - Flow starting -- trace file: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/ed9908ef-89d6-4b91-b379-d159deb19f96/pipeline_info/execution_trace.txt
May-26 19:13:37.457 [main] DEBUG nextflow.script.ScriptRunner - > Launching execution
May-26 19:13:39.017 [main] DEBUG nextflow.script.ProcessConfig - Config settings `withLabel:process_medium` matches labels `process_medium` for process with name SALMON_QUANT
May-26 19:13:39.033 [main] DEBUG nextflow.executor.ExecutorFactory - << taskConfig executor: null
May-26 19:13:39.034 [main] DEBUG nextflow.executor.ExecutorFactory - >> processorType: 'local'
May-26 19:13:39.046 [main] DEBUG nextflow.executor.Executor - [warm up] executor > local
May-26 19:13:39.061 [main] DEBUG n.processor.LocalPollingMonitor - Creating local task monitor for executor 'local' > cpus=80; memory=361.8 GB; capacity=80; pollInterval=100ms; dumpInterval=5m
May-26 19:13:39.215 [main] DEBUG nextflow.processor.TaskProcessor - Creating *combiner* operator for each param(s) at index(es): [1, 2]
May-26 19:13:39.272 [main] DEBUG nextflow.script.ProcessConfig - Config settings `withLabel:process_medium` matches labels `process_medium` for process with name SALMON_QUANT_OUTPUT
May-26 19:13:39.274 [main] DEBUG nextflow.executor.ExecutorFactory - << taskConfig executor: null
May-26 19:13:39.274 [main] DEBUG nextflow.executor.ExecutorFactory - >> processorType: 'local'
May-26 19:13:39.300 [main] DEBUG nextflow.script.ProcessConfig - Config settings `withLabel:process_medium` matches labels `process_medium` for process with name SALMON_QUANT_DE
May-26 19:13:39.307 [main] DEBUG nextflow.executor.ExecutorFactory - << taskConfig executor: null
May-26 19:13:39.307 [main] DEBUG nextflow.executor.ExecutorFactory - >> processorType: 'local'
May-26 19:13:39.328 [main] DEBUG nextflow.Session - Workflow process names [dsl2]: SALMON_QUANT_DE, SALMON_BUILD_INDEX, SALMON_QUANT_OUTPUT, SALMON_QUANT, SALMON_QUANT_OUTPUT_INNER
May-26 19:13:39.330 [main] DEBUG nextflow.Session - Ignite dataflow network (9)
May-26 19:13:39.346 [main] DEBUG nextflow.processor.TaskProcessor - Starting process > SALMON_QUANT
May-26 19:13:39.348 [main] DEBUG nextflow.processor.TaskProcessor - Starting process > SALMON_QUANT
May-26 19:13:39.349 [main] DEBUG nextflow.processor.TaskProcessor - Starting process > SALMON_QUANT_OUTPUT
May-26 19:13:39.352 [main] DEBUG nextflow.processor.TaskProcessor - Starting process > SALMON_QUANT_DE
May-26 19:13:39.354 [main] DEBUG nextflow.script.ScriptRunner - > Await termination 
May-26 19:13:39.354 [main] DEBUG nextflow.Session - Session await
May-26 19:13:39.614 [Actor Thread 41] DEBUG nextflow.conda.CondaCache - conda found local env for environment=/anaconda3/envs/transcriptome/; path=/anaconda3/envs/transcriptome
May-26 19:13:39.822 [Task submitter] DEBUG nextflow.executor.LocalTaskHandler - Launch cmd line: /bin/bash -ue .command.run
May-26 19:13:39.832 [Task submitter] INFO  nextflow.Session - [18/bc1037] Submitted process > SALMON_QUANT (untrt_N052611)
May-26 19:13:39.851 [Task submitter] DEBUG nextflow.executor.LocalTaskHandler - Launch cmd line: /bin/bash -ue .command.run
May-26 19:13:39.852 [Task submitter] INFO  nextflow.Session - [fb/7681de] Submitted process > SALMON_QUANT (trt_N080611)
May-26 19:13:39.874 [Task submitter] DEBUG nextflow.executor.LocalTaskHandler - Launch cmd line: /bin/bash -ue .command.run
May-26 19:13:39.875 [Task submitter] INFO  nextflow.Session - [b2/5fcc5a] Submitted process > SALMON_QUANT (untrt_N61311)
May-26 19:13:39.893 [Task submitter] DEBUG nextflow.executor.LocalTaskHandler - Launch cmd line: /bin/bash -ue .command.run
May-26 19:13:39.893 [Task submitter] INFO  nextflow.Session - [b3/3d236c] Submitted process > SALMON_QUANT (trt_N052611)
May-26 19:13:39.909 [Task submitter] DEBUG nextflow.executor.LocalTaskHandler - Launch cmd line: /bin/bash -ue .command.run
May-26 19:13:39.910 [Task submitter] INFO  nextflow.Session - [18/250c6b] Submitted process > SALMON_QUANT (trt_N61311)
May-26 19:13:39.928 [Task submitter] DEBUG nextflow.executor.LocalTaskHandler - Launch cmd line: /bin/bash -ue .command.run
May-26 19:13:39.929 [Task submitter] INFO  nextflow.Session - [b3/27c8e1] Submitted process > SALMON_QUANT (trt_N061011)
May-26 19:13:39.947 [Task submitter] DEBUG nextflow.executor.LocalTaskHandler - Launch cmd line: /bin/bash -ue .command.run
May-26 19:13:39.948 [Task submitter] INFO  nextflow.Session - [56/e85c69] Submitted process > SALMON_QUANT (untrt_N061011)
May-26 19:13:39.967 [Task submitter] DEBUG nextflow.executor.LocalTaskHandler - Launch cmd line: /bin/bash -ue .command.run
May-26 19:13:39.968 [Task submitter] INFO  nextflow.Session - [ba/4516b7] Submitted process > SALMON_QUANT (untrt_N080611)
May-26 19:13:44.820 [Task monitor] DEBUG n.processor.TaskPollingMonitor - Task completed > TaskHandler[id: 8; name: SALMON_QUANT (trt_N061011); status: COMPLETED; exit: 1; error: -; workDir: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/b3/27c8e1eef9a76d2ba053753bb88d0a]
May-26 19:13:44.837 [Task monitor] DEBUG nextflow.processor.TaskRun - Unable to dump output of process 'SALMON_QUANT (trt_N061011)' -- Unable to dump output of process Cause: java.nio.file.NoSuchFileException .command.out: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/b3/27c8e1eef9a76d2ba053753bb88d0a/.command.out
May-26 19:13:44.838 [Task monitor] DEBUG nextflow.processor.TaskRun - Unable to dump error of process 'SALMON_QUANT (trt_N061011)' -- Cause: java.nio.file.NoSuchFileException: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/b3/27c8e1eef9a76d2ba053753bb88d0a/.command.err
May-26 19:13:44.851 [Task monitor] ERROR nextflow.processor.TaskProcessor - Error executing process > 'SALMON_QUANT (trt_N061011)'

Caused by:
  Process `SALMON_QUANT (trt_N061011)` terminated with an error exit status (1)

Command executed:

  mkdir -p trt_N061011
  salmon quant --gcBias -l A -i GRCh38.salmon.index \
        -1 trt_N061011_1.fq.gz -2 trt_N061011_2.fq.gz -o trt_N061011 -p 6  -g Genome.gtf

Command exit status:
  1

Command output:
  (empty)

Work dir:
  /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/b3/27c8e1eef9a76d2ba053753bb88d0a

Tip: you can try to figure out what's wrong by changing to the process work dir and showing the script file named `.command.sh`
May-26 19:13:44.880 [Task monitor] INFO  nextflow.Session - Execution cancelled -- Finishing pending tasks before exit
May-26 19:13:44.889 [Task monitor] DEBUG nextflow.processor.TaskRun - Unable to dump error of process 'SALMON_QUANT (trt_N061011)' -- Cause: java.nio.file.NoSuchFileException: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/b3/27c8e1eef9a76d2ba053753bb88d0a/.command.err
May-26 19:13:44.889 [Task monitor] DEBUG nextflow.processor.TaskRun - Unable to dump output of process 'SALMON_QUANT (trt_N061011)' -- Cause: java.nio.file.NoSuchFileException: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/b3/27c8e1eef9a76d2ba053753bb88d0a/.command.out
May-26 19:13:44.891 [main] DEBUG nextflow.Session - Session await > all process finished
May-26 19:13:44.893 [Task monitor] DEBUG n.processor.TaskPollingMonitor - Task completed > TaskHandler[id: 4; name: SALMON_QUANT (untrt_N061011); status: COMPLETED; exit: 1; error: -; workDir: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/56/e85c6970c58ecd820fbc274593ce7f]
May-26 19:13:44.896 [Task monitor] DEBUG n.processor.TaskPollingMonitor - Task completed > TaskHandler[id: 3; name: SALMON_QUANT (untrt_N080611); status: COMPLETED; exit: 1; error: -; workDir: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/ba/4516b78775022bd715671cc3b90255]
May-26 19:13:44.901 [Task monitor] DEBUG n.processor.TaskPollingMonitor - Task completed > TaskHandler[id: 5; name: SALMON_QUANT (trt_N61311); status: COMPLETED; exit: 1; error: -; workDir: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/18/250c6b06bbaad24d9a75715210e86c]
May-26 19:13:45.017 [Task monitor] DEBUG n.processor.TaskPollingMonitor - Task completed > TaskHandler[id: 2; name: SALMON_QUANT (untrt_N052611); status: COMPLETED; exit: 1; error: -; workDir: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/18/bc10379d7cf01633e064ab8016612b]
May-26 19:13:45.115 [Task monitor] DEBUG n.processor.TaskPollingMonitor - Task completed > TaskHandler[id: 1; name: SALMON_QUANT (untrt_N61311); status: COMPLETED; exit: 1; error: -; workDir: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/b2/5fcc5adb76a8a372a84f8d466a7fd7]
May-26 19:13:45.703 [Task monitor] DEBUG n.processor.TaskPollingMonitor - Task completed > TaskHandler[id: 7; name: SALMON_QUANT (trt_N080611); status: COMPLETED; exit: 1; error: -; workDir: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/fb/7681dea42dfcdef5dbb14c9bb6c951]
May-26 19:13:45.715 [Task monitor] DEBUG n.processor.TaskPollingMonitor - Task completed > TaskHandler[id: 6; name: SALMON_QUANT (trt_N052611); status: COMPLETED; exit: 1; error: -; workDir: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/b3/3d236c746f31895d05fcbfb7156232]
May-26 19:13:45.723 [main] DEBUG nextflow.Session - Session await > all barriers passed
May-26 19:13:45.725 [main] DEBUG nextflow.processor.TaskRun - Unable to dump error of process 'SALMON_QUANT (trt_N061011)' -- Cause: java.nio.file.NoSuchFileException: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/b3/27c8e1eef9a76d2ba053753bb88d0a/.command.err
May-26 19:13:45.726 [main] DEBUG nextflow.processor.TaskRun - Unable to dump output of process 'SALMON_QUANT (trt_N061011)' -- Cause: java.nio.file.NoSuchFileException: /fidRNAseq_analysis_flow__salmon_50002023_05_26_19_13_31_621799/work/b3/27c8e1eef9a76d2ba053753bb88d0a/.command.out
May-26 19:13:45.738 [main] DEBUG nextflow.trace.WorkflowStatsObserver - Workflow completed > WorkflowStats[succeededCount=0; failedCount=8; ignoredCount=0; cachedCount=0; pendingCount=0; submittedCount=0; runningCount=0; retriesCount=0; abortedCount=0; succeedDuration=0ms; failedDuration=4m 8s; cachedDuration=0ms;loadCpus=0; loadMemory=0; peakRunning=8; peakCpus=48; peakMemory=288 GB; ]
May-26 19:13:45.738 [main] DEBUG nextflow.trace.TraceFileObserver - Flow completing -- flushing trace file
May-26 19:13:45.742 [main] DEBUG nextflow.trace.ReportObserver - Flow completing -- rendering html report
May-26 19:13:45.824 [main] DEBUG nextflow.trace.ReportObserver - Execution report summary data:
  [{"cpuUsage":null,"process":"SALMON_QUANT","mem":null,"memUsage":null,"timeUsage":{"mean":0.02,"min":0.02,"q1":0.02,"q2":0.02,"q3":0.02,"max":0.02,"minLabel":"SALMON_QUANT (trt_N061011)","maxLabel":"SALMON_QUANT (trt_N080611)","q1Label":"SALMON_QUANT (untrt_N080611)","q2Label":"SALMON_QUANT (trt_N61311)","q3Label":"SALMON_QUANT (untrt_N61311)"},"vmem":null,"reads":null,"cpu":null,"time":{"mean":5172.75,"min":4810,"q1":4889.25,"q2":5020.5,"q3":5343.75,"max":5809,"minLabel":"SALMON_QUANT (trt_N061011)","maxLabel":"SALMON_QUANT (trt_N080611)","q1Label":"SALMON_QUANT (untrt_N080611)","q2Label":"SALMON_QUANT (trt_N61311)","q3Label":"SALMON_QUANT (untrt_N61311)"},"writes":null}]
May-26 19:13:46.979 [main] DEBUG nextflow.trace.TimelineObserver - Flow completing -- rendering html timeline
May-26 19:13:47.102 [main] DEBUG nextflow.cache.CacheDB - Closing CacheDB done
May-26 19:13:47.121 [main] DEBUG nextflow.script.ScriptRunner - > Execution complete -- Goodbye