FALCON_unzip successful with Ecoli sample, but failed with my own data

[wsuplantpathology]

Hi @pb-jchin @pb-cdunn ,

Please help me with this issue, I was running falcon_unzip 0.4.0, and was successful using Ecoli example data after falcon running. However, it was failed when I ran my own data, even though I was using exactly the same environment, the same dependencies, and the same falcon-kit. Here is fc_unzip.cfg
fc_unzip.txt
Here is what I got from my own data running in 3-unzip/reads/pwatcher.dir/stderr :

[40293]starting track_reads
[40293]file list: ['/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00045/raw_reads.45.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00001/raw_reads.1.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00036/raw_reads.36.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00025/raw_reads.25.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00014/raw_reads.14.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00060/raw_reads.60.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00010/raw_reads.10.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00023/raw_reads.23.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00059/raw_reads.59.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00041/raw_reads.41.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00057/raw_reads.57.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00029/raw_reads.29.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00051/raw_reads.51.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00017/raw_reads.17.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00021/raw_reads.21.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00079/raw_reads.79.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00055/raw_reads.55.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00005/raw_reads.5.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00040/raw_reads.40.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00070/raw_reads.70.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00049/raw_reads.49.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00085/raw_reads.85.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00003/raw_reads.3.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00050/raw_reads.50.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00075/raw_reads.75.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00065/raw_reads.65.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00019/raw_reads.19.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00008/raw_reads.8.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00078/raw_reads.78.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00024/raw_reads.24.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00015/raw_reads.15.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00047/raw_reads.47.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00046/raw_reads.46.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00039/raw_reads.39.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00037/raw_reads.37.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00083/raw_reads.83.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00061/raw_reads.61.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00009/raw_reads.9.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00058/raw_reads.58.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00016/raw_reads.16.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00072/raw_reads.72.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00027/raw_reads.27.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00044/raw_reads.44.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00054/raw_reads.54.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00034/raw_reads.34.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00067/raw_reads.67.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00013/raw_reads.13.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00068/raw_reads.68.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00064/raw_reads.64.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00082/raw_reads.82.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00018/raw_reads.18.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00035/raw_reads.35.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00062/raw_reads.62.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00006/raw_reads.6.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00012/raw_reads.12.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00076/raw_reads.76.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00043/raw_reads.43.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00084/raw_reads.84.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00026/raw_reads.26.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00056/raw_reads.56.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00028/raw_reads.28.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00020/raw_reads.20.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00031/raw_reads.31.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00069/raw_reads.69.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00032/raw_reads.32.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00048/raw_reads.48.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00022/raw_reads.22.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00071/raw_reads.71.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00038/raw_reads.38.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00081/raw_reads.81.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00004/raw_reads.4.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00066/raw_reads.66.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00007/raw_reads.7.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00042/raw_reads.42.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00030/raw_reads.30.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00063/raw_reads.63.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00002/raw_reads.2.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00052/raw_reads.52.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00033/raw_reads.33.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00080/raw_reads.80.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00074/raw_reads.74.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00073/raw_reads.73.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00077/raw_reads.77.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00011/raw_reads.11.las', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00053/raw_reads.53.las']
[40293]preparing tr_stage1
[40293]maxrss:    10796
[40294]starting run_tr_stage1('/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/raw_reads.db', '/data/chen/PacBio/PST/assembly/falcon/raw_all/0-rawreads/m_00045/raw_reads.45.las', 2500, 40, dict(37794 elem))
[40294]maxrss:    38416
     ......
[40293]finished track_reads
python -m falcon_kit.mains.pr_ctg_track
+ python -m falcon_kit.mains.pr_ctg_track
/usr/bin/python: No module named ext_falcon
touch /data/chen/PacBio/PST/assembly/falcon/raw_all/3-unzip/reads/track_reads_done.exit
+ touch /data/chen/PacBio/PST/assembly/falcon/raw_all/3-unzip/reads/track_reads_done.exit
2017-03-15 22:25:07,803 - root - DEBUG - CD: '/data/chen/PacBio/PST/assembly/falcon/raw_all/3-unzip/reads' -> '/data/chen/PacBio/PST/assembly/falcon/raw_all/3-unzip/reads'
2017-03-15 22:25:07,803 - root - DEBUG - CD: '/data/chen/PacBio/PST/assembly/falcon/raw_all/3-unzip/reads' -> '/data/chen/PacBio/PST/assembly/falcon/raw_all/3-unzip/reads'
2017-03-15 22:25:07,804 - root - CRITICAL - Error in /home/chongjing.xia/FALCON-integrate/pypeFLOW/pypeflow/do_task.py with args="{'json_fn': '/data/chen/PacBio/PST/assembly/falcon/raw_all/3-unzip/reads/task.json',\n 'timeout': 600000000000000,\n 'tmpdir': None}"
Traceback (most recent call last):
  File "/usr/lib64/python2.7/runpy.py", line 162, in _run_module_as_main
    "__main__", fname, loader, pkg_name)
  File "/usr/lib64/python2.7/runpy.py", line 72, in _run_code
    exec code in run_globals
  File "/home/chongjing.xia/FALCON-integrate/pypeFLOW/pypeflow/do_task.py", line 190, in <module>
    main()
  File "/home/chongjing.xia/FALCON-integrate/pypeFLOW/pypeflow/do_task.py", line 182, in main
    run(**vars(parsed_args))
  File "/home/chongjing.xia/FALCON-integrate/pypeFLOW/pypeflow/do_task.py", line 136, in run
    run_cfg_in_tmpdir(cfg, tmpdir)
  File "/home/chongjing.xia/FALCON-integrate/pypeFLOW/pypeflow/do_task.py", line 160, in run_cfg_in_tmpdir
    run_python_func(func, myinputs, myoutputs, parameters)
  File "/home/chongjing.xia/FALCON-integrate/pypeFLOW/pypeflow/do_task.py", line 125, in run_python_func
    do_support.run_bash(script_fn)
  File "/home/chongjing.xia/FALCON-integrate/pypeFLOW/pypeflow/do_support.py", line 51, in run_bash
    raise Exception('{} <- {!r}'.format(rc, cmd))
