search

PacificBiosciences / FALCON

FALCON: experimental PacBio diploid assembler -- Out-of-date -- Please use a binary release: https://github.com/PacificBiosciences/FALCON_unzip/wiki/Binaries
https://github.com/PacificBiosciences/FALCON_unzip/wiki/Binaries
Other
204 stars 103 forks source link

[ERROR]Some tasks are recently_done but not satisfied: set([Node(0-rawreads/tan-runs/tan_004), Node(0-rawreads/tan-runs/tan_001)]) #674

Closed laguda-1996 closed 3 years ago

laguda-1996 commented 5 years ago

I downloaded and installed falcon via https://pb-falcon.readthedocs.io/en/latest/ Hi,I was trying to run falcon for ecoli in tutorial,and the program stopped with:

[ERROR]Task Node(0-rawreads/tan-runs/tan_004) failed with exit-code=1
[ERROR]Task Node(0-rawreads/tan-runs/tan_001) failed with exit-code=1
[ERROR]Some tasks are recently_done but not satisfied: set([Node(0-rawreads/tan-runs/tan_004), Node(0-rawreads/tan-runs/tan_001)])
[ERROR]ready: set([])
    submitted: set([Node(0-rawreads/tan-runs/tan_002), Node(0-rawreads/tan-runs/tan_003), Node(0-rawreads/tan-runs/tan_000)])
[ERROR]Noop. We cannot kill blocked threads. Hopefully, everything will die on SIGTERM.
Traceback (most recent call last):
  File "/home/dsy/miniconda2/bin/fc_run", line 11, in <module>
    load_entry_point('falcon-kit==1.2.4', 'console_scripts', 'fc_run')()
  File "/home/dsy/miniconda2/lib/python2.7/site-packages/falcon_kit/mains/run1.py", line 726, in main
    main1(argv[0], args.config, args.logger)
  File "/home/dsy/miniconda2/lib/python2.7/site-packages/falcon_kit/mains/run1.py", line 76, in main1
    input_fofn_fn=input_fofn_fn,
  File "/home/dsy/miniconda2/lib/python2.7/site-packages/falcon_kit/mains/run1.py", line 242, in run
    dist=Dist(NPROC=4, MB=4000, job_dict=config['job.step.da']),
  File "/home/dsy/miniconda2/lib/python2.7/site-packages/falcon_kit/pype.py", line 194, in gen_parallel_tasks
    wf.refreshTargets()
  File "/home/dsy/miniconda2/lib/python2.7/site-packages/pypeflow/simple_pwatcher_bridge.py", line 278, in refreshTargets
    self._refreshTargets(updateFreq, exitOnFailure)
  File "/home/dsy/miniconda2/lib/python2.7/site-packages/pypeflow/simple_pwatcher_bridge.py", line 362, in _refreshTargets
    raise Exception(msg)
Exception: Some tasks are recently_done but not satisfied: set([Node(0-rawreads/tan-runs/tan_004), Node(0-rawreads/tan-runs/tan_001)])

I looked at the stderr file in the given subfolder(/0-rawreads/build):

executable=${PYPEFLOW_JOB_START_SCRIPT}
+ executable=/home/dsy/test_e.coli/0-rawreads/build/run-P8c29bfea2edc95.bash
timeout=${PYPEFLOW_JOB_START_TIMEOUT:-60} # wait 60s by default
+ timeout=60

# Wait up to timeout seconds for the executable to become "executable",
# then exec.
#timeleft = int(timeout)
while [[ ! -x "${executable}" ]]; do
    if [[ "${timeout}" == "0" ]]; then
        echo "timed out waiting for (${executable})"
        exit 77
    fi
    echo "not executable: '${executable}', waiting ${timeout}s"
    sleep 1
    timeout=$((timeout-1))
done
+ [[ ! -x /home/dsy/test_e.coli/0-rawreads/build/run-P8c29bfea2edc95.bash ]]

/bin/bash ${executable}
+ /bin/bash /home/dsy/test_e.coli/0-rawreads/build/run-P8c29bfea2edc95.bash
+ '[' '!' -d /home/dsy/test_e.coli/0-rawreads/build ']'
+ cd /home/dsy/test_e.coli/0-rawreads/build
+ eval '/bin/bash run.sh'
++ /bin/bash run.sh
export PATH=$PATH:/bin
+ export PATH=/home/dsy/Falcon_pacbio/fc_env_181031/bin/bin:/home/dsy/miniconda2/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/home/dsy/miniconda2/bin/minimap2:/usr/bin/samtools:/bin
+ PATH=/home/dsy/Falcon_pacbio/fc_env_181031/bin/bin:/home/dsy/miniconda2/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/home/dsy/miniconda2/bin/minimap2:/usr/bin/samtools:/bin
cd /home/dsy/test_e.coli/0-rawreads/build
+ cd /home/dsy/test_e.coli/0-rawreads/build
/bin/bash task.sh
+ /bin/bash task.sh
pypeflow 2.1.1
2018-11-01 10:41:13,653 - root - DEBUG - Running "/home/dsy/miniconda2/lib/python2.7/site-packages/pypeflow/do_task.py /home/dsy/test_e.coli/0-rawreads/build/task.json"
2018-11-01 10:41:13,654 - root - DEBUG - Checking existence of '/home/dsy/test_e.coli/0-rawreads/build/task.json' with timeout=30
2018-11-01 10:41:13,654 - root - DEBUG - Loading JSON from '/home/dsy/test_e.coli/0-rawreads/build/task.json'
2018-11-01 10:41:13,654 - root - DEBUG - {u'bash_template_fn': u'template.sh',
 u'inputs': {u'config': u'../../General_config.json',
             u'input_fofn': u'../../input.fofn'},
 u'outputs': {u'db': u'raw_reads.db', u'length_cutoff': u'length_cutoff'},
 u'parameters': {u'pypeflow_mb': 4000,
                 u'pypeflow_nproc': 1,
                 u'topdir': u'../..'}}
2018-11-01 10:41:13,654 - root - WARNING - CD: '/home/dsy/test_e.coli/0-rawreads/build' <- '/home/dsy/test_e.coli/0-rawreads/build'
2018-11-01 10:41:13,654 - root - DEBUG - Checking existence of u'../../input.fofn' with timeout=30
2018-11-01 10:41:13,654 - root - DEBUG - Checking existence of u'../../General_config.json' with timeout=30
2018-11-01 10:41:13,654 - root - DEBUG - Checking existence of u'template.sh' with timeout=30
2018-11-01 10:41:13,654 - root - WARNING - CD: '/home/dsy/test_e.coli/0-rawreads/build' <- '/home/dsy/test_e.coli/0-rawreads/build'
2018-11-01 10:41:13,655 - root - INFO - $('/bin/bash user_script.sh')
hostname
+ hostname
pwd
+ pwd
date
+ date
# Substitution will be similar to snakemake "shell".
python -m falcon_kit.mains.dazzler --config-fn=../../General_config.json --db-fn=raw_reads.db  build --input-fofn-fn=../../input.fofn --length-cutoff-fn=length_cutoff
+ python -m falcon_kit.mains.dazzler --config-fn=../../General_config.json --db-fn=raw_reads.db build --input-fofn-fn=../../input.fofn --length-cutoff-fn=length_cutoff
falcon-kit 1.2.4
pypeflow 2.1.1
[INFO]Log-level: INFO
[INFO]config('../../General_config.json'):
{u'falcon_sense_greedy': False, u'pa_fasta_filter_option': u'streamed-internal-median', u'seed_coverage': u'30', u'overlap_filtering_setting': u'--max-diff 100 --max-cov 100 --min-cov 20 --bestn 10 --n-core 6', u'length_cutoff_pr': u'12000', u'input_fofn': u'input.fofn', u'pa_HPCdaligner_option': u'-v -B4 -t16 -e.70 -l1000 -s1000', u'ver': u'100', u'bestn': 12, u'pa_HPCTANmask_option': u'-l500', u'input_type': u'raw', u'pa_REPmask_code': u'0,300/0,300/0,300', u'pa_DBsplit_option': u'-x500 -s50', u'fc_ovlp_to_graph_option': u' --min-len 12000', u'genome_size': u'4652500', u'avoid_text_file_busy': True, u'pa_dazcon_option': u'-j 4 -x -l 500', u'skip_checks': False, u'ovlp_daligner_option': u'-v -e.96  -l500 -s1000 -h60', u'target': u'assembly', u'falcon_sense_skip_contained': False, u'pa_daligner_option': u'-v -e.70 -l1000 -s1000 --> -s100', u'length_cutoff': u'-1', u'pa_DBdust_option': u'', u'ovlp_HPCdaligner_option': u'-v -B4 -t32 -h60 -e.96 -l500 -s1000', u'LA4Falcon_preload': False, u'dazcon': False, u'falcon_sense_option': u'--output-multi --min-idt 0.70 --min-cov 4 --max-n-read 200 --n-core 6', u'ovlp_DBsplit_option': u'-x500 -s50'}
[INFO]our subset of config:
{'daligner_opt': u'-v -e.70 -l1000 -s1000 --> -s100 -v -B4 -t16 -e.70 -l1000 -s1000', 'genome_size': 4652500, 'TANmask_opt': u'-v -e.70 -l1000 -s1000 --> -s100 -l500', 'DBdust_opt': u'', 'seed_coverage': 30.0, 'user_length_cutoff': -1, 'fasta_filter_option': u'streamed-internal-median', 'REPmask_opt': u'-v -e.70 -l1000 -s1000 --> -s100 ', 'DBsplit_opt': u'-x500 -s50'}
[INFO]Building rdb from '../../input.fofn', to write 'raw_reads.db'
[INFO]$('bash -vex build_db.sh')
#!/bin/bash
set -vex
+ set -vex
echo "PBFALCON_ERRFILE=$PBFALCON_ERRFILE"
+ echo PBFALCON_ERRFILE=
set -o pipefail
+ set -o pipefail
rm -f raw_reads.db .raw_reads.* # in case of re-run
+ rm -f raw_reads.db '.raw_reads.*'
#fc_fasta2fasta < my.input.fofn >| fc.fofn
while read fn; do  cat  ${fn} | python -m falcon_kit.mains.fasta_filter streamed-internal-median - | fasta2DB -v raw_reads -i${fn##*/}; done < my.input.fofn
+ read fn
+ cat /home/dsy/test_e.coli/ecoli.m140913_050931_42139_c100713652400000001823152404301535_s1_p0.subreads/ecoli.1.fasta
+ python -m falcon_kit.mains.fasta_filter streamed-internal-median -
+ fasta2DB -v raw_reads -iecoli.1.fasta
falcon-kit 1.2.4
pypeflow 2.1.1
INFO:root:Counting bytes from "-"
INFO:root:        #1 count=         24,885 
Adding 'ecoli.1.fasta.fasta' ...
INFO:root:        #4 count=         56,588 
INFO:root:       #10 count=        110,822 
INFO:root:       #17 count=        219,377 
INFO:root:       #33 count=        431,653 
INFO:root:       #71 count=        834,148 
INFO:root:      #141 count=      1,634,922 
INFO:root:      #284 count=      3,234,318 
INFO:root:      #570 count=      6,422,036 
INFO:root:    #1,196 count=     12,806,779 
INFO:root:    #2,513 count=     25,548,890 
INFO:root:    #5,106 count=     51,032,525 
INFO:root:   #10,156 count=    102,004,104 
INFO:root:   #20,808 count=    203,940,368 
+ read fn
+ cat /home/dsy/test_e.coli/ecoli.m140913_050931_42139_c100713652400000001823152404301535_s1_p0.subreads/ecoli.2.fasta
+ python -m falcon_kit.mains.fasta_filter streamed-internal-median -
+ fasta2DB -v raw_reads -iecoli.2.fasta
falcon-kit 1.2.4
pypeflow 2.1.1
INFO:root:Counting bytes from "-"
INFO:root:        #1 count=          8,431 
INFO:root:        #2 count=         18,720 
Adding 'ecoli.2.fasta.fasta' ...
INFO:root:        #5 count=         41,485 
INFO:root:        #8 count=         87,632 
INFO:root:       #12 count=        169,359 
INFO:root:       #25 count=        309,915 
INFO:root:       #50 count=        608,856 
INFO:root:      #110 count=      1,164,505 
INFO:root:      #225 count=      2,245,051 
INFO:root:      #466 count=      4,411,007 
INFO:root:      #933 count=      8,729,414 
INFO:root:    #1,861 count=     17,369,636 
INFO:root:    #3,611 count=     34,641,069 
INFO:root:    #7,153 count=     69,184,371 
INFO:root:   #14,295 count=    138,259,252 
INFO:root:   #28,404 count=    276,393,751 
+ read fn
+ cat /home/dsy/test_e.coli/ecoli.m140913_050931_42139_c100713652400000001823152404301535_s1_p0.subreads/ecoli.3.fasta
+ python -m falcon_kit.mains.fasta_filter streamed-internal-median -
+ fasta2DB -v raw_reads -iecoli.3.fasta
falcon-kit 1.2.4
pypeflow 2.1.1
INFO:root:Counting bytes from "-"
INFO:root:        #1 count=          2,478 
INFO:root:        #2 count=         19,929 
Adding 'ecoli.3.fasta.fasta' ...
INFO:root:        #4 count=         48,600 
INFO:root:        #8 count=         90,141 
INFO:root:       #15 count=        161,374 
INFO:root:       #26 count=        309,296 
INFO:root:       #47 count=        590,609 
INFO:root:      #102 count=      1,153,567 
INFO:root:      #215 count=      2,277,181 
INFO:root:      #443 count=      4,525,924 
INFO:root:      #892 count=      8,994,698 
INFO:root:    #1,802 count=     17,930,324 
INFO:root:    #3,610 count=     35,804,922 
INFO:root:    #7,263 count=     71,551,998 
INFO:root:   #14,522 count=    143,047,521 
INFO:root:   #28,897 count=    286,008,531 
+ read fn
#cat fc.fofn | xargs rm -f
DBdust  raw_reads
+ DBdust raw_reads

DBsplit -f -x500 -s50 raw_reads
+ DBsplit -f -x500 -s50 raw_reads
#LB=$(cat raw_reads.db | LD_LIBRARY_PATH= awk '$1 == "blocks" {print $3}')
#echo -n $LB >| db_block_count

CUTOFF=$(python2.7 -m falcon_kit.mains.calc_cutoff --coverage 30.0 4652500 <(DBstats -b1 raw_reads))
++ python2.7 -m falcon_kit.mains.calc_cutoff --coverage 30.0 4652500 /dev/fd/63
+++ DBstats -b1 raw_reads
falcon-kit 1.2.4
pypeflow 2.1.1
+ CUTOFF=22484
echo -n $CUTOFF >| length_cutoff
+ echo -n 22484
# TODO: Verify that db exists.
#ln -sf length_cutoff length_cutoff

date
+ date
2018-11-01 10:41:41,660 - root - DEBUG - Call '/bin/bash user_script.sh' returned 0.
2018-11-01 10:41:41,660 - root - WARNING - CD: '/home/dsy/test_e.coli/0-rawreads/build' -> '/home/dsy/test_e.coli/0-rawreads/build'
2018-11-01 10:41:41,660 - root - DEBUG - Checking existence of u'length_cutoff' with timeout=30
2018-11-01 10:41:41,660 - root - DEBUG - Checking existence of u'raw_reads.db' with timeout=30
2018-11-01 10:41:41,660 - root - WARNING - CD: '/home/dsy/test_e.coli/0-rawreads/build' -> '/home/dsy/test_e.coli/0-rawreads/build'

real    0m28.098s
user    0m29.034s
sys 0m2.714s
touch /home/dsy/test_e.coli/0-rawreads/build/run.sh.done
+ touch /home/dsy/test_e.coli/0-rawreads/build/run.sh.done
+ finish
+ echo 'finish code: 0'

and my .cfg file are as following :

[General]
input_fofn = input.fofn
input_type = raw
length_cutoff = -1
genome_size = 4652500
seed_coverage = 30
length_cutoff_pr = 12000

# pa_daligner_option =   -v -e.70 -l1000 -s1000 --> -s100
pa_daligner_option =   -v -e.70 -l1000 -s1000 
ovlp_daligner_option = -v -e.96  -l500 -s1000 -h60

# pa_HPCdaligner_option = -v -B4 -M8
pa_HPCdaligner_option =  -v -B4 -t16 -e.70 -l1000 -s1000
# ovlp_HPCdaligner_option =  -v -B4 -M8
ovlp_HPCdaligner_option = -v -B4 -t32 -h60 -e.96 -l500 -s1000

pa_DBsplit_option = -x500 -s50
ovlp_DBsplit_option = -x500 -s50

falcon_sense_option = --output-multi --min-idt 0.70 --min-cov 4 --max-n-read 200 --n-core 6
overlap_filtering_setting = --max-diff 100 --max-cov 100 --min-cov 20 --bestn 10 --n-core 6

[job.defaults]
job_type = local
njobs = 6
pwatcher_type = blocking
submit = /bin/bash -c "${JOB_SCRIPT}" > "${JOB_STDOUT}" 2> "${JOB_STDERR}"
#JOB_QUEUE = myqueue
#MB = 4000
NPROC = 4

default_concurrent_jobs = 30
pa_concurrent_jobs = 30
ovlp_concurrent_jobs = 30
cns_concurrent_jobs = 30

[job.step.da]
NPROC = 4

[job.step.la]
NPROC = 4

[job.step.pda]
NPROC = 4

[job.step.pla]
NPROC = 4

[job.step.cns]
NPROC = 4 
MB = 2000

[job.step.asm]
NPROC = 4

I have seen some issues on github and tried different parameter settings based on other people's answers, but all of them are reported incorrectly.Although I saw the stderr file, I could not understand it.Can you give me some advice?thank you very much.

gconcepcion commented 5 years ago

It looks like there is possibly just misconfigured (or not even configured) tan repeat masking parameters in your fc_run.cfg file.

Is there a reason you needed to install via the readthedocs tarball method?

We have simplified installation as well as added new features to the bioconda version of pb-assembly.

See this link for details: https://github.com/PacificBiosciences/pb-assembly

pb-cdunn commented 5 years ago

Look for a stderr file under 0-rawreads/tan-runs/tan_004.

JN-0 commented 4 years ago

Hi guys.

I am getting a similar error at top level but my stderr actually looks different.

I installed FALCON through conda and I used fc_run D01_v01.cfg &> fc_run.log & as my test run.

My directory is here . ├── 0-rawreads │   └── build │   ├── build_db.sh │   ├── my.input.fofn │   ├── pwatcher.dir -> /gpfs1/scratch/30days/uqswan29/fc/mypwatcher/jobs/Pc9f2e42080f9f1 │   ├── raw_reads.db │   ├── run.sh │   ├── task.json │   ├── task.sh │   ├── template.sh │   ├── top.txt │   └── user_script.sh ├── 1-preads_ovl ├── 2-asm-falcon ├── all.log ├── config.json ├── D01_v01.cfg ├── D01_v01.cfg.original ├── fc_run_arabidopsis.cfg ├── fc_runhuman.cfg ├── fc_run_human.cfg ├── fc_run.log ├── fc_run_plant.cfg ├── fc_unzip.cfg ├── Generalconfig.json ├── input.fofn ├── mypwatcher │   ├── exits │   │   └── exit-Pc9f2e42080f9f1 │   ├── heartbeats │   ├── jobs │   │   └── Pc9f2e42080f9f1 │   │   ├── stderr │   │   └── stdout │   └── wrappers │   └── run-Pc9f2e42080f9f1.bash ├── nohup.out └── .pbs

The stderr file is following 

+ python3 -m pwatcher.mains.fs_heartbeat --directory=/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build --heartbeat-file=/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/heartbeats/heartbeat-Pc9f2e42080f9f1 --exit-file=/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/exits/exit-Pc9f2e42080f9f1 --rate=10.0 /bin/bash run.sh
export PATH=$PATH:/bin
+ export PATH=/home/uqswan29/.conda/envs/conda_PacBio/bin:/sw/RCC/Anaconda/2019.07/condabin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/opt/ganglia/bin:/opt/ganglia/sbin:/usr/java/latest/bin:/opt/pbs/bin:/opt/rocks/bin:/opt/rocks/sbin:/home/uqswan29/.local/bin:/home/uqswan29/bin:/bin
+ PATH=/home/uqswan29/.conda/envs/conda_PacBio/bin:/sw/RCC/Anaconda/2019.07/condabin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/opt/ganglia/bin:/opt/ganglia/sbin:/usr/java/latest/bin:/opt/pbs/bin:/opt/rocks/bin:/opt/rocks/sbin:/home/uqswan29/.local/bin:/home/uqswan29/bin:/bin
cd /gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build
+ cd /gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build
/bin/bash task.sh
+ /bin/bash task.sh
pypeflow 2.3.0
2020-04-13 00:58:34,828 - root - DEBUG - Running "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pypeflow/do_task.py /gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build/task.json"
2020-04-13 00:58:34,829 - root - DEBUG - Checking existence of '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build/task.json' with timeout=30
2020-04-13 00:58:34,829 - root - DEBUG - Loading JSON from '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build/task.json'
2020-04-13 00:58:34,830 - root - DEBUG - {'bash_template_fn': 'template.sh',
 'inputs': {'config': '../../General_config.json',
            'input_fofn': '../../input.fofn'},
 'outputs': {'db': 'raw_reads.db', 'length_cutoff': 'length_cutoff'},
 'parameters': {'pypeflow_mb': 4000, 'pypeflow_nproc': 1, 'topdir': '../..'}}
2020-04-13 00:58:34,830 - root - INFO - CD: '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build' <- '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build'
2020-04-13 00:58:34,830 - root - DEBUG - Checking existence of '../../General_config.json' with timeout=30
2020-04-13 00:58:34,830 - root - DEBUG - Checking existence of '../../input.fofn' with timeout=30
2020-04-13 00:58:34,830 - root - DEBUG - Checking existence of 'template.sh' with timeout=30
2020-04-13 00:58:34,830 - root - INFO - CD: '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build' <- '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build'
2020-04-13 00:58:34,832 - root - INFO - $('/bin/bash user_script.sh')
hostname
+ hostname
pwd
+ pwd
date
+ date
# Substitution will be similar to snakemake "shell".
python3 -m falcon_kit.mains.dazzler --config-fn=../../General_config.json --db-fn=raw_reads.db  build --input-fofn-fn=../../input.fofn --length-cutoff-fn=length_cutoff
+ python3 -m falcon_kit.mains.dazzler --config-fn=../../General_config.json --db-fn=raw_reads.db build --input-fofn-fn=../../input.fofn --length-cutoff-fn=length_cutoff
falcon-kit 1.8.1 (pip thinks "falcon-kit 1.8.1")
pypeflow 2.3.0
[INFO]Log-level: INFO
[INFO]config('../../General_config.json'):
{'LA4Falcon_preload': False, 'avoid_text_file_busy': True, 'bestn': 12, 'dazcon': False, 'falcon_sense_greedy': False, 'falcon_sense_option': '--output-multi --min-idt 0.70 --min-cov 2 --max-n-read 200 --n-core 8', 'falcon_sense_skip_contained': True, 'fc_ovlp_to_graph_option': ' --min-len 5000', 'genome_size': '3000000000', 'input_fofn': 'input.fofn', 'input_type': 'raw', 'length_cutoff': '-1', 'length_cutoff_pr': '5000', 'overlap_filtering_setting': '--max-diff 100 --max-cov 100 --min-cov 2 --n-core 12', 'ovlp_DBdust_option': '', 'ovlp_DBsplit_option': '-s400', 'ovlp_HPCdaligner_option': '-v -B4 -M32 -h60 -e.96 -l500 -s1000', 'ovlp_daligner_option': '-e.96 -l500 -s1000 -h60', 'pa_DBdust_option': '', 'pa_DBsplit_option': '-a -x500 -s400', 'pa_HPCTANmask_option': '-l500', 'pa_HPCdaligner_option': '-v -B4 -M32 -e.70 -l1000 -s1000', 'pa_REPmask_code': '0,300/0,300/0,300', 'pa_daligner_option': '-e.70 -l1000 -s1000', 'pa_dazcon_option': '-j 4 -x -l 500', 'pa_fasta_filter_option': 'streamed-internal-median', 'pa_subsample_coverage': 0, 'pa_subsample_random_seed': 12345, 'pa_subsample_strategy': 'random', 'seed_coverage': '30', 'skip_checks': False, 'target': 'assembly', 'ver': '100'}
[INFO]our subset of config:
{'genome_size': 3000000000, 'seed_coverage': 30.0, 'DBdust_opt': '', 'DBsplit_opt': '-a -x500 -s400', 'daligner_opt': '-e.70 -l1000 -s1000 -v -B4 -M32 -e.70 -l1000 -s1000', 'TANmask_opt': '-e.70 -l1000 -s1000 -l500', 'REPmask_opt': '-e.70 -l1000 -s1000 ', 'user_length_cutoff': -1, 'fasta_filter_option': 'streamed-internal-median', 'subsample_coverage': 0, 'subsample_random_seed': 12345, 'subsample_strategy': 'random'}
[INFO]Building rdb from '../../input.fofn', to write 'raw_reads.db'
[INFO]$('bash -vex build_db.sh')
module () {  eval $($LMOD_CMD bash "$@") && eval $(${LMOD_SETTARG_CMD:-:} -s sh)
}
ml () {  eval $($LMOD_DIR/ml_cmd "$@")
}
# -*- shell-script -*-
#
########################################################################
# Start Lmod BASHENV
########################################################################

# Remember the XTRACE and VERBOSE states so that they are restored
# at the end of this script.
[[ ${-/x} != $- ]] && XTRACE_STATE="-x"  || XTRACE_STATE="+x"
+ [[ hvB != hvxB ]]
+ XTRACE_STATE=-x
[[ ${-/v} != $- ]] && VERBOSE_STATE="-v" || VERBOSE_STATE="+v"
+ [[ hxB != hvxB ]]
+ VERBOSE_STATE=-v
set +xv     # Turn off tracing for now.
+ set +xv
unset XTRACE_STATE  VERBOSE_STATE
+ unset XTRACE_STATE VERBOSE_STATE

########################################################################
# End Lmod BASHENV
########################################################################
#
# Local Variables:
# mode: shell-script
# indent-tabs-mode: nil
# End:
#!/bin/bash
set -vex
+ set -vex
echo "PBFALCON_ERRFILE=$PBFALCON_ERRFILE"
+ echo PBFALCON_ERRFILE=
set -o pipefail
+ set -o pipefail
rm -f raw_reads.db raw_reads.dam .raw_reads.* # in case of re-run
+ rm -f raw_reads.db raw_reads.dam '.raw_reads.*'
#fc_fasta2fasta < my.input.fofn >| fc.fofn
zmw_whitelist_option=""
+ zmw_whitelist_option=
use_subsampling=0
+ use_subsampling=0
if [[ $use_subsampling -eq 1 ]]; then
    while read fn; do  zcat  ${fn} | python3 -m falcon_kit.mains.zmw_collect; done < my.input.fofn > zmw.all.tsv
    cat zmw.all.tsv | python3 -m falcon_kit.mains.zmw_subsample --coverage "0" --random-seed "12345" --strategy "random" --genome-size "3000000000" zmw.whitelist.json
    zmw_whitelist_option="--zmw-whitelist-fn zmw.whitelist.json"
fi
+ [[ 0 -eq 1 ]]
while read fn; do  zcat  ${fn} | python3 -m falcon_kit.mains.fasta_filter ${zmw_whitelist_option} streamed-internal-median - | fasta2DB -v raw_reads -i${fn##*/}; done < my.input.fofn
+ read fn
+ zcat /gpfs1/scratch/30days/uqswan29/XNUCL_20191212_S64018_PL100147073-1_D01.subreads.fastq.gz
+ python3 -m falcon_kit.mains.fasta_filter streamed-internal-median -
+ fasta2DB -v raw_reads -iXNUCL_20191212_S64018_PL100147073-1_D01.subreads.fastq.gz
falcon-kit 1.8.1 (pip thinks "falcon-kit 1.8.1")
pypeflow 2.3.0
INFO:root:Counting bytes from "None"

gzip: Standard input is empty, terminating!
stdout: Broken pipe
build_db.sh: line 14: 32331 Exit 1                  zcat ${fn}
     32332 Killed                  | python3 -m falcon_kit.mains.fasta_filter ${zmw_whitelist_option} streamed-internal-median -
     32333 Done                    | fasta2DB -v raw_reads -i${fn##*/}
[WARNING]Call 'bash -vex build_db.sh' returned 35072.
Traceback (most recent call last):
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/falcon_kit/mains/dazzler.py", line 1532, in <module>
    main()
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/falcon_kit/mains/dazzler.py", line 1528, in main
    args.func(args)
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/falcon_kit/mains/dazzler.py", line 1050, in cmd_build
    build_db(ours, args.input_fofn_fn, args.db_fn, args.length_cutoff_fn)
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/falcon_kit/mains/dazzler.py", line 169, in build_db
    io.syscall('bash -vex {}'.format(script_fn))
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pypeflow/io.py", line 27, in syscall
    raise Exception(msg)
Exception: Call 'bash -vex build_db.sh' returned 35072.
2020-04-13 01:00:21,247 - root - WARNING - Call '/bin/bash user_script.sh' returned 256.
2020-04-13 01:00:21,247 - root - INFO - CD: '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build' -> '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build'
2020-04-13 01:00:21,247 - root - INFO - CD: '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build' -> '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build'
2020-04-13 01:00:21,248 - root - CRITICAL - Error in /home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pypeflow/do_task.py with args="{'json_fn': '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build/task.json',\n 'timeout': 30,\n 'tmpdir': None}"
Traceback (most recent call last):
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pypeflow/do_task.py", line 280, in <module>
    main()
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pypeflow/do_task.py", line 272, in main
    run(**vars(parsed_args))
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pypeflow/do_task.py", line 266, in run
    run_cfg_in_tmpdir(cfg, tmpdir, '.')
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pypeflow/do_task.py", line 241, in run_cfg_in_tmpdir
    run_bash(bash_template, myinputs, myoutputs, parameters)
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pypeflow/do_task.py", line 200, in run_bash
    util.system(cmd)
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pypeflow/io.py", line 27, in syscall
    raise Exception(msg)
Exception: Call '/bin/bash user_script.sh' returned 256.
+++ pwd
++ echo 'FAILURE. Running top in /gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build (If you see -terminal database is inaccessible- you are using the python bin-wrapper, so you will not get diagnostic info. No big deal. This process is crashing anyway.)'
++ rm -f top.txt
++ which python
++ which top
++ env -u LD_LIBRARY_PATH top -b -n 1
++ env -u LD_LIBRARY_PATH top -b -n 1
++ pstree -apl

real    1m46.859s
user    1m52.798s
sys 0m22.293s
Namespace(command=['/bin/bash', 'run.sh'], directory='/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build', exit_file='/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/exits/exit-Pc9f2e42080f9f1', heartbeat_file='/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/heartbeats/heartbeat-Pc9f2e42080f9f1', rate=10.0)

cwd:'/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build'
hostname=flashlite2.local
heartbeat_fn='/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/heartbeats/heartbeat-Pc9f2e42080f9f1'
exit_fn='/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/exits/exit-Pc9f2e42080f9f1'
sleep_s=10.0
before setpgid: pid=32316 pgid=32304
 after setpgid: pid=32316 pgid=32316
In cwd: /gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build, Blocking call: '/bin/bash run.sh'
 returned: 256

all.log is here

2020-04-12 14:58:34,349 - fc_run:549 - INFO - Setup logging from file "None".
2020-04-12 14:58:34,349 - root:41 - INFO - $ lfs setstripe -c 12 /gpfs1/scratch/30days/uqswan29/fc >
2020-04-12 14:58:34,353 - falcon_kit.util.system:52 - INFO - Apparently '/gpfs1/scratch/30days/uqswan29/fc' is not in lustre filesystem, which is fine.
2020-04-12 14:58:34,353 - fc_run:50 - INFO - fc_run started with configuration D01_v01.cfg
2020-04-12 14:58:34,354 - fc_run:55 - INFO - cfg=
{
  "General": {
    "LA4Falcon_preload": false,
    "avoid_text_file_busy": true,
    "bestn": 12,
    "dazcon": false,
    "falcon_sense_greedy": false,
    "falcon_sense_option": "--output-multi --min-idt 0.70 --min-cov 2 --max-n-read 200 --n-core 8",
    "falcon_sense_skip_contained": true,
    "fc_ovlp_to_graph_option": " --min-len 5000",
    "genome_size": "3000000000",
    "input_fofn": "input.fofn",
    "input_type": "raw",
    "length_cutoff": "-1",
    "length_cutoff_pr": "5000",
    "overlap_filtering_setting": "--max-diff 100 --max-cov 100 --min-cov 2 --n-core 12",
    "ovlp_DBdust_option": "",
    "ovlp_DBsplit_option": "-s400",
    "ovlp_HPCdaligner_option": "-v -B4 -M32 -h60 -e.96 -l500 -s1000",
    "ovlp_daligner_option": "-e.96 -l500 -s1000 -h60",
    "pa_DBdust_option": "",
    "pa_DBsplit_option": "-a -x500 -s400",
    "pa_HPCTANmask_option": "-l500",
    "pa_HPCdaligner_option": "-v -B4 -M32 -e.70 -l1000 -s1000",
    "pa_REPmask_code": "0,300/0,300/0,300",
    "pa_daligner_option": "-e.70 -l1000 -s1000",
    "pa_dazcon_option": "-j 4 -x -l 500",
    "pa_fasta_filter_option": "streamed-internal-median",
    "pa_subsample_coverage": 0,
    "pa_subsample_random_seed": 12345,
    "pa_subsample_strategy": "random",
    "seed_coverage": "30",
    "skip_checks": false,
    "target": "assembly"
  },
  "job.defaults": {
    "job_type": "local",
    "njobs": "32",
    "pwatcher_type": "fs_based",
    "stop_all_jobs_on_failure": "False",
    "use_tmpdir": false
  },
  "job.step.asm": {},
  "job.step.cns": {
    "njobs": "8"
  },
  "job.step.da": {},
  "job.step.dust": {},
  "job.step.la": {},
  "job.step.pda": {},
  "job.step.pla": {}
}
2020-04-12 14:58:34,355 - pypeflow.simple_pwatcher_bridge:738 - INFO - In simple_pwatcher_bridge, pwatcher_impl=<module 'pwatcher.fs_based' from '/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pwatcher/fs_based.py'>
2020-04-12 14:58:34,360 - pypeflow.simple_pwatcher_bridge:749 - INFO - job_type='local', (default)job_defaults={'job_type': 'local', 'stop_all_jobs_on_failure': 'False', 'njobs': '32', 'pwatcher_type': 'fs_based', 'use_tmpdir': False}, use_tmpdir=False, squash=False, job_name_style=0
2020-04-12 14:58:34,360 - pypeflow.simple_pwatcher_bridge:377 - INFO - Setting max_jobs to 32; was None
2020-04-12 14:58:34,361 - root:23 - DEBUG - 'Serializing 9 records'
2020-04-12 14:58:34,361 - root:23 - DEBUG - '  Serialized to 0.0MB as json'
2020-04-12 14:58:34,365 - root:23 - DEBUG - "  Opened for write: './config.json'"
2020-04-12 14:58:34,365 - root:23 - DEBUG - "Deserializing from '/gpfs1/scratch/30days/uqswan29/fc/config.json'"
2020-04-12 14:58:34,368 - root:23 - DEBUG - "  Opened for read: '/gpfs1/scratch/30days/uqswan29/fc/config.json'"
2020-04-12 14:58:34,368 - root:23 - DEBUG - '  Read 0.0MB as json'
2020-04-12 14:58:34,368 - root:23 - DEBUG - '  Deserialized 9 records'
2020-04-12 14:58:34,368 - root:23 - DEBUG - 'Serializing 33 records'
2020-04-12 14:58:34,369 - root:23 - DEBUG - '  Serialized to 0.0MB as json'
2020-04-12 14:58:34,378 - root:23 - DEBUG - "  Opened for write: '/gpfs1/scratch/30days/uqswan29/fc/General_config.json'"
2020-04-12 14:58:34,378 - falcon_kit.util.system:95 - DEBUG - mkdir -p '0-rawreads'
2020-04-12 14:58:34,394 - falcon_kit.util.system:95 - DEBUG - mkdir -p '1-preads_ovl'
2020-04-12 14:58:34,396 - falcon_kit.util.system:95 - DEBUG - mkdir -p '2-asm-falcon'
2020-04-12 14:58:34,396 - pypeflow.tasks:45 - DEBUG - gen_task(python3 -m falcon_kit.mains.dazzler --config-fn={input.config} --db-fn={output.db}  build --input-fofn-fn={input.input_fofn} --length-cutoff-fn={output.length_cutoff}
# TODO: Verify that db exists.
#ln -sf {output.length_cutoff} length_cutoff

    inputs={'config': 'General_config.json', 'input_fofn': 'input.fofn'},
    outputs={'length_cutoff': '0-rawreads/build/length_cutoff', 'db': '0-rawreads/build/raw_reads.db'})
2020-04-12 14:58:34,397 - pypeflow.tasks:50 - DEBUG -  parameters={'pypeflow_mb': 4000, 'pypeflow_nproc': 1, 'topdir': '../..'}
2020-04-12 14:58:34,397 - pypeflow.tasks:52 - DEBUG -  dist.job_dict={'MB': 4000, 'NPROC': 1}
2020-04-12 14:58:34,397 - pypeflow.simple_pwatcher_bridge:634 - DEBUG - New PypeTask(wdir=None,
    inputs={'config': 'General_config.json', 'input_fofn': 'input.fofn'},
    outputs={'length_cutoff': '0-rawreads/build/length_cutoff', 'db': '0-rawreads/build/raw_reads.db'})
2020-04-12 14:58:34,398 - pypeflow.simple_pwatcher_bridge:713 - DEBUG - Created PypeTask('0-rawreads/build', '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build', "{'db': '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build/raw_reads.db',\n 'length_cutoff': '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build/length_cutoff'}", "{'config': '/gpfs1/scratch/30days/uqswan29/fc/General_config.json',\n 'input_fofn': '/gpfs1/scratch/30days/uqswan29/fc/input.fofn'}")
2020-04-12 14:58:34,398 - pypeflow.simple_pwatcher_bridge:656 - DEBUG - Added PRODUCERS['0-rawreads/build'] = PypeTask('0-rawreads/build', '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build', "{'db': '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build/raw_reads.db',\n 'length_cutoff': '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build/length_cutoff'}", "{'config': '/gpfs1/scratch/30days/uqswan29/fc/General_config.json',\n 'input_fofn': '/gpfs1/scratch/30days/uqswan29/fc/input.fofn'}")
2020-04-12 14:58:34,398 - pypeflow.simple_pwatcher_bridge:562 - DEBUG - No producer PypeTask for basedir '.' from path '/gpfs1/scratch/30days/uqswan29/fc/General_config.json' -- Pure input?
2020-04-12 14:58:34,398 - pypeflow.simple_pwatcher_bridge:562 - DEBUG - No producer PypeTask for basedir '.' from path '/gpfs1/scratch/30days/uqswan29/fc/input.fofn' -- Pure input?
2020-04-12 14:58:34,398 - pypeflow.simple_pwatcher_bridge:660 - DEBUG - Built PypeTask('0-rawreads/build', '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build', "{'db': PLF('raw_reads.db', '0-rawreads/build'),\n 'length_cutoff': PLF('length_cutoff', '0-rawreads/build')}", "{'config': PLF('General_config.json', None),\n 'input_fofn': PLF('input.fofn', None)}")
2020-04-12 14:58:34,398 - pypeflow.simple_pwatcher_bridge:260 - DEBUG - New Node(0-rawreads/build) needs set()
2020-04-12 14:58:34,398 - pypeflow.tasks:45 - DEBUG - gen_task(python3 -m falcon_kit.mains.dazzler --config={input.config} --db={input.db}  tan-split --split={output.split} --bash-template={output.bash_template}

    inputs={'config': 'General_config.json', 'db': '0-rawreads/build/raw_reads.db'},
    outputs={'split': '0-rawreads/tan-split/tan-uows.json', 'bash_template': '0-rawreads/tan-split/bash_template.sh'})
2020-04-12 14:58:34,398 - pypeflow.tasks:50 - DEBUG -  parameters={'pypeflow_mb': 4000, 'pypeflow_nproc': 1, 'topdir': '../..'}
2020-04-12 14:58:34,399 - pypeflow.tasks:52 - DEBUG -  dist.job_dict={'MB': 4000, 'NPROC': 1}
2020-04-12 14:58:34,399 - pypeflow.simple_pwatcher_bridge:634 - DEBUG - New PypeTask(wdir=None,
    inputs={'config': 'General_config.json', 'db': '0-rawreads/build/raw_reads.db'},
    outputs={'split': '0-rawreads/tan-split/tan-uows.json', 'bash_template': '0-rawreads/tan-split/bash_template.sh'})
2020-04-12 14:58:34,399 - pypeflow.simple_pwatcher_bridge:713 - DEBUG - Created PypeTask('0-rawreads/tan-split', '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/tan-split', "{'bash_template': '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/tan-split/bash_template.sh',\n 'split': '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/tan-split/tan-uows.json'}", "{'config': '/gpfs1/scratch/30days/uqswan29/fc/General_config.json',\n 'db': '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build/raw_reads.db'}")
2020-04-12 14:58:34,399 - pypeflow.simple_pwatcher_bridge:656 - DEBUG - Added PRODUCERS['0-rawreads/tan-split'] = PypeTask('0-rawreads/tan-split', '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/tan-split', "{'bash_template': '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/tan-split/bash_template.sh',\n 'split': '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/tan-split/tan-uows.json'}", "{'config': '/gpfs1/scratch/30days/uqswan29/fc/General_config.json',\n 'db': '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build/raw_reads.db'}")
2020-04-12 14:58:34,399 - pypeflow.simple_pwatcher_bridge:562 - DEBUG - No producer PypeTask for basedir '.' from path '/gpfs1/scratch/30days/uqswan29/fc/General_config.json' -- Pure input?
2020-04-12 14:58:34,400 - pypeflow.simple_pwatcher_bridge:660 - DEBUG - Built PypeTask('0-rawreads/tan-split', '/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/tan-split', "{'bash_template': PLF('bash_template.sh', '0-rawreads/tan-split'),\n 'split': PLF('tan-uows.json', '0-rawreads/tan-split')}", "{'config': PLF('General_config.json', None),\n 'db': PLF('raw_reads.db', '0-rawreads/build')}")
2020-04-12 14:58:34,400 - pypeflow.simple_pwatcher_bridge:260 - DEBUG - New Node(0-rawreads/tan-split) needs {Node(0-rawreads/build)}
2020-04-12 14:58:34,400 - pypeflow.simple_pwatcher_bridge:305 - INFO - Num unsatisfied: 2, graph: 2
2020-04-12 14:58:34,400 - pypeflow.simple_pwatcher_bridge:315 - INFO - About to submit: Node(0-rawreads/build)
2020-04-12 14:58:34,400 - pypeflow.simple_pwatcher_bridge:109 - DEBUG - enque nodes:
{Node(0-rawreads/build)}
2020-04-12 14:58:34,401 - root:15 - DEBUG - mkdir -p "/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build"
2020-04-12 14:58:34,406 - pypeflow.simple_pwatcher_bridge:132 - DEBUG - In rundir='/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build', job_dict={'job_type': 'local', 'stop_all_jobs_on_failure': 'False', 'njobs': '32', 'pwatcher_type': 'fs_based', 'use_tmpdir': False, 'NPROC': 1, 'MB': 4000}
2020-04-12 14:58:34,406 - pwatcher.fs_based:663 - DEBUG - run(jobids=<1>, job_type=local, job_defaults_dict={'job_type': 'local', 'stop_all_jobs_on_failure': 'False', 'njobs': '32', 'pwatcher_type': 'fs_based', 'use_tmpdir': False})
2020-04-12 14:58:34,406 - pwatcher.fs_based:447 - DEBUG - jobs:
{'Pc9f2e42080f9f1': Job(jobid='Pc9f2e42080f9f1', cmd='/bin/bash run.sh', rundir='/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build', options={'job_type': 'local', 'stop_all_jobs_on_failure': 'False', 'njobs': '32', 'pwatcher_type': 'fs_based', 'use_tmpdir': False, 'NPROC': 1, 'MB': 4000})}
2020-04-12 14:58:34,407 - pwatcher.fs_based:213 - DEBUG - Wrapped "python3 -m pwatcher.mains.fs_heartbeat --directory=/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build --heartbeat-file=/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/heartbeats/heartbeat-Pc9f2e42080f9f1 --exit-file=/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/exits/exit-Pc9f2e42080f9f1 --rate=10.0 /bin/bash run.sh || echo 99 >| /gpfs1/scratch/30days/uqswan29/fc/mypwatcher/exits/exit-Pc9f2e42080f9f1"
2020-04-12 14:58:34,407 - pwatcher.fs_based:219 - DEBUG - Writing wrapper "/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/wrappers/run-Pc9f2e42080f9f1.bash"
2020-04-12 14:58:34,407 - pwatcher.fs_based:457 - INFO -  starting job Job(jobid='Pc9f2e42080f9f1', cmd='/bin/bash run.sh', rundir='/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build', options={'job_type': 'local', 'stop_all_jobs_on_failure': 'False', 'njobs': '32', 'pwatcher_type': 'fs_based', 'use_tmpdir': False, 'NPROC': 1, 'MB': 4000}) w/ job_type=LOCAL
2020-04-12 14:58:34,408 - pwatcher.fs_based:61 - DEBUG - CD: '/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/jobs/Pc9f2e42080f9f1' <- '/gpfs1/scratch/30days/uqswan29/fc'
2020-04-12 14:58:34,414 - pwatcher.fs_based:233 - INFO - dir: '/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/jobs/Pc9f2e42080f9f1'
CALL:
 '/bin/bash /gpfs1/scratch/30days/uqswan29/fc/mypwatcher/wrappers/run-Pc9f2e42080f9f1.bash 1>|stdout 2>|stderr & '
2020-04-12 14:58:34,416 - pwatcher.fs_based:236 - INFO - pid=32304 pgid=32304 sub-pid=32314
2020-04-12 14:58:34,416 - pwatcher.fs_based:66 - DEBUG - CD: '/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/jobs/Pc9f2e42080f9f1' -> '/gpfs1/scratch/30days/uqswan29/fc'
2020-04-12 14:58:34,416 - pwatcher.fs_based:122 - INFO - Submitted backgroundjob=MetaJobLocal(MetaJob(job=Job(jobid='Pc9f2e42080f9f1', cmd='/bin/bash run.sh', rundir='/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build', options={'job_type': 'local', 'stop_all_jobs_on_failure': 'False', 'njobs': '32', 'pwatcher_type': 'fs_based', 'use_tmpdir': False, 'NPROC': 1, 'MB': 4000}), lang_exe='/bin/bash'))
2020-04-12 14:58:34,417 - pypeflow.simple_pwatcher_bridge:153 - DEBUG - Result of watcher.run()={'submitted': ['Pc9f2e42080f9f1']}
2020-04-12 14:58:34,417 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:34,417 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:34,417 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:34,417 - pypeflow.simple_pwatcher_bridge:335 - INFO - (slept for another 0.0s -- another 1 loop iterations)
2020-04-12 14:58:34,517 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:34,517 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:34,517 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:34,718 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:34,718 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:34,718 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:34,718 - pypeflow.simple_pwatcher_bridge:335 - INFO - (slept for another 0.30000000000000004s -- another 2 loop iterations)
2020-04-12 14:58:35,018 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:35,019 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:35,019 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:35,419 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:35,419 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:35,419 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:35,920 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:35,920 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:35,920 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:35,920 - pypeflow.simple_pwatcher_bridge:335 - INFO - (slept for another 1.2000000000000002s -- another 3 loop iterations)
2020-04-12 14:58:36,521 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:36,521 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:36,521 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:37,222 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:37,222 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:37,223 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:38,024 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:38,024 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:38,024 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:38,925 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:38,941 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:38,941 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:38,941 - pypeflow.simple_pwatcher_bridge:335 - INFO - (slept for another 2.9999999999999996s -- another 4 loop iterations)
2020-04-12 14:58:39,943 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:39,943 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:39,943 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:41,044 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:41,044 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:41,044 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:42,246 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:42,246 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:42,246 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:43,547 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:43,548 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:43,548 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:44,949 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:44,949 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:44,950 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:44,950 - pypeflow.simple_pwatcher_bridge:335 - INFO - (slept for another 6.0s -- another 5 loop iterations)
2020-04-12 14:58:46,451 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:46,451 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:46,452 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:48,053 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:48,053 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:48,054 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:49,755 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:49,756 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:49,756 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:51,558 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:51,558 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:51,558 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:53,460 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:53,460 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:53,460 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:55,462 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:55,463 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:55,463 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:55,463 - pypeflow.simple_pwatcher_bridge:335 - INFO - (slept for another 10.500000000000002s -- another 6 loop iterations)
2020-04-12 14:58:57,565 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:57,565 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:57,565 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:58:59,768 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:58:59,768 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:58:59,768 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:02,070 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:02,071 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:02,071 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:04,473 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:04,473 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:04,473 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:06,976 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:06,976 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:06,976 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:09,579 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:09,579 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:09,579 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:12,282 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:12,282 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:12,283 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:12,283 - pypeflow.simple_pwatcher_bridge:335 - INFO - (slept for another 16.800000000000004s -- another 7 loop iterations)
2020-04-12 14:59:15,086 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:15,113 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:15,113 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:18,016 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:18,016 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:18,017 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:21,020 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:21,020 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:21,020 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:24,123 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:24,123 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:24,124 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:27,327 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:27,327 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:27,327 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:30,631 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:30,631 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:30,631 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:34,034 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:34,035 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:34,035 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:37,538 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:37,539 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:37,539 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:37,539 - pypeflow.simple_pwatcher_bridge:335 - INFO - (slept for another 25.20000000000001s -- another 8 loop iterations)
2020-04-12 14:59:41,143 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:41,143 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:41,143 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:44,845 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:44,845 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:44,845 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:48,649 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:48,649 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:48,650 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:52,554 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:52,554 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:52,554 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 14:59:56,558 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 14:59:56,558 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 14:59:56,558 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 15:00:00,659 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 15:00:00,659 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 15:00:00,659 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 15:00:04,864 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 15:00:04,864 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 15:00:04,864 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 15:00:09,168 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 15:00:09,169 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 15:00:09,169 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 15:00:13,573 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 15:00:13,573 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 15:00:13,574 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 15:00:13,574 - pypeflow.simple_pwatcher_bridge:335 - INFO - (slept for another 36.000000000000014s -- another 9 loop iterations)
2020-04-12 15:00:18,076 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 15:00:18,076 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 15:00:18,077 - pwatcher.fs_based:556 - DEBUG - Status RUNNING for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 15:00:22,682 - pypeflow.simple_pwatcher_bridge:325 - DEBUG - N in queue: 1 (max_jobs=32)
2020-04-12 15:00:22,682 - pwatcher.fs_based:667 - DEBUG - query(which='list', jobids=<1>)
2020-04-12 15:00:22,682 - pwatcher.fs_based:556 - DEBUG - Status EXIT 256 for heartbeat:heartbeat-Pc9f2e42080f9f1
2020-04-12 15:00:22,682 - pypeflow.simple_pwatcher_bridge:94 - ERROR - Task Node(0-rawreads/build) failed with exit-code=256
2020-04-12 15:00:22,683 - pypeflow.simple_pwatcher_bridge:343 - DEBUG - recently_done: [(Node(0-rawreads/build), False)]
2020-04-12 15:00:22,683 - pypeflow.simple_pwatcher_bridge:344 - DEBUG - Num done in this iteration: 1
2020-04-12 15:00:22,683 - pypeflow.simple_pwatcher_bridge:358 - ERROR - Some tasks are recently_done but not satisfied: {Node(0-rawreads/build)}
2020-04-12 15:00:22,683 - pypeflow.simple_pwatcher_bridge:359 - ERROR - ready: set()
    submitted: set()
2020-04-12 15:00:22,683 - pwatcher.fs_based:671 - DEBUG - delete(which='known', jobids=<0>)
2020-04-12 15:00:22,683 - pwatcher.fs_based:633 - DEBUG - Deleting jobs for jobids from known ([])
2020-04-12 15:00:22,683 - pwatcher.fs_based:614 - ERROR - Failed to kill job for heartbeat 'heartbeat-Pc9f2e42080f9f1' (which might mean it was already gone): FileNotFoundError(2, 'No such file or directory')
Traceback (most recent call last):
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pypeflow/simple_pwatcher_bridge.py", line 278, in refreshTargets
    self._refreshTargets(updateFreq, exitOnFailure)
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pypeflow/simple_pwatcher_bridge.py", line 362, in _refreshTargets
    raise Exception(msg)
Exception: Some tasks are recently_done but not satisfied: {Node(0-rawreads/build)}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pwatcher/fs_based.py", line 611, in delete_heartbeat
    bjob.kill(state, heartbeat)
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pwatcher/fs_based.py", line 273, in kill
    with open(heartbeat_fn) as ifs:
FileNotFoundError: [Errno 2] No such file or directory: '/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/heartbeats/heartbeat-Pc9f2e42080f9f1'
2020-04-12 15:00:22,716 - pwatcher.fs_based:621 - DEBUG - Cannot remove heartbeat '/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/heartbeats/heartbeat-Pc9f2e42080f9f1': FileNotFoundError(2, 'No such file or directory')
2020-04-12 15:00:22,716 - pypeflow.simple_pwatcher_bridge:189 - DEBUG - In notifyTerminate(), result of delete:None

fc_run.log:

falcon-kit 1.8.1 (pip thinks "falcon-kit 1.8.1")
pypeflow 2.3.0
[INFO]Setup logging from file "None".
[INFO]$ lfs setstripe -c 12 /gpfs1/scratch/30days/uqswan29/fc >
[INFO]Apparently '/gpfs1/scratch/30days/uqswan29/fc' is not in lustre filesystem, which is fine.
[INFO]fc_run started with configuration D01_v01.cfg
[INFO]cfg=
{
  "General": {
    "LA4Falcon_preload": false,
    "avoid_text_file_busy": true,
    "bestn": 12,
    "dazcon": false,
    "falcon_sense_greedy": false,
    "falcon_sense_option": "--output-multi --min-idt 0.70 --min-cov 2 --max-n-read 200 --n-core 8",
    "falcon_sense_skip_contained": true,
    "fc_ovlp_to_graph_option": " --min-len 5000",
    "genome_size": "3000000000",
    "input_fofn": "input.fofn",
    "input_type": "raw",
    "length_cutoff": "-1",
    "length_cutoff_pr": "5000",
    "overlap_filtering_setting": "--max-diff 100 --max-cov 100 --min-cov 2 --n-core 12",
    "ovlp_DBdust_option": "",
    "ovlp_DBsplit_option": "-s400",
    "ovlp_HPCdaligner_option": "-v -B4 -M32 -h60 -e.96 -l500 -s1000",
    "ovlp_daligner_option": "-e.96 -l500 -s1000 -h60",
    "pa_DBdust_option": "",
    "pa_DBsplit_option": "-a -x500 -s400",
    "pa_HPCTANmask_option": "-l500",
    "pa_HPCdaligner_option": "-v -B4 -M32 -e.70 -l1000 -s1000",
    "pa_REPmask_code": "0,300/0,300/0,300",
    "pa_daligner_option": "-e.70 -l1000 -s1000",
    "pa_dazcon_option": "-j 4 -x -l 500",
    "pa_fasta_filter_option": "streamed-internal-median",
    "pa_subsample_coverage": 0,
    "pa_subsample_random_seed": 12345,
    "pa_subsample_strategy": "random",
    "seed_coverage": "30",
    "skip_checks": false,
    "target": "assembly"
  },
  "job.defaults": {
    "job_type": "local",
    "njobs": "32",
    "pwatcher_type": "fs_based",
    "stop_all_jobs_on_failure": "False",
    "use_tmpdir": false
  },
  "job.step.asm": {},
  "job.step.cns": {
    "njobs": "8"
  },
  "job.step.da": {},
  "job.step.dust": {},
  "job.step.la": {},
  "job.step.pda": {},
  "job.step.pla": {}
}
[INFO]In simple_pwatcher_bridge, pwatcher_impl=<module 'pwatcher.fs_based' from '/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pwatcher/fs_based.py'>
[INFO]job_type='local', (default)job_defaults={'job_type': 'local', 'stop_all_jobs_on_failure': 'False', 'njobs': '32', 'pwatcher_type': 'fs_based', 'use_tmpdir': False}, use_tmpdir=False, squash=False, job_name_style=0
[INFO]Setting max_jobs to 32; was None
[INFO]Num unsatisfied: 2, graph: 2
[INFO]About to submit: Node(0-rawreads/build)
[INFO] starting job Job(jobid='Pc9f2e42080f9f1', cmd='/bin/bash run.sh', rundir='/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build', options={'job_type': 'local', 'stop_all_jobs_on_failure': 'False', 'njobs': '32', 'pwatcher_type': 'fs_based', 'use_tmpdir': False, 'NPROC': 1, 'MB': 4000}) w/ job_type=LOCAL
[INFO]dir: '/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/jobs/Pc9f2e42080f9f1'
CALL:
 '/bin/bash /gpfs1/scratch/30days/uqswan29/fc/mypwatcher/wrappers/run-Pc9f2e42080f9f1.bash 1>|stdout 2>|stderr & '
[INFO]pid=32304 pgid=32304 sub-pid=32314
[INFO]Submitted backgroundjob=MetaJobLocal(MetaJob(job=Job(jobid='Pc9f2e42080f9f1', cmd='/bin/bash run.sh', rundir='/gpfs1/scratch/30days/uqswan29/fc/0-rawreads/build', options={'job_type': 'local', 'stop_all_jobs_on_failure': 'False', 'njobs': '32', 'pwatcher_type': 'fs_based', 'use_tmpdir': False, 'NPROC': 1, 'MB': 4000}), lang_exe='/bin/bash'))
[INFO](slept for another 0.0s -- another 1 loop iterations)
[INFO](slept for another 0.30000000000000004s -- another 2 loop iterations)
[INFO](slept for another 1.2000000000000002s -- another 3 loop iterations)
[INFO](slept for another 2.9999999999999996s -- another 4 loop iterations)
[INFO](slept for another 6.0s -- another 5 loop iterations)
[INFO](slept for another 10.500000000000002s -- another 6 loop iterations)
[INFO](slept for another 16.800000000000004s -- another 7 loop iterations)
[INFO](slept for another 25.20000000000001s -- another 8 loop iterations)
[INFO](slept for another 36.000000000000014s -- another 9 loop iterations)
[ERROR]Task Node(0-rawreads/build) failed with exit-code=256
[ERROR]Some tasks are recently_done but not satisfied: {Node(0-rawreads/build)}
[ERROR]ready: set()
    submitted: set()
[ERROR]Failed to kill job for heartbeat 'heartbeat-Pc9f2e42080f9f1' (which might mean it was already gone): FileNotFoundError(2, 'No such file or directory')
Traceback (most recent call last):
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pypeflow/simple_pwatcher_bridge.py", line 278, in refreshTargets
    self._refreshTargets(updateFreq, exitOnFailure)
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pypeflow/simple_pwatcher_bridge.py", line 362, in _refreshTargets
    raise Exception(msg)
Exception: Some tasks are recently_done but not satisfied: {Node(0-rawreads/build)}

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pwatcher/fs_based.py", line 611, in delete_heartbeat
    bjob.kill(state, heartbeat)
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pwatcher/fs_based.py", line 273, in kill
    with open(heartbeat_fn) as ifs:
FileNotFoundError: [Errno 2] No such file or directory: '/gpfs1/scratch/30days/uqswan29/fc/mypwatcher/heartbeats/heartbeat-Pc9f2e42080f9f1'
Traceback (most recent call last):
  File "/home/uqswan29/.conda/envs/conda_PacBio/bin/fc_run", line 11, in <module>
    load_entry_point('falcon-kit==1.8.1', 'console_scripts', 'fc_run')()
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/falcon_kit/mains/run1.py", line 706, in main
    main1(argv[0], args.config, args.logger)
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/falcon_kit/mains/run1.py", line 73, in main1
    input_fofn_fn=input_fofn_fn,
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/falcon_kit/mains/run1.py", line 235, in run
    dist=Dist(NPROC=4, MB=4000, job_dict=config['job.step.da']),
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/falcon_kit/pype.py", line 106, in gen_parallel_tasks
    wf.refreshTargets()
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pypeflow/simple_pwatcher_bridge.py", line 278, in refreshTargets
    self._refreshTargets(updateFreq, exitOnFailure)
  File "/home/uqswan29/.conda/envs/conda_PacBio/lib/python3.7/site-packages/pypeflow/simple_pwatcher_bridge.py", line 362, in _refreshTargets
    raise Exception(msg)
Exception: Some tasks are recently_done but not satisfied: {Node(0-rawreads/build)}

My cfg file:

[General]
input_fofn = input.fofn

input_type = raw
#input_type = preads

target = assembly

genome_size = 3000000000
seed_coverage = 30
length_cutoff = -1

length_cutoff_pr = 5000

pa_HPCdaligner_option =  -v -B4 -M32 -e.70 -l1000 -s1000
ovlp_HPCdaligner_option = -v -B4 -M32 -h60 -e.96 -l500 -s1000

pa_daligner_option = -e.70 -l1000 -s1000
ovlp_daligner_option = -e.96 -l500 -s1000 -h60

pa_DBsplit_option = -a -x500 -s400
ovlp_DBsplit_option = -s400

falcon_sense_option=--output-multi --min-idt 0.70 --min-cov 2 --max-n-read 200 --n-core 8
falcon_sense_skip_contained = True

overlap_filtering_setting=--max-diff 100 --max-cov 100 --min-cov 2 --n-core 12

[job.defaults]
job_type=local
stop_all_jobs_on_failure = False
njobs = 32

[job.step.cns]
njobs = 8

I tried workaround in #687 and I am only allowed to update packages but no the conda base which was updated July last year.

I can't seem to debug it, can you tell me where I am doing it wrong?

Thanks in advance.

pb-cdunn commented 3 years ago

You always have to look for stderr, in this case in 0-rawreads/build/. These problems are usually software installation.