Exception: 256 <- '/bin/bash -vex /data/chen/PacBio/PST/assembly/falcon/raw_all/3-unzip/reads/track_reads.sh'

real	109m20.759s
user	411m47.694s
sys	12m34.778s
 returned: 256

For comparison, here is what I got from successful ecoli example, from 3-unzip/reads/pwatcher.dir/stderr:

[40154]starting track_reads
[40154]file list: ['/data/chen/software/FALCON-integrate/test/0-rawreads/m_00013/raw_reads.13.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00015/raw_reads.15.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00008/raw_reads.8.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00020/raw_reads.20.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00019/raw_reads.19.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00005/raw_reads.5.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00010/raw_reads.10.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00002/raw_reads.2.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00012/raw_reads.12.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00009/raw_reads.9.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00001/raw_reads.1.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00016/raw_reads.16.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00004/raw_reads.4.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00007/raw_reads.7.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00014/raw_reads.14.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00006/raw_reads.6.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00018/raw_reads.18.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00003/raw_reads.3.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00011/raw_reads.11.las', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00017/raw_reads.17.las']
[40154]preparing tr_stage1
[40154]maxrss:    10808
[40155]starting run_tr_stage1('/data/chen/software/FALCON-integrate/test/0-rawreads/raw_reads.db', '/data/chen/software/FALCON-integrate/test/0-rawreads/m_00013/raw_reads.13.las', 2500, 40, dict(1442 elem))
         .......
[40185]finished track_reads
#mkdir -p 3-unzip/reads/
python -m falcon_kit.mains.fetch_reads
+ python -m falcon_kit.mains.fetch_reads
cd /data/chen/software/FALCON-integrate/test/3-unzip/reads
+ cd /data/chen/software/FALCON-integrate/test/3-unzip/reads
date
+ date
touch /data/chen/software/FALCON-integrate/test/3-unzip/reads/track_reads_done
+ touch /data/chen/software/FALCON-integrate/test/3-unzip/reads/track_reads_done
touch /data/chen/software/FALCON-integrate/test/3-unzip/reads/track_reads_done.exit
+ touch /data/chen/software/FALCON-integrate/test/3-unzip/reads/track_reads_done.exit
2017-03-15 20:32:53,799 - root - DEBUG - CD: '/data/chen/software/FALCON-integrate/test/3-unzip/reads' -> '/data/chen/software/FALCON-integrate/test/3-unzip/reads'
2017-03-15 20:32:53,799 - root - DEBUG - Checking existence of u'ctg_list' with timeout=600000000000000
2017-03-15 20:32:53,802 - root - DEBUG - Checking existence of u'track_reads_done' with timeout=600000000000000
2017-03-15 20:32:53,804 - root - DEBUG - CD: '/data/chen/software/FALCON-integrate/test/3-unzip/reads' -> '/data/chen/software/FALCON-integrate/test/3-unzip/reads'

real	6m19.866s
user	4m55.217s
sys	0m28.049s
touch /data/chen/software/FALCON-integrate/test/3-unzip/reads/run.sh.done
+ touch /data/chen/software/FALCON-integrate/test/3-unzip/reads/run.sh.done
 returned: 0```

The only difference between these two runnings was that there were three jobs failed in 0-rawreads step due to LAcheck issue in Falcon, and I manually ran that three jobs and successful (see my comments in falcon issue #124). For Ecoli example, I ran Falcon successfully directly, without any manual steps. 

Please let me know if you need more information. Thanks very much in advance.
chongjing

[gconcepcion]

Hi @wsuplantpathology

Can you post the contents of:
/data/chen/PacBio/PST/assembly/falcon/raw_all/3-unzip/reads/task.json
It looks like the task finished successfully.

Does 3-unzip/reads/track_reads_done exist, and is 3-unzip/reads/ctg_list non-empty?

If so, you may be able to proceed by touching the sentinels and re-invoking the pipeline:

touch /data/chen/PacBio/PST/assembly/falcon/raw_all/3-unzip/reads/track_reads_done.exit
touch /data/chen/PacBio/PST/assembly/falcon/raw_all/3-unzip/reads/run.sh.done

[wsuplantpathology]

Thanks @gconcepcion

1. Here is the contents of /data/chen/PacBio/PST/assembly/falcon/raw_all/3-unzip/reads/task.json

{
    "inputs": {
        "falcon_asm_done": "/data/chen/PacBio/PST/assembly/falcon/raw_all/2-asm-falcon/falcon_asm_done"
    },
    "outputs": {
        "ctg_list_file": "ctg_list",
        "job_done": "track_reads_done"
    },
    "parameters": {
        "config": {
            "job_queue": "default",
            "job_type": "local",
            "pwatcher_type": "fs_based",
            "sge_blasr_aln": "-pe smp 24 -q your_sge_queue",
            "sge_hasm": "-pe smp 48 -q your_sge_queue",
            "sge_phasing": "-pe smp 12 -q your_sge_queue",
            "sge_track_reads": "-pe smp 12 -q your_sge_queue",
            "smrt_bin": "/data/chen/software/GenomicConsensus-smrtanalysis-3.0.2/bin",
            "unzip_blasr_concurrent_jobs": 8,
            "unzip_phasing_concurrent_jobs": 8
        },
        "sge_option": "-pe smp 12 -q your_sge_queue",
        "wd": "/data/chen/PacBio/PST/assembly/falcon/raw_all/3-unzip/reads"
    },
    "python_function": "falcon_unzip.unzip.task_track_reads"
}

2. I do have non-empty 3-unzip/reads/ctg_list, but 3-unzip/reads/track_reads_done does not exist. However, I have 3-unzip/reads/track_reads_done.exit and this file is empty.

3. I ran your last two commands, nothing happens but two empty files generated, run.sh.done and track_reads_done.exit

Besides, in the 3-unzip/reads/ directory there are many *F_reads.fa and *F_ref.fa files, and they are non-empty. however, I notice the first file 000000F_reads.fa is 42Mb, then size of following *F_reads.fa is decreasing, with last one 000544F._reads.fa has only 354kb. Is this normal? The name of *F are all listed in ctg_list. My new questions are,

1. how do you know the task looks like finished successfully?
2. what is that critical error in CRITICAL - Error in /home/chongjing.xia/FALCON-integrate/pypeFLOW/pypeflow/do_task.py with args="{'json_fn': '/data/chen/PacBio/PST/assembly/falcon/raw_all/3-unzip/reads/task.json',\n 'timeout': 600000000000000,\n 'tmpdir': None}"

Thanks very much for your time and efforts, I appreciate.

[gconcepcion]

1. Is your SGE queue really called "your_sge_queue", or did you change it just to paste it here? I would say look into this as the obvious culprit. Not sure if this is the case - just a suggestion to investigate.

2. So the run.sh script exited due to an import failure prior to touching the track_reads_done file. That's interesting because python -m falcon_kit.mains.rr_ctg_track seems to have completely successfully, but then the script chokes on: python -m falcon_kit.mains.pr_ctg_track with an python env error. But both of those scripts import the same python modules so i'm not sure what's happening.

Besides, in the 3-unzip/reads/ directory there are many *F_reads.fa and *F_ref.fa files, and they are non-empty. however, I notice the first file 000000F_reads.fa is 42Mb, then size of following *F_reads.fa is decreasing, with last one 000544F._reads.fa has only 354kb. Is this normal? The name of *F are all listed in ctg_list. My new questions are,

Yes, this is normal. In general the lowest number contig 000000F is the longest and thus it has the most reads mapping to it. The number of reads mapping to a particular contig should decrease as the contig number increases. Unless of course the contig is a highly repetitive section of DNA

how do you know the task looks like finished successfully?

Sorry, I was mistaken - I missed the env error /usr/bin/python: No module named ext_falcon
I'll need to take a look and see if I can figure out what's going on here.

what is that critical error in CRITICAL - Error in /home/chongjing.xia/FALCON-integrate/pypeFLOW/pypeflow/do_task.py with args="{'json_fn': '/data/chen/PacBio/PST/assembly/falcon/raw_all/3-unzip/reads/task.json',\n 'timeout': 600000000000000,\n 'tmpdir': None}"

That's just saying that the read tracking task exited without completing successfully, due to the issues mentioned above.

[wsuplantpathology]

Thanks @gconcepcion for your explanations, very helpful.

Is your SGE queue really called "your_sge_queue", or did you change it just to paste it here? I would say look into this as the obvious culprit. Not sure if this is the case - just a suggestion to investigate.

No, I just leave these setting as default. I set job_type = local. So I didn't change SGE settings in the example .cfg. Actually, we are using SLURM, our partition is called "kamiak". Do you think I should set job_queue = kamiak, even though I have job_type = local.

Some update information:
Since you mentioned the track reads step looks successful, so I proceeded the following steps. And it turns out, everything looks good: I got phasing step done, and even quiver consensus. Basically, I have all_p_ctg.fa (85Mb, which is a little bit smaller than previously estimated 100Mb), all_h_ctg.fa (54Mb, I think this size is good since my fungus has high heterozygosity). But these are my first impression, I'll look into the details of the running process. Any comments are welcome on these results, since I am not so confident on how to interpret these data.

Thanks very much.