# HG changeset patch
# User iuc
# Date 1663339183 0
# Node ID ad80238462c196f80ad01412662f4dc39dd0ccc6
# Parent  2a9baa0c43168a96be27e6208e6a0ebf2018581b
planemo upload for repository https://github.com/galaxyproject/tools-iuc/tree/master/tools/shovill commit 1e28eb4ffcf3d9168877c291d27e533b96021445

diff -r 2a9baa0c4316 -r ad80238462c1 shovill.xml
--- a/shovill.xml	Thu Feb 03 20:41:04 2022 +0000
+++ b/shovill.xml	Fri Sep 16 14:39:43 2022 +0000
@@ -1,11 +1,12 @@
-<tool id="shovill" name="Shovill" version="@TOOL_VERSION@+galaxy1">
+<tool id="shovill" name="Shovill" version="@TOOL_VERSION@+galaxy@VERSION_SUFFIX@">
     <description>Faster SPAdes assembly of Illumina reads</description>
+    <macros>
+        <token name="@TOOL_VERSION@">1.1.0</token>
+        <token name="@VERSION_SUFFIX@">1</token>
+    </macros>
     <xrefs>
         <xref type="bio.tools">shovill</xref>
     </xrefs>
-    <macros>
-        <token name="@TOOL_VERSION@">1.1.0</token>
-    </macros>
     <requirements>
         <requirement type="package" version="@TOOL_VERSION@">shovill</requirement>
     </requirements>
@@ -19,10 +20,10 @@
             #set r2_ext = $library.R2.extension
             #if $r1_ext == 'fastqsanger.gz' or $r1_ext == 'fastqsanger.bz2'
                 cp '$library.R1' fastq_r1.'$r1_ext' &&
-                cp '$library.R2' fastq_r2.'$r2_ext' && 
+                cp '$library.R2' fastq_r2.'$r2_ext' &&
             #else
                 ln -s '$library.R1' fastq_r1.'$r1_ext' &&
-                ln -s '$library.R2' fastq_r2.'$r2_ext' && 
+                ln -s '$library.R2' fastq_r2.'$r2_ext' &&
             #end if
         #else if str($library.lib_type) == "collection"
             #set r1_ext = $library.input1.forward.extension
@@ -42,13 +43,13 @@
 	## (3) Or default to 4 GB if GALAXY_MEMORY_MB is unset
 	GALAXY_MEMORY_GB=\$((\${GALAXY_MEMORY_MB:-4096}/1024)) &&
 	SHOVILL_RAM=\${SHOVILL_RAM:-\${GALAXY_MEMORY_GB}} &&
-        
+
         shovill
             --outdir 'out'
             --cpus \${GALAXY_SLOTS:-1}
             --ram \${SHOVILL_RAM:-4}
-            --R1 fastq_r1.'$r1_ext'
-            --R2 fastq_r2.'$r2_ext'
+            --R1 'fastq_r1.$(r1_ext)'
+            --R2 'fastq_r2.$(r2_ext)'
             $trim
             --namefmt '$adv.namefmt'
             --depth '$adv.depth'
@@ -61,11 +62,14 @@
             #if $adv.opts
                 --opts '$adv.opts'
             #end if
-            $adv.nocorr
             --minlen $adv.minlen
             --mincov $adv.mincov
             --assembler $assembler
-
+            #if $adv.keep_files.nocorr == 'no_correction'
+                --nocorr
+            #else
+                $adv.keep_files.keepfiles
+            #end if
     ]]></command>
     <inputs>
         <conditional name="library">
@@ -82,7 +86,6 @@
             </when>
         </conditional>
         <param name="trim" argument="--trim" type="boolean" truevalue="--trim" falsevalue="" label="Trim reads" help="Use Trimmomatic to remove common adaptors first (default: OFF)" />
-        <param name="log" type="boolean" label="Output log file?" checked="true" help="Return the Shovill log file as part of the output. Default is on" />
         <param name="assembler" argument="--assembler" type="select" label="Assembler to use" help="Which assembler would you like shovill to use, default is Spades">
             <option value="skesa">skesa</option>
             <option value="megahit">megahit</option>
@@ -104,22 +107,34 @@
             <param name="gsize" argument="--gsize" type="text" value="" label="Estimated genome size" help="An estimate of the final genome size, it will autodetect if this is blank. (default: '')" />
             <param name="kmers" argument="--kmers" type="text" value="" label="List of kmer sizes to use" help="List of K-mer sizes to use in SPAdes. Blank is AUTO. default: ''" />
             <param name="opts" argument="--opts" type="text" value="" label="Extra SPAdes options" help="eg. --plasmid --sc ... (default: '')" />
-            <param name="nocorr" argument="--nocorr" type="boolean" truevalue="--nocorr" falsevalue="" checked="True" label="Disable post-assembly correction" help="Disable post assembly correction with pilon (default: ON)" />
+            <conditional name="keep_files">
+                <param name="nocorr" argument="--nocorr" type="select" label="Disable post-assembly correction" help="Disable post assembly correction with pilon (default: ON)">
+                    <option value="no_correction" selected="true">No corrections</option>
+                    <option value="yes_correction">Post assembly corrections</option>
+                </param>
+                <when value="no_correction"/>
+                <when value="yes_correction">
+                    <param name="keepfiles" argument="--keepfiles" type="boolean" truevalue="--keepfiles"  checked="False" falsevalue=""  label="Keep bam files" help="Keep bam files only if post-assembly correction is enable"/>
+                </when>
+            </conditional>
             <param name="minlen" argument="--minlen" type="integer" value="0" label="Minimum contig length" help="Minimum length of contig to be output. 0 is AUTO (default: 0)" />
             <param name="mincov" argument="--mincov" type="integer" value="2" label="Minimum contig coverage" help="Minimum coverage to call part of a contig. 0 is AUTO (default: 2)" />
         </section>
+        <param name="log" type="boolean" label="Output log file?" checked="true" help="Return the Shovill log file as part of the output. Default is on" />
+
     </inputs>
-
     <outputs>
         <data name="shovill_std_log" format="txt" label="${tool.name} on ${on_string} Log file" from_work_dir="out/shovill.log" >
-            <filter>log</filter>
+            <filter>log == True</filter>
         </data>
-        <data format="fasta" name="contigs" label="${tool.name} on ${on_string}: Contigs" from_work_dir="out/contigs.fa"/>
-        <data format="txt" name="contigs_graph" label="${tool.name} on ${on_string}: Contig Graph" from_work_dir="out/contigs.gfa"/>
+        <data name="contigs" format="fasta" label="${tool.name} on ${on_string}: Contigs" from_work_dir="out/contigs.fa"/>
+        <data name="contigs_graph" format="txt"  label="${tool.name} on ${on_string}: Contig Graph" from_work_dir="out/contigs.gfa"/>
+        <data name="bamfiles" format="unsorted.bam" from_work_dir="out/shovill.bam" label="Bam file for ${tool.name} on ${on_string}">
+          <filter> adv['keep_files']['nocorr'] == 'yes_correction' and adv['keep_files']['keepfiles'] == True </filter>
+        </data>
     </outputs>
-
     <tests>
-        <test> <!-- Test 1: Basic test -->
+        <test expect_num_outputs="3"> <!-- Test 1: Basic test -->
             <param name="lib_type" value="paired" />
             <param name="R1" value="mutant_R1.fastq" ftype="fastqsanger" />
             <param name="R2" value="mutant_R2.fastq" ftype="fastqsanger" />
@@ -134,10 +149,10 @@
                     <has_text text="[lighter] Processed 820 reads"/>
                     <has_text text="[FLASH] FLASH v1.2.11 complete!"/>
                     <has_text text="[spades] ======= SPAdes pipeline finished."/>
-                </assert_contents>
-            </output>
+                  </assert_contents>
+                </output>
         </test>
-        <test> <!-- Test 2: Auto everything + trim + different name format test -->
+        <test expect_num_outputs="3"> <!-- Test 2: Auto everything + trim + different name format test -->
             <param name="lib_type" value="paired" />
             <param name="R1" value="mutant_R1.fastq" ftype="fastqsanger" />
             <param name="R2" value="mutant_R2.fastq" ftype="fastqsanger" />
@@ -146,7 +161,9 @@
                 <param name="depth" value="0"/>
                 <param name="minlen" value="0"/>
                 <param name="mincov" value="0"/>
-                <param name="nocorr" value="false"/>
+                <conditional name="keep_files">
+                    <param name="nocorr" value="yes_correction"/>
+                </conditional>
                 <param name="namefmt" value="contig%03d"/>
             </section>
             <output name="contigs" ftype="fasta">
@@ -166,7 +183,7 @@
                 </assert_contents>
             </output>
         </test>
-        <test> <!-- Test 3: Alternate assembler #1: Megahit -->
+        <test expect_num_outputs="3"> <!-- Test 3: Alternate assembler #1: Megahit -->
             <param name="lib_type" value="paired" />
             <param name="R1" value="mutant_R1.fastq" ftype="fastqsanger" />
             <param name="R2" value="mutant_R2.fastq" ftype="fastqsanger" />
@@ -174,7 +191,7 @@
             <output name="contigs" ftype="fasta">
                 <assert_contents>
                     <has_text text="&gt;contig00001"/>
-                </assert_contents>
+                  </assert_contents>
             </output>
             <output name="shovill_std_log" ftype="txt" >
                 <assert_contents>
@@ -185,7 +202,7 @@
                 </assert_contents>
             </output>
         </test>
-        <test> <!-- Test 4: Alternate assembler #2: Skesa -->
+        <test expect_num_outputs="3"> <!-- Test 4: Alternate assembler #2: Skesa -->
             <param name="lib_type" value="paired" />
             <param name="R1" value="mutant_R1.fastq" ftype="fastqsanger" />
             <param name="R2" value="mutant_R2.fastq" ftype="fastqsanger" />
@@ -204,7 +221,7 @@
                 </assert_contents>
             </output>
         </test>
-        <test> <!-- Test 5: Alternate assembler #3: Velvet -->
+        <test expect_num_outputs="3"> <!-- Test 5: Alternate assembler #3: Velvet -->
             <param name="lib_type" value="paired" />
             <param name="R1" value="mutant_R1.fastq" ftype="fastqsanger" />
             <param name="R2" value="mutant_R2.fastq" ftype="fastqsanger" />
@@ -223,7 +240,7 @@
                 </assert_contents>
             </output>
         </test>
-        <test> <!-- Test 6: Gzipped input with trimming -->
+        <test expect_num_outputs="3"> <!-- Test 6: Gzipped input with trimming -->
             <param name="lib_type" value="paired" />
             <param name="R1" value="mutant_R1.fastq.gz" ftype="fastqsanger.gz" />
             <param name="R2" value="mutant_R2.fastq.gz" ftype="fastqsanger.gz" />
@@ -242,29 +259,53 @@
                 </assert_contents>
             </output>
         </test>
+        <test expect_num_outputs="4"> <!-- Test 7: Add keepfiles option -->
+            <param name="lib_type" value="paired" />
+            <param name="R1" value="mutant_R1.fastq.gz" ftype="fastqsanger.gz" />
+            <param name="R2" value="mutant_R2.fastq.gz" ftype="fastqsanger.gz" />
+            <param name="trim" value="true" />
+            <section name="adv">
+                <conditional name="keep_files">
+                    <param name="nocorr" value="yes_correction" />
+                    <param name="keepfiles" value="True" />
+                </conditional>
+                <param name="log" value="true"/>
+            </section>
+            <output name="contigs" ftype="fasta">
+                <assert_contents>
+                    <has_text text="&gt;contig00001"/>
+                </assert_contents>
+            </output>
+            <output name="bamfiles" ftype="unsorted.bam">
+                <assert_contents>
+                    <has_size value="36359" delta="1000" />
+                </assert_contents>
+            </output>
+        </test>
     </tests>
     <help><![CDATA[
-Synopsis:
-  Faster de novo assembly pipeline for Illumina paired end reads based around Spades
+      Synopsis:
+      Faster de novo assembly pipeline for Illumina paired end reads based around Spades
 
-Details and options:
-    - Takes paired end Illumina fastq reads
-    - Trim reads:   Use Trimmomatic to remove common adaptors first (default: OFF)
-    - Output log file:  If set to "Yes", tool will return Shovill's log file as part of the output
-    - Assembler:    Which assembler should shovill use from: Skesa, Megahit, Velvet or Spades. Spades is the default.
+      Details and options:
+      - Takes paired end Illumina fastq reads
+      - Trim reads:   Use Trimmomatic to remove common adaptors first (default: OFF)
+      - Output log file:  If set to "Yes", tool will return Shovill's log file as part of the output
+      - Assembler:    Which assembler should shovill use from: Skesa, Megahit, Velvet or Spades. Spades is the default.
 
-Advanced options:
-    - Name format:          Format of output contig FASTA IDs in 'printf' style (default: 'contig%05d')
-    - Depth:                Sub-sample the reads to this depth. Disable with *Depth: 0* (default: 100)
-    - Estimated genomesize: An estimate of the final genome size, it will autodetect if this is blank. (default: '')
-    - List of kmers to use: List of K-mer sizes to use in SPAdes. Blank is AUTO. (default: '')
-    - Extra SPAdes options: Extra SPAdes options eg. --plasmid --sc ... (default: '')
-    - Disable post-assembly correction: Disable post assembly correction with pilon (default: ON)
-    - Minimum contig length:    Minimum length of contig to be output. 0 is AUTO (default: 0)
-    - Minimum contig coverage:  Minimum coverage to call part of a contig. 0 is AUTO (default: 2)
-    - Spades result to correct: Spades result to correct: before_rr, contigs or scaffolds (default: 'contigs')
+      Advanced options:
+      - Name format:          Format of output contig FASTA IDs in 'printf' style (default: 'contig%05d')
+      - Depth:                Sub-sample the reads to this depth. Disable with *Depth: 0* (default: 100)
+      - Estimated genomesize: An estimate of the final genome size, it will autodetect if this is blank. (default: '')
+      - List of kmers to use: List of K-mer sizes to use in SPAdes. Blank is AUTO. (default: '')
+      - Extra SPAdes options: Extra SPAdes options eg. --plasmid --sc ... (default: '')
+      - Disable post-assembly correction: Disable post assembly correction with pilon (default: ON)
+      - Keep the bam files : Enable to keep mapped files from bwa in the post assembly correction (default: OFF)
+      - Minimum contig length:    Minimum length of contig to be output. 0 is AUTO (default: 0)
+      - Minimum contig coverage:  Minimum coverage to call part of a contig. 0 is AUTO (default: 2)
+      - Spades result to correct: Spades result to correct: before_rr, contigs or scaffolds (default: 'contigs')
 
-Documentation can be found at Torsten Seemann `site <https://github.com/tseemann/shovill>`_.
+    Documentation can be found at Torsten Seemann `site <https://github.com/tseemann/shovill>`_.
     ]]></help>
     <citations>
         <citation type="bibtex">
diff -r 2a9baa0c4316 -r ad80238462c1 test-data/contigs.fa
--- a/test-data/contigs.fa	Thu Feb 03 20:41:04 2022 +0000
+++ b/test-data/contigs.fa	Fri Sep 16 14:39:43 2022 +0000
@@ -1,22 +1,20 @@
->contig00001 len=14151 cov=4.0 corr=0 spades=NODE_1_length_14151_cov_3.95289_pilon
-GAAGAAGTAAAAAAGGGCTATTTTCCAATCAAACGTGCGATTGACTTGGTATTAAGTATC
-GTTTTATTATTTTTAACATTTCCGATTATGTTCATATTCGCCATTGCTATCGTCATAGAT
-TCGCCAGGAAACCCTATTTATAGTCAGGTTAGAGTTGGGAAGATGGGTAAATTAATTAAA
-ATATACAAATTACGTTCGATGTGTAAAAACGCAGAGAAAAACGGTGCGCAATGGGCTGAT
-AAAGATGATGATCGTATAACAAATGTCGGGAAGTTTATTCGTAAAACACGCATTGATGAA
-TTACCACAACTAATTAATGTTGTTAAAGGGGAAATGAGTTTTATTGGACCACGCCCGGAA
-CGTCCAGAATTTGTAGAATTATTTAGTTCAGAAATAATAGGATTTGAGCAAAGATGTCTT
-GTTACACCAGGATTAACAGGTCTTGCGCAAATTCAAGGTGGATATGACTTAACACCACAA
-CAAAAATTAAAATATGACATGAAATATATACATAAAGGTAGCTTAATGATGGAATTATAT
-ATATCAATTAGAACATTGATGGTTGTTATTACAGGGGAAGGCTCAAGGTAGTCTTAATTT
-GCTTAATAAGTTTAAATAAAAGTTACATTTTAAAGATTGTGACCAATTGTTACAGTATAA
-CGAGGAATCCCTTGAGACAGTATCAAATGGCATTAAGAAATATTTGCCATCATTGATTTG
-CATGGCTATAAATACTATTCATCTGATGAGATAGCCATGTTAAGAAATTGAAAGTATAGC
-ATTAAAGGGGTTTGTAACAGTTGAAAATTATATATTGTATTACTAAAGCAGATAATGGTG
-GTGCACAAACACATCTCATTCAACTCGCTAACCATTTTTGCGTACACCATGATGTTTATG
-TCATTGTAGGCAATCATGGACCAATGATTGAACAACTAGATGCAAGAGTCAATGTAATTA
-TTATCGAACATTTAGTAGGTCCAATTGACTTTAAACAAGATATTTTAGCTGTCAAAGTGT
-TAGCACAGTTATTCTCGAAAATTAAACCTGATGTTATCCATCTACATTCTTCCAAAGCTG
-GAACGGTCGGACGAATTGCGAAGTTCATTTCGAAATCGAAAGACACACGTGTAGTTTTTA
-CTGCGCATGGATGGGCTTTTACAGAGGGTGTTAAACCAGCTAAAAAATTTCTATATCTAG
-TTATTGAAAAATTAATGTCACGTATTACAGATAGCATTATTTGTGTTTCAGATTTCGATA
+>contig00001 len=1129 cov=61.4 corr=0 origname=Contig_1_61.3517 sw=shovill-skesa/1.1.0 date=20220816
+TAGAAATTTTTTAGCTGGTTTAACACCCTCTGTAAAAGCCCATCCATGCGCAGTAAAAAC
+TACACGTGTGTCTTTCGATTTCGAAATGAACTTCGCAATTCGTCCGACCGTTCCAGCTTT
+GGAAGAATGTAGATGGATAACATCAGGTTTAATTTTCGAGAATAACTGTGCTAACACTTT
+GACAGCTAAAATATCTTGTTTAAAGTCAATTGGACCTACTAAATGTTCGATAATAATTAC
+ATTGACTCTTGCATCTAGTTGTTCAATCATTGGTCCATGATTGCCTACAATGACATAAAC
+ATCATGGTGTACGCAAAAATGGTTAGCGAGTTGAATGAGATGTGTTTGTGCACCACCATT
+ATCTGCTTTAGTAATACAATATATAATTTTCAACTGTTACAAACCCCTTTAATGCTATAC
+TTTCAATTTCTTAACATGGCTATCTCATCAGATGAATAGTATTTATAGCCATGCAAATCA
+ATGATGGCAAATATTTCTTAATGCCATTTGATACTGTCTCAAGGGATTCCTCGTTATACT
+GTAACAATTGGTCACAATCTTTAAAATGTAACTTTTATTTAAACTTATTAAGCAAATTAA
+GACTACCTTGAGCCTTCCCCTGTAATAACAACCATCAATGTTCTAATTGATATATATAAT
+TCCATCATTAAGCTACCTTTATGTATATATTTCATGTCATATTTTAATTTTTGTTGTGGT
+GTTAAGTCATATCCACCTTGAATTTGCGCAAGACCTGTTAATCCTGGTGTAACAAGACAT
+CTTTGCTCAAATCCTATTATTTCTGAACTAAATAATTCTACAAATTCTGGACGTTCCGGG
+CGTGGTCCAATAAAACTCATTTCCCCTTTAACAACATTAATTAGTTGTGGTAATTCATCA
+ATGCGTGTTTTACGAATAAACTTCCCGACATTTGTTATACGATCATCATCTTTATCAGCC
+CATTGCGCACCGTTTTTCTCTGCGTTTTTACACATCGAACGTAATTTGTATATTTTAATT
+AATTTACCCATCTTCCCAACTCTAACCTGACTATAAATAGGGTTTCCTGGCGAATCTATG
+ACGATAGCAATGGCGAATATGAACATAATCGGAAATGTTAAAAATAATA
diff -r 2a9baa0c4316 -r ad80238462c1 test-data/shovill.bam
Binary file test-data/shovill.bam has changed
diff -r 2a9baa0c4316 -r ad80238462c1 test-data/shovill_std_log
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/test-data/shovill_std_log	Fri Sep 16 14:39:43 2022 +0000
@@ -0,0 +1,1460 @@
+[shovill] Hello piemari
+[shovill] You ran: /home/piemari/apps/conda/envs/metaphlan/bin/shovill --outdir ../shovill_bam/ --cpus 8 --ram 4 --R1 ../mutant_R1.fastq --R2 ../mutant_R2.fastq --namefmt contig%05d --depth 100 --keepfiles --minlen 0 --mincov 2 --assembler spades --force
+[shovill] This is shovill 1.1.0
+[shovill] Written by Torsten Seemann
+[shovill] Homepage is https://github.com/tseemann/shovill
+[shovill] Operating system is linux
+[shovill] Perl version is v5.32.1
+[shovill] Machine has 32 CPU cores and 251.66 GB RAM
+[shovill] Using bwa - /home/piemari/apps/conda/envs/metaphlan/bin/bwa | Version: 0.7.17-r1188
+[shovill] Using flash - /home/piemari/apps/conda/envs/metaphlan/bin/flash | FLASH v1.2.11
+[shovill] Using java - /home/piemari/apps/conda/envs/metaphlan/bin/java | openjdk version "11.0.1" 2018-10-16 LTS
+[shovill] Using kmc - /home/piemari/apps/conda/envs/metaphlan/bin/kmc | K-Mer Counter (KMC) ver. 3.2.1 (2022-01-04)
+[shovill] Using lighter - /home/piemari/apps/conda/envs/metaphlan/bin/lighter | Lighter v1.1.2
+[shovill] Using megahit - /home/piemari/apps/conda/envs/metaphlan/bin/megahit | MEGAHIT v1.2.9
+[shovill] Using megahit_toolkit - /home/piemari/apps/conda/envs/metaphlan/bin/megahit_toolkit | v1.2.9
+[shovill] Using pigz - /home/piemari/apps/conda/envs/metaphlan/bin/pigz | pigz 2.6
+[shovill] Using pilon - /home/piemari/apps/conda/envs/metaphlan/bin/pilon | Pilon version 1.24 Thu Jan 28 13:00:45 2021 -0500
+[shovill] Using samclip - /home/piemari/apps/conda/envs/metaphlan/bin/samclip | samclip 0.4.0
+[shovill] Using samtools - /home/piemari/apps/conda/envs/metaphlan/bin/samtools | Version: 1.15 (using htslib 1.14)
+[shovill] Using seqtk - /home/piemari/apps/conda/envs/metaphlan/bin/seqtk | Version: 1.3-r106
+[shovill] Using skesa - /home/piemari/apps/conda/envs/metaphlan/bin/skesa | SKESA 2.4.0
+[shovill] Using spades.py - /home/piemari/apps/conda/envs/metaphlan/bin/spades.py | SPAdes genome assembler v3.14.1
+[shovill] Using trimmomatic - /home/piemari/apps/conda/envs/metaphlan/bin/trimmomatic | 0.39
+[shovill] Using velvetg - /home/piemari/apps/conda/envs/metaphlan/bin/velvetg | Version 1.2.10
+[shovill] Using velveth - /home/piemari/apps/conda/envs/metaphlan/bin/velveth | Version 1.2.10
+[shovill] Found spades version: 003014000
+[shovill] Will use spades 003014000 options: --isolate and --merged
+[shovill] Forced overwrite of existing --outdir ../shovill_bam/
+[shovill] Using tempdir: /tmp
+[shovill] Changing into folder: /home/piemari/shovill_bam
+[shovill] Collecting raw read statistics with 'seqtk'
+[shovill] Running: seqtk fqchk -q3 \/home\/piemari\/mutant_R1\.fastq >/tmp/1MILzK1fer 2>&1 | sed 's/^/[seqtk] /' | tee -a shovill.log
+[shovill] Read stats: max_len = 150
+[shovill] Read stats: min_len = 150
+[shovill] Read stats: total_bp = 300000
+[shovill] Read stats: avg_len = 150
+[shovill] Estimating genome size by counting unqiue 21-mers > frequency 10 
+[shovill] Running: kmc -sm -m2 -t8 -k21 -ci10 \/home\/piemari\/mutant_R1\.fastq /tmp/_n_4cOtiee/kmc /tmp/_n_4cOtiee 2>&1 | sed 's/^/[kmc] /' | tee -a shovill.log
+[kmc] **
+[kmc] 
Stage 1: 0%
Stage 1: 100%
+[kmc] 
Stage 2: 0%
Stage 2: 84%
Stage 2: 90%
Stage 2: 94%
Stage 2: 96%
Stage 2: 98%
Stage 2: 99%
Stage 2: 100%
+[kmc] 
+[kmc] 
+[kmc] 1st stage: 0.08264s
+[kmc] 2nd stage: 0.104849s
+[kmc] 3rd stage: 0.002521s
+[kmc] Total    : 0.19001s
+[kmc] Tmp size : 0MB
+[kmc] Tmp size strict memory : 0MB
+[kmc] Tmp total: 0MB
+[kmc] 
+[kmc] Stats:
+[kmc]    No. of k-mers below min. threshold :        34495
+[kmc]    No. of k-mers above max. threshold :            0
+[kmc]    No. of unique k-mers               :        35683
+[kmc]    No. of unique counted k-mers       :         1188
+[kmc]    Total no. of k-mers                :       130000
+[kmc]    Total no. of reads                 :         1000
+[kmc]    Total no. of super-k-mers          :        18576
+[shovill] Using genome size 1188 bp
+[shovill] Estimated sequencing depth: 252 x
+[shovill] Subsampling reads by factor 0.397 to get from 252x to 100x
+[shovill] Running: seqtk sample \/home\/piemari\/mutant_R1\.fastq 0.397 | pigz --fast -c -p 8 > R1.sub.fq.gz 2>&1 | sed 's/^/[seqtk] /' | tee -a shovill.log
+[shovill] Running: seqtk sample \/home\/piemari\/mutant_R2\.fastq 0.397 | pigz --fast -c -p 8 > R2.sub.fq.gz 2>&1 | sed 's/^/[seqtk] /' | tee -a shovill.log
+[shovill] Appending -Xmx4g to _JAVA_OPTIONS
+[shovill] Running: ln -sf R1\.sub\.fq\.gz R1.fq.gz 2>&1 | sed 's/^/[ln] /' | tee -a shovill.log
+[shovill] Running: ln -sf R2\.sub\.fq\.gz R2.fq.gz 2>&1 | sed 's/^/[ln] /' | tee -a shovill.log
+[shovill] Average read length looks like 150 bp
+[shovill] Automatically setting --minlen to 75
+[shovill] Setting k-mer range to (31 .. 112)
+[shovill] Estimated K-mers: 31 51 71 91 111 [kn=5, ks=20, kmin=31, kmax=112]
+[shovill] Using kmers: 31,51,71,91,111
+[shovill] Correcting reads with 'Lighter'
+[shovill] Running: lighter -od . -r R1.fq.gz -r R2.fq.gz -K 32 1188 -t 8 -maxcor 1 2>&1 | sed 's/^/[lighter] /' | tee -a shovill.log
+[lighter] [2022-05-04 12:29:31] =============Start====================
+[lighter] [2022-05-04 12:29:31] Scanning the input files to infer alpha(sampling rate)
+[lighter] [2022-05-04 12:29:31] Average coverage is 103.535 and alpha is 0.068
+[lighter] [2022-05-04 12:29:31] Bad quality threshold is "1"
+[lighter] [2022-05-04 12:29:32] Finish sampling kmers
+[lighter] [2022-05-04 12:29:32] Bloom filter A's false positive rate: 0.264464
+[lighter] [2022-05-04 12:29:32] Finish storing trusted kmers
+[lighter] [2022-05-04 12:29:32] Finish error correction
+[lighter] Processed 820 reads:
+[lighter] 	48 are error-free
+[lighter] 	Corrected 1731 bases(2.242228 corrections for reads with errors)
+[lighter] 	Trimmed 0 reads with average trimmed bases 0.000000
+[lighter] 	Discard 0 reads
+[shovill] Overlapping/stitching PE reads with 'FLASH'
+[shovill] Running: flash -m 20 -M 150 -d . -o flash -z -t 8 R1.cor.fq.gz R2.cor.fq.gz 2>&1 | sed 's/^//' | tee -a shovill.log
+[FLASH] Starting FLASH v1.2.11
+[FLASH] Fast Length Adjustment of SHort reads
+[FLASH]  
+[FLASH] Input files:
+[FLASH]     R1.cor.fq.gz
+[FLASH]     R2.cor.fq.gz
+[FLASH]  
+[FLASH] Output files:
+[FLASH]     ./flash.extendedFrags.fastq.gz
+[FLASH]     ./flash.notCombined_1.fastq.gz
+[FLASH]     ./flash.notCombined_2.fastq.gz
+[FLASH]     ./flash.hist
+[FLASH]     ./flash.histogram
+[FLASH]  
+[FLASH] Parameters:
+[FLASH]     Min overlap:           20
+[FLASH]     Max overlap:           150
+[FLASH]     Max mismatch density:  0.250000
+[FLASH]     Allow "outie" pairs:   false
+[FLASH]     Cap mismatch quals:    false
+[FLASH]     Combiner threads:      8
+[FLASH]     Input format:          FASTQ, phred_offset=33
+[FLASH]     Output format:         FASTQ, phred_offset=33, gzip
+[FLASH]  
+[FLASH] Starting reader and writer threads
+[FLASH] Starting 8 combiner threads
+[FLASH] Processed 410 read pairs
+[FLASH]  
+[FLASH] Read combination statistics:
+[FLASH]     Total pairs:      410
+[FLASH]     Combined pairs:   387
+[FLASH]     Uncombined pairs: 23
+[FLASH]     Percent combined: 94.39%
+[FLASH]  
+[FLASH] Writing histogram files.
+[FLASH]  
+[FLASH] FLASH v1.2.11 complete!
+[FLASH] 0.022 seconds elapsed
+[shovill] Assembling reads with 'spades'
+[shovill] Running: spades.py -1 flash.notCombined_1.fastq.gz -2 flash.notCombined_2.fastq.gz --isolate --threads 8 --memory 4 -o spades --tmp-dir /tmp -k 31,51,71,91,111  --merged flash.extendedFrags.fastq.gz 2>&1 | sed 's/^/[spades] /' | tee -a shovill.log
+[spades] Command line: /home/piemari/apps/conda/envs/metaphlan/bin/spades.py	-1	/home/piemari/shovill_bam/flash.notCombined_1.fastq.gz	-2	/home/piemari/shovill_bam/flash.notCombined_2.fastq.gz	--isolate	--threads	8	--memory	4	-o	/home/piemari/shovill_bam/spades	--tmp-dir	/tmp	-k	31,51,71,91,111	--merged	/home/piemari/shovill_bam/flash.extendedFrags.fastq.gz	
+[spades] 
+[spades] System information:
+[spades]   SPAdes version: 3.14.1
+[spades]   Python version: 3.7.12
+[spades]   OS: Linux-3.10.0-1160.62.1.el7.x86_64-x86_64-with-centos-7.9.2009-Core
+[spades] 
+[spades] Output dir: /home/piemari/shovill_bam/spades
+[spades] Mode: ONLY assembling (without read error correction)
+[spades] Debug mode is turned OFF
+[spades] 
+[spades] Dataset parameters:
+[spades]   Isolate mode
+[spades]   Reads:
+[spades]     Library number: 1, library type: paired-end
+[spades]       orientation: fr
+[spades]       left reads: ['/home/piemari/shovill_bam/flash.notCombined_1.fastq.gz']
+[spades]       right reads: ['/home/piemari/shovill_bam/flash.notCombined_2.fastq.gz']
+[spades]       interlaced reads: not specified
+[spades]       single reads: not specified
+[spades]       merged reads: ['/home/piemari/shovill_bam/flash.extendedFrags.fastq.gz']
+[spades] Assembly parameters:
+[spades]   k: [31, 51, 71, 91, 111]
+[spades]   Repeat resolution is enabled
+[spades]   Mismatch careful mode is turned OFF
+[spades]   MismatchCorrector will be SKIPPED
+[spades]   Coverage cutoff is turned OFF
+[spades] Other parameters:
+[spades]   Dir for temp files: /tmp
+[spades]   Threads: 8
+[spades]   Memory limit (in Gb): 4
+[spades] 
+[spades] 
+[spades] ======= SPAdes pipeline started. Log can be found here: /home/piemari/shovill_bam/spades/spades.log
+[spades] 
+[spades] /home/piemari/shovill_bam/flash.notCombined_1.fastq.gz: max reads length: 150
+[spades] /home/piemari/shovill_bam/flash.notCombined_2.fastq.gz: max reads length: 150
+[spades] Files with merged reads were ignored.
+[spades] 
+[spades] Reads length: 150
+[spades] 
+[spades] 
+[spades] ===== Before start started. 
+[spades] 
+[spades] 
+[spades] ===== Assembling started. 
+[spades] 
+[spades] 
+[spades] ===== K31 started. 
+[spades] 
+[spades] 
+[spades] == Running: /home/piemari/apps/conda/envs/metaphlan/bin/spades-core /home/piemari/shovill_bam/spades/K31/configs/config.info /home/piemari/shovill_bam/spades/K31/configs/isolate_mode.info
+[spades] 
+[spades] WARNING: Try to use logger before create one. Level=INFO. Message=Additional contigs is tmp_contigs.fasta
+[spades]   0:00:00.000     4M / 9M    INFO    General                 (main.cpp                  :  75)   Loaded config from /home/piemari/shovill_bam/spades/K31/configs/config.info
+[spades]   0:00:00.000     4M / 9M    INFO    General                 (main.cpp                  :  75)   Loaded config from /home/piemari/shovill_bam/spades/K31/configs/isolate_mode.info
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (memory_limit.cpp          :  49)   Memory limit set to 4 Gb
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  85)   Starting SPAdes, built from N/A, git revision N/A
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  86)   Maximum k-mer length: 128
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  87)   Assembling dataset (/home/piemari/shovill_bam/spades/dataset.info) with K=31
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  88)   Maximum # of threads to use (adjusted due to OMP capabilities): 8
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 194)   SPAdes started
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 201)   Starting from stage: read_conversion
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 207)   Two-step RR enabled: 0
+[spades]   0:00:00.000     4M / 10M   INFO   StageManager             (stage.cpp                 : 166)   STAGE == Binary Read Conversion
+[spades]   0:00:00.002     4M / 12M   INFO    General                 (read_converter.cpp        :  72)   Converting reads to binary format for library #0 (takes a while)
+[spades]   0:00:00.002     4M / 12M   INFO    General                 (read_converter.cpp        :  73)   Converting paired reads
+[spades]   0:00:00.009    71M / 71M   INFO    General                 (binary_converter.cpp      : 111)   23 reads written
+[spades]   0:00:00.009    47M / 47M   INFO    General                 (read_converter.cpp        :  81)   Converting single reads
+[spades]   0:00:00.011    57M / 57M   INFO    General                 (binary_converter.cpp      : 111)   0 reads written
+[spades]   0:00:00.011    57M / 57M   INFO    General                 (read_converter.cpp        :  87)   Converting merged reads
+[spades]   0:00:00.017    77M / 77M   INFO    General                 (binary_converter.cpp      : 111)   387 reads written
+[spades]   0:00:00.022    17M / 40M   INFO   StageManager             (stage.cpp                 : 166)   STAGE == de Bruijn graph construction
+[spades]   0:00:00.026    17M / 40M   INFO    General                 (construction.cpp          : 150)   Max read length 280
+[spades]   0:00:00.026    17M / 40M   INFO    General                 (construction.cpp          : 153)   Max read length without merged 150
+[spades]   0:00:00.026    17M / 40M   INFO    General                 (construction.cpp          : 156)   Average read length 193.032
+[spades]   0:00:00.026    17M / 40M   INFO    General                 (stage.cpp                 : 113)   PROCEDURE == k+1-mer counting
+[spades]   0:00:00.026    17M / 40M   INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 64 files using 8 threads. This might take a while.
+[spades]   0:00:00.026    17M / 40M   INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.027    17M / 40M   INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166615 Gb
+[spades]   0:00:00.027    17M / 40M   INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 349417
+[spades]   0:00:00.100    71M / 560M  INFO    General                 (kmer_splitters.hpp        : 293)   Used 866 reads
+[spades]   0:00:00.100    71M / 560M  INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.111    71M / 560M  INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 7283 kmers in total.
+[spades]   0:00:00.111    71M / 560M  INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.114    71M / 560M  INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Extension index construction
+[spades]   0:00:00.114    71M / 560M  INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.114    71M / 560M  INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 128 files using 8 threads. This might take a while.
+[spades]   0:00:00.115    71M / 560M  INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.115    71M / 560M  INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166468 Gb
+[spades]   0:00:00.115    71M / 560M  INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 174554
+[spades]   0:00:00.188     2G / 2G    INFO    General                 (kmer_splitters.hpp        : 364)   Processed 7283 kmers
+[spades]   0:00:00.188     2G / 2G    INFO    General                 (kmer_splitters.hpp        : 369)   Used 7283 kmers.
+[spades]   0:00:00.212    85M / 2G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.236    85M / 2G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 7222 kmers in total.
+[spades]   0:00:00.236    85M / 2G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.241    85M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.264    86M / 2G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
+[spades]   0:00:00.266    86M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 12384 bytes occupied (13.7181 bits per kmer).
+[spades]   0:00:00.266    86M / 2G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build:  99)   Building k-mer extensions from k+1-mers
+[spades]   0:00:00.273    86M / 2G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build: 103)   Building k-mer extensions from k+1-mers finished.
+[spades]   0:00:00.274    86M / 2G    INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Early tip clipping
+[spades]   0:00:00.274    86M / 2G    INFO    General                 (construction.cpp          : 293)   Early tip clipper length bound set as (RL - K)
+[spades]   0:00:00.274    86M / 2G    INFO   Early tip clipping       (early_simplification.hpp  :  28)   Early tip clipping
+[spades]   0:00:00.279    86M / 2G    INFO   Early tip clipping       (early_simplification.hpp  :  63)   #tipped junctions: 96
+[spades]   0:00:00.284    86M / 2G    INFO   Early tip clipping       (early_simplification.hpp  :  74)   Clipped tips: 97
+[spades]   0:00:00.284    86M / 2G    INFO   Early tip clipping       (early_simplification.hpp  :  30)   2642 32-mers were removed by early tip clipper
+[spades]   0:00:00.285    86M / 2G    INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Condensing graph
+[spades]   0:00:00.285    86M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 354)   Extracting unbranching paths
+[spades]   0:00:00.287    86M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 373)   Extracting unbranching paths finished. 186 sequences extracted
+[spades]   0:00:00.288    86M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 309)   Collecting perfect loops
+[spades]   0:00:00.289    86M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 342)   Collecting perfect loops finished. 0 loops collected
+[spades]   0:00:00.290    86M / 2G    INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Filling coverage indices (PHM)
+[spades]   0:00:00.290    86M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.290    86M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.301    87M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 7864 bytes occupied (8.6382 bits per kmer).
+[spades]   0:00:00.301    87M / 2G    INFO    General                 (construction.cpp          : 429)   Collecting k-mer coverage information from reads, this takes a while.
+[spades]   0:00:00.310    87M / 2G    INFO    General                 (construction.cpp          : 549)   Filling coverage and flanking coverage from PHM
+[spades]   0:00:00.314    87M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == EC Threshold Finding
+[spades]   0:00:00.314    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 181)   Kmer coverage valley at: 2
+[spades]   0:00:00.315    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 201)   K-mer histogram maximum: 60
+[spades]   0:00:00.315    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 237)   Estimated median coverage: 60. Coverage mad: 7.413
+[spades]   0:00:00.315    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 259)   Fitting coverage model
+[spades]   0:00:00.324    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 2
+[spades]   0:00:00.349    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 4
+[spades]   0:00:00.414    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 8
+[spades]   0:00:00.501    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 16
+[spades]   0:00:00.540    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 309)   Fitted mean coverage: 56.9644. Fitted coverage std. dev: 9.10691
+[spades]   0:00:00.540    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 334)   Probability of erroneous kmer at valley: 1
+[spades]   0:00:00.541    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 358)   Preliminary threshold calculated as: 39
+[spades]   0:00:00.541    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 362)   Threshold adjusted to: 29
+[spades]   0:00:00.541    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 375)   Estimated genome size (ignoring repeats): 1104
+[spades]   0:00:00.541    87M / 2G    INFO    General                 (genomic_info_filler.cpp   :  53)   Mean coverage was calculated as 56.9644
+[spades]   0:00:00.541    87M / 2G    INFO    General                 (genomic_info_filler.cpp   :  68)   EC coverage threshold value was calculated as 29
+[spades]   0:00:00.542    87M / 2G    INFO    General                 (genomic_info_filler.cpp   :  69)   Trusted kmer low bound: 0
+[spades]   0:00:00.542    87M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Raw Simplification
+[spades]   0:00:00.542    87M / 2G    INFO    General                 (simplification.cpp        : 128)   PROCEDURE == InitialCleaning
+[spades]   0:00:00.542    87M / 2G    INFO    General                 (graph_simplification.hpp  : 671)   Flanking coverage based disconnection disabled
+[spades]   0:00:00.542    87M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Self conjugate edge remover
+[spades]   0:00:00.545    87M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Self conjugate edge remover triggered 0 times
+[spades]   0:00:00.545    87M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Simplification
+[spades]   0:00:00.546    87M / 2G    INFO    General                 (simplification.cpp        : 383)   Graph simplification started
+[spades]   0:00:00.546    87M / 2G    INFO    General                 (graph_simplification.hpp  : 643)   Creating parallel br instance
+[spades]   0:00:00.546    87M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 1
+[spades]   0:00:00.546    87M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.550    87M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.550    87M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.557    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 60 times
+[spades]   0:00:00.557    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.559    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 3 times
+[spades]   0:00:00.560    84M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 2
+[spades]   0:00:00.560    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.560    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.561    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.561    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.561    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.561    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.562    84M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 3
+[spades]   0:00:00.562    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.562    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.562    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.562    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.563    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.563    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.563    84M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 4
+[spades]   0:00:00.563    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.563    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.564    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.564    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.564    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.564    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.564    84M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 5
+[spades]   0:00:00.564    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.565    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.565    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.565    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.565    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.565    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.566    84M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 6
+[spades]   0:00:00.566    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.566    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.566    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.566    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.567    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.567    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.567    84M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 7
+[spades]   0:00:00.567    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.567    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.568    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.568    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.568    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.568    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.568    84M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 8
+[spades]   0:00:00.568    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.569    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.569    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.569    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.569    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.569    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.570    84M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 9
+[spades]   0:00:00.570    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.570    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.570    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.570    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.571    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.571    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.571    84M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 10
+[spades]   0:00:00.571    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.571    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.571    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.572    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.572    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.572    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.572    84M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 11
+[spades]   0:00:00.572    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.575    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.575    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.576    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.576    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.576    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.576    84M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Simplification Cleanup
+[spades]   0:00:00.576    84M / 2G    INFO    General                 (simplification.cpp        : 196)   PROCEDURE == Post simplification
+[spades]   0:00:00.577    84M / 2G    INFO    General                 (graph_simplification.hpp  : 456)   Disconnection of relatively low covered edges disabled
+[spades]   0:00:00.577    84M / 2G    INFO    General                 (graph_simplification.hpp  : 493)   Complex tip clipping disabled
+[spades]   0:00:00.577    84M / 2G    INFO    General                 (graph_simplification.hpp  : 643)   Creating parallel br instance
+[spades]   0:00:00.577    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.578    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.578    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.578    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.578    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.579    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.579    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.579    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.579    84M / 2G    INFO    General                 (simplification.cpp        : 343)   Disrupting self-conjugate edges
+[spades]   0:00:00.579    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Removing isolated edges
+[spades]   0:00:00.580    84M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Removing isolated edges triggered 1 times
+[spades]   0:00:00.580    84M / 2G    INFO    General                 (simplification.cpp        : 496)   Counting average coverage
+[spades]   0:00:00.580    84M / 2G    INFO    General                 (simplification.cpp        : 502)   Average coverage = 55.1872
+[spades]   0:00:00.580    84M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Contig Output
+[spades]   0:00:00.583    84M / 2G    INFO    General                 (read_converter.cpp        : 102)   Outputting contigs to /home/piemari/shovill_bam/spades/K31/simplified_contigs
+[spades]   0:00:00.585    84M / 2G    INFO    General                 (binary_converter.cpp      : 111)   1 reads written
+[spades]   0:00:00.589    84M / 2G    INFO    General                 (pipeline.cpp              : 259)   SPAdes finished
+[spades]   0:00:00.590    84M / 2G    INFO    General                 (main.cpp                  : 107)   Assembling time: 0 hours 0 minutes 0 seconds
+[spades] 
+[spades] ===== K31 finished. 
+[spades] 
+[spades] 
+[spades] ===== K51 started. 
+[spades] 
+[spades] 
+[spades] == Running: /home/piemari/apps/conda/envs/metaphlan/bin/spades-core /home/piemari/shovill_bam/spades/K51/configs/config.info /home/piemari/shovill_bam/spades/K51/configs/isolate_mode.info
+[spades] 
+[spades] WARNING: Try to use logger before create one. Level=INFO. Message=Additional contigs is /home/piemari/shovill_bam/spades/K31/simplified_contigs
+[spades]   0:00:00.000     4M / 9M    INFO    General                 (main.cpp                  :  75)   Loaded config from /home/piemari/shovill_bam/spades/K51/configs/config.info
+[spades]   0:00:00.000     4M / 9M    INFO    General                 (main.cpp                  :  75)   Loaded config from /home/piemari/shovill_bam/spades/K51/configs/isolate_mode.info
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (memory_limit.cpp          :  49)   Memory limit set to 4 Gb
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  85)   Starting SPAdes, built from N/A, git revision N/A
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  86)   Maximum k-mer length: 128
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  87)   Assembling dataset (/home/piemari/shovill_bam/spades/dataset.info) with K=51
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  88)   Maximum # of threads to use (adjusted due to OMP capabilities): 8
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 194)   SPAdes started
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 201)   Starting from stage: read_conversion
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 207)   Two-step RR enabled: 0
+[spades]   0:00:00.000     4M / 10M   INFO   StageManager             (stage.cpp                 : 166)   STAGE == Binary Read Conversion
+[spades]   0:00:00.001     4M / 12M   INFO    General                 (read_converter.cpp        :  53)   Binary reads detected
+[spades]   0:00:00.002     4M / 14M   INFO   StageManager             (stage.cpp                 : 166)   STAGE == de Bruijn graph construction
+[spades]   0:00:00.002     4M / 14M   INFO    General                 (construction.cpp          : 115)   Contigs from previous K will be used: /home/piemari/shovill_bam/spades/K31/simplified_contigs
+[spades]   0:00:00.007     4M / 14M   INFO    General                 (construction.cpp          : 150)   Max read length 280
+[spades]   0:00:00.007     4M / 14M   INFO    General                 (construction.cpp          : 153)   Max read length without merged 150
+[spades]   0:00:00.007     4M / 14M   INFO    General                 (construction.cpp          : 156)   Average read length 193.032
+[spades]   0:00:00.007     4M / 14M   INFO    General                 (stage.cpp                 : 113)   PROCEDURE == k+1-mer counting
+[spades]   0:00:00.007     4M / 14M   INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 64 files using 8 threads. This might take a while.
+[spades]   0:00:00.007     4M / 14M   INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.007     4M / 14M   INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166632 Gb
+[spades]   0:00:00.007     4M / 14M   INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 174726
+[spades]   0:00:00.085    84M / 556M  INFO    General                 (kmer_splitters.hpp        : 293)   Used 868 reads
+[spades]   0:00:00.085    84M / 556M  INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.102    84M / 556M  INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 8238 kmers in total.
+[spades]   0:00:00.102    84M / 556M  INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.106    84M / 556M  INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Extension index construction
+[spades]   0:00:00.106    84M / 556M  INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.106    84M / 556M  INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 128 files using 8 threads. This might take a while.
+[spades]   0:00:00.106    84M / 556M  INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.106    84M / 556M  INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166509 Gb
+[spades]   0:00:00.107    84M / 556M  INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 87298
+[spades]   0:00:00.181     2G / 2G    INFO    General                 (kmer_splitters.hpp        : 364)   Processed 8238 kmers
+[spades]   0:00:00.181     2G / 2G    INFO    General                 (kmer_splitters.hpp        : 369)   Used 8238 kmers.
+[spades]   0:00:00.203    97M / 2G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.220    97M / 2G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 8201 kmers in total.
+[spades]   0:00:00.221    97M / 2G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.226    97M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.252    92M / 2G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
+[spades]   0:00:00.253    92M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 12872 bytes occupied (12.5565 bits per kmer).
+[spades]   0:00:00.254    92M / 2G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build:  99)   Building k-mer extensions from k+1-mers
+[spades]   0:00:00.257    92M / 2G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build: 103)   Building k-mer extensions from k+1-mers finished.
+[spades]   0:00:00.258    92M / 2G    INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Early tip clipping
+[spades]   0:00:00.258    92M / 2G    INFO    General                 (construction.cpp          : 293)   Early tip clipper length bound set as (RL - K)
+[spades]   0:00:00.259    92M / 2G    INFO   Early tip clipping       (early_simplification.hpp  :  28)   Early tip clipping
+[spades]   0:00:00.263    92M / 2G    INFO   Early tip clipping       (early_simplification.hpp  :  63)   #tipped junctions: 115
+[spades]   0:00:00.268    92M / 2G    INFO   Early tip clipping       (early_simplification.hpp  :  74)   Clipped tips: 116
+[spades]   0:00:00.268    92M / 2G    INFO   Early tip clipping       (early_simplification.hpp  :  30)   3952 52-mers were removed by early tip clipper
+[spades]   0:00:00.268    92M / 2G    INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Condensing graph
+[spades]   0:00:00.269    92M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 354)   Extracting unbranching paths
+[spades]   0:00:00.272    92M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 373)   Extracting unbranching paths finished. 118 sequences extracted
+[spades]   0:00:00.273    92M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 309)   Collecting perfect loops
+[spades]   0:00:00.274    92M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 342)   Collecting perfect loops finished. 0 loops collected
+[spades]   0:00:00.274    92M / 2G    INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Filling coverage indices (PHM)
+[spades]   0:00:00.275    92M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.275    92M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.286    92M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 8280 bytes occupied (8.04079 bits per kmer).
+[spades]   0:00:00.286    92M / 2G    INFO    General                 (construction.cpp          : 429)   Collecting k-mer coverage information from reads, this takes a while.
+[spades]   0:00:00.294    92M / 2G    INFO    General                 (construction.cpp          : 549)   Filling coverage and flanking coverage from PHM
+[spades]   0:00:00.297    92M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == EC Threshold Finding
+[spades]   0:00:00.297    92M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 181)   Kmer coverage valley at: 2
+[spades]   0:00:00.297    92M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 201)   K-mer histogram maximum: 51
+[spades]   0:00:00.298    92M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 237)   Estimated median coverage: 51. Coverage mad: 7.413
+[spades]   0:00:00.298    92M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 259)   Fitting coverage model
+[spades]   0:00:00.306    92M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 2
+[spades]   0:00:00.326    92M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 4
+[spades]   0:00:00.371    92M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 8
+[spades]   0:00:00.392    92M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 309)   Fitted mean coverage: 48.7323. Fitted coverage std. dev: 7.8967
+[spades]   0:00:00.392    92M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 334)   Probability of erroneous kmer at valley: 1
+[spades]   0:00:00.393    92M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 358)   Preliminary threshold calculated as: 33
+[spades]   0:00:00.393    92M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 362)   Threshold adjusted to: 25
+[spades]   0:00:00.393    92M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 375)   Estimated genome size (ignoring repeats): 1099
+[spades]   0:00:00.393    92M / 2G    INFO    General                 (genomic_info_filler.cpp   :  53)   Mean coverage was calculated as 48.7323
+[spades]   0:00:00.393    92M / 2G    INFO    General                 (genomic_info_filler.cpp   :  68)   EC coverage threshold value was calculated as 25
+[spades]   0:00:00.394    92M / 2G    INFO    General                 (genomic_info_filler.cpp   :  69)   Trusted kmer low bound: 0
+[spades]   0:00:00.394    92M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Raw Simplification
+[spades]   0:00:00.394    92M / 2G    INFO    General                 (simplification.cpp        : 128)   PROCEDURE == InitialCleaning
+[spades]   0:00:00.394    92M / 2G    INFO    General                 (graph_simplification.hpp  : 671)   Flanking coverage based disconnection disabled
+[spades]   0:00:00.394    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Self conjugate edge remover
+[spades]   0:00:00.397    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Self conjugate edge remover triggered 0 times
+[spades]   0:00:00.397    92M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Simplification
+[spades]   0:00:00.398    92M / 2G    INFO    General                 (simplification.cpp        : 383)   Graph simplification started
+[spades]   0:00:00.398    92M / 2G    INFO    General                 (graph_simplification.hpp  : 643)   Creating parallel br instance
+[spades]   0:00:00.398    92M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 1
+[spades]   0:00:00.399    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.399    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.399    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.401    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 40 times
+[spades]   0:00:00.402    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.402    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.402    92M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 2
+[spades]   0:00:00.403    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.403    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.403    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.404    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.404    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.404    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.405    92M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 3
+[spades]   0:00:00.405    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.405    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.405    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.405    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.405    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.406    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.406    92M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 4
+[spades]   0:00:00.406    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.406    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.406    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.406    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.407    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.407    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.407    92M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 5
+[spades]   0:00:00.407    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.407    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.407    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.408    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.408    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.408    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.408    92M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 6
+[spades]   0:00:00.408    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.408    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.408    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.409    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.409    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.409    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.409    92M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 7
+[spades]   0:00:00.409    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.409    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.410    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.410    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.410    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.410    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.410    92M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 8
+[spades]   0:00:00.410    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.411    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.411    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.411    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.411    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.411    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.411    92M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 9
+[spades]   0:00:00.412    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.412    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.412    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.412    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.412    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.412    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.413    92M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 10
+[spades]   0:00:00.413    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.413    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.413    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.413    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.413    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.413    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.414    92M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 11
+[spades]   0:00:00.414    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.416    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.416    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.416    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.417    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.417    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.417    92M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Simplification Cleanup
+[spades]   0:00:00.418    92M / 2G    INFO    General                 (simplification.cpp        : 196)   PROCEDURE == Post simplification
+[spades]   0:00:00.418    92M / 2G    INFO    General                 (graph_simplification.hpp  : 456)   Disconnection of relatively low covered edges disabled
+[spades]   0:00:00.418    92M / 2G    INFO    General                 (graph_simplification.hpp  : 493)   Complex tip clipping disabled
+[spades]   0:00:00.419    92M / 2G    INFO    General                 (graph_simplification.hpp  : 643)   Creating parallel br instance
+[spades]   0:00:00.419    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.419    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.420    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.420    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.420    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.421    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.421    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.421    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.421    92M / 2G    INFO    General                 (simplification.cpp        : 343)   Disrupting self-conjugate edges
+[spades]   0:00:00.422    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Removing isolated edges
+[spades]   0:00:00.422    92M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Removing isolated edges triggered 2 times
+[spades]   0:00:00.422    92M / 2G    INFO    General                 (simplification.cpp        : 496)   Counting average coverage
+[spades]   0:00:00.423    92M / 2G    INFO    General                 (simplification.cpp        : 502)   Average coverage = 47.8689
+[spades]   0:00:00.423    92M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Contig Output
+[spades]   0:00:00.424    92M / 2G    INFO    General                 (read_converter.cpp        : 102)   Outputting contigs to /home/piemari/shovill_bam/spades/K51/simplified_contigs
+[spades]   0:00:00.426    92M / 2G    INFO    General                 (binary_converter.cpp      : 111)   1 reads written
+[spades]   0:00:00.433    92M / 2G    INFO    General                 (pipeline.cpp              : 259)   SPAdes finished
+[spades]   0:00:00.433    92M / 2G    INFO    General                 (main.cpp                  : 107)   Assembling time: 0 hours 0 minutes 0 seconds
+[spades] 
+[spades] ===== K51 finished. 
+[spades] 
+[spades] 
+[spades] ===== K71 started. 
+[spades] 
+[spades] 
+[spades] == Running: /home/piemari/apps/conda/envs/metaphlan/bin/spades-core /home/piemari/shovill_bam/spades/K71/configs/config.info /home/piemari/shovill_bam/spades/K71/configs/isolate_mode.info
+[spades] 
+[spades] WARNING: Try to use logger before create one. Level=INFO. Message=Additional contigs is /home/piemari/shovill_bam/spades/K51/simplified_contigs
+[spades]   0:00:00.000     4M / 9M    INFO    General                 (main.cpp                  :  75)   Loaded config from /home/piemari/shovill_bam/spades/K71/configs/config.info
+[spades]   0:00:00.000     4M / 9M    INFO    General                 (main.cpp                  :  75)   Loaded config from /home/piemari/shovill_bam/spades/K71/configs/isolate_mode.info
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (memory_limit.cpp          :  49)   Memory limit set to 4 Gb
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  85)   Starting SPAdes, built from N/A, git revision N/A
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  86)   Maximum k-mer length: 128
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  87)   Assembling dataset (/home/piemari/shovill_bam/spades/dataset.info) with K=71
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  88)   Maximum # of threads to use (adjusted due to OMP capabilities): 8
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 194)   SPAdes started
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 201)   Starting from stage: read_conversion
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 207)   Two-step RR enabled: 0
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 218)   Will need read mapping, kmer mapper will be attached
+[spades]   0:00:00.000     4M / 10M   INFO   StageManager             (stage.cpp                 : 166)   STAGE == Binary Read Conversion
+[spades]   0:00:00.001     4M / 12M   INFO    General                 (read_converter.cpp        :  53)   Binary reads detected
+[spades]   0:00:00.001     4M / 14M   INFO   StageManager             (stage.cpp                 : 166)   STAGE == de Bruijn graph construction
+[spades]   0:00:00.001     4M / 14M   INFO    General                 (construction.cpp          : 115)   Contigs from previous K will be used: /home/piemari/shovill_bam/spades/K51/simplified_contigs
+[spades]   0:00:00.006     4M / 14M   INFO    General                 (construction.cpp          : 150)   Max read length 280
+[spades]   0:00:00.006     4M / 14M   INFO    General                 (construction.cpp          : 153)   Max read length without merged 150
+[spades]   0:00:00.006     4M / 14M   INFO    General                 (construction.cpp          : 156)   Average read length 193.032
+[spades]   0:00:00.006     4M / 14M   INFO    General                 (stage.cpp                 : 113)   PROCEDURE == k+1-mer counting
+[spades]   0:00:00.006     4M / 14M   INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 64 files using 8 threads. This might take a while.
+[spades]   0:00:00.007     4M / 14M   INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.007     4M / 14M   INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166632 Gb
+[spades]   0:00:00.007     4M / 14M   INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 116484
+[spades]   0:00:00.088    81M / 554M  INFO    General                 (kmer_splitters.hpp        : 293)   Used 868 reads
+[spades]   0:00:00.088    81M / 554M  INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.100    83M / 554M  INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 8725 kmers in total.
+[spades]   0:00:00.100    83M / 554M  INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.104    83M / 554M  INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Extension index construction
+[spades]   0:00:00.104    83M / 554M  INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.104    83M / 554M  INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 128 files using 8 threads. This might take a while.
+[spades]   0:00:00.104    83M / 554M  INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.104    83M / 554M  INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166542 Gb
+[spades]   0:00:00.104    83M / 554M  INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 58210
+[spades]   0:00:00.177     2G / 2G    INFO    General                 (kmer_splitters.hpp        : 364)   Processed 8725 kmers
+[spades]   0:00:00.177     2G / 2G    INFO    General                 (kmer_splitters.hpp        : 369)   Used 8725 kmers.
+[spades]   0:00:00.200    89M / 2G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.218    89M / 2G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 8713 kmers in total.
+[spades]   0:00:00.218    89M / 2G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.224    89M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.249    87M / 2G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
+[spades]   0:00:00.251    87M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 13120 bytes occupied (12.0464 bits per kmer).
+[spades]   0:00:00.251    87M / 2G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build:  99)   Building k-mer extensions from k+1-mers
+[spades]   0:00:00.254    87M / 2G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build: 103)   Building k-mer extensions from k+1-mers finished.
+[spades]   0:00:00.255    87M / 2G    INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Condensing graph
+[spades]   0:00:00.255    87M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 354)   Extracting unbranching paths
+[spades]   0:00:00.260    87M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 373)   Extracting unbranching paths finished. 308 sequences extracted
+[spades]   0:00:00.266    87M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 309)   Collecting perfect loops
+[spades]   0:00:00.271    87M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 342)   Collecting perfect loops finished. 0 loops collected
+[spades]   0:00:00.280    87M / 2G    INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Filling coverage indices (PHM)
+[spades]   0:00:00.281    87M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.281    87M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.294    87M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 8536 bytes occupied (7.8267 bits per kmer).
+[spades]   0:00:00.294    87M / 2G    INFO    General                 (construction.cpp          : 429)   Collecting k-mer coverage information from reads, this takes a while.
+[spades]   0:00:00.300    87M / 2G    INFO    General                 (construction.cpp          : 549)   Filling coverage and flanking coverage from PHM
+[spades]   0:00:00.307    87M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == EC Threshold Finding
+[spades]   0:00:00.308    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 181)   Kmer coverage valley at: 2
+[spades]   0:00:00.308    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 201)   K-mer histogram maximum: 44
+[spades]   0:00:00.308    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 237)   Estimated median coverage: 44. Coverage mad: 7.413
+[spades]   0:00:00.308    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 259)   Fitting coverage model
+[spades]   0:00:00.315    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 2
+[spades]   0:00:00.334    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 4
+[spades]   0:00:00.377    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 8
+[spades]   0:00:00.421    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 309)   Fitted mean coverage: 40.9755. Fitted coverage std. dev: 6.3525
+[spades]   0:00:00.421    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 334)   Probability of erroneous kmer at valley: 1
+[spades]   0:00:00.421    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 358)   Preliminary threshold calculated as: 28
+[spades]   0:00:00.421    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 362)   Threshold adjusted to: 21
+[spades]   0:00:00.422    87M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 375)   Estimated genome size (ignoring repeats): 1088
+[spades]   0:00:00.422    87M / 2G    INFO    General                 (genomic_info_filler.cpp   :  53)   Mean coverage was calculated as 40.9755
+[spades]   0:00:00.422    87M / 2G    INFO    General                 (genomic_info_filler.cpp   :  68)   EC coverage threshold value was calculated as 21
+[spades]   0:00:00.422    87M / 2G    INFO    General                 (genomic_info_filler.cpp   :  69)   Trusted kmer low bound: 0
+[spades]   0:00:00.423    87M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Gap Closer
+[spades]   0:00:00.423    87M / 2G    INFO    General                 (graph_pack.hpp            : 105)   Index refill
+[spades]   0:00:00.423    87M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.423    87M / 2G    INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 128 files using 8 threads. This might take a while.
+[spades]   0:00:00.424    87M / 2G    INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.424    87M / 2G    INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166486 Gb
+[spades]   0:00:00.424    87M / 2G    INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 58191
+[spades]   0:00:00.513     2G / 2G    INFO    General                 (edge_index_builders.hpp   :  82)   Used 616 sequences.
+[spades]   0:00:00.531    94M / 2G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.562    94M / 2G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 8725 kmers in total.
+[spades]   0:00:00.563    94M / 2G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.568    94M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.586    89M / 2G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
+[spades]   0:00:00.588    89M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 13104 bytes occupied (12.0151 bits per kmer).
+[spades]   0:00:00.588    89M / 2G    INFO    General                 (edge_index_builders.hpp   : 107)   Collecting edge information from graph, this takes a while.
+[spades]   0:00:00.592    89M / 2G    INFO    General                 (edge_index.hpp            :  92)   Index refilled
+[spades]   0:00:00.595    89M / 2G    INFO    General                 (gap_closer.cpp            : 147)   Preparing shift maps
+[spades]   0:00:00.596    89M / 2G    INFO    General                 (gap_closer.cpp            : 107)   Processing paired reads (takes a while)
+[spades]   0:00:00.598    89M / 2G    INFO    General                 (gap_closer.cpp            : 126)   Used 23 paired reads
+[spades]   0:00:00.598    89M / 2G    INFO    General                 (gap_closer.cpp            : 128)   Merging paired indices
+[spades]   0:00:00.598    89M / 2G    INFO   GapCloser                (gap_closer.cpp            : 332)   Closing short gaps
+[spades]   0:00:00.599    89M / 2G    INFO   GapCloser                (gap_closer.cpp            : 364)   Closing short gaps complete: filled 0 gaps after checking 0 candidates
+[spades]   0:00:00.599    89M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Raw Simplification
+[spades]   0:00:00.599    89M / 2G    INFO    General                 (simplification.cpp        : 128)   PROCEDURE == InitialCleaning
+[spades]   0:00:00.600    89M / 2G    INFO    General                 (graph_simplification.hpp  : 671)   Flanking coverage based disconnection disabled
+[spades]   0:00:00.600    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Self conjugate edge remover
+[spades]   0:00:00.600    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Self conjugate edge remover triggered 0 times
+[spades]   0:00:00.600    89M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Simplification
+[spades]   0:00:00.601    89M / 2G    INFO    General                 (simplification.cpp        : 383)   Graph simplification started
+[spades]   0:00:00.601    89M / 2G    INFO    General                 (graph_simplification.hpp  : 643)   Creating parallel br instance
+[spades]   0:00:00.601    89M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 1
+[spades]   0:00:00.601    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.603    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 128 times
+[spades]   0:00:00.603    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.607    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 19 times
+[spades]   0:00:00.607    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.609    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.609    89M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 2
+[spades]   0:00:00.609    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.610    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.610    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.610    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.610    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.611    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.611    89M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 3
+[spades]   0:00:00.611    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.611    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.611    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.612    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.612    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.612    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.612    89M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 4
+[spades]   0:00:00.612    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.612    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.613    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.613    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.613    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.613    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.613    89M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 5
+[spades]   0:00:00.613    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.614    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.614    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.614    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.614    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.614    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.614    89M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 6
+[spades]   0:00:00.615    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.615    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.615    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.615    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.615    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.615    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.616    89M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 7
+[spades]   0:00:00.616    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.616    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.616    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.616    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.617    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.617    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.617    89M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 8
+[spades]   0:00:00.617    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.617    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.617    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.618    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.618    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.618    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.618    89M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 9
+[spades]   0:00:00.618    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.618    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.619    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.619    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.619    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.619    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.619    89M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 10
+[spades]   0:00:00.619    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.620    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.620    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.620    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.620    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.620    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.620    89M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 11
+[spades]   0:00:00.621    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.623    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.623    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.623    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.623    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.624    89M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.624    89M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Gap Closer
+[spades]   0:00:00.624    89M / 2G    INFO    General                 (graph_pack.hpp            : 105)   Index refill
+[spades]   0:00:00.625    89M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.625    89M / 2G    INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 128 files using 8 threads. This might take a while.
+[spades]   0:00:00.625    89M / 2G    INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.626    89M / 2G    INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166471 Gb
+[spades]   0:00:00.626    89M / 2G    INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 58185
+[spades]   0:00:00.681     2G / 2G    INFO    General                 (edge_index_builders.hpp   :  82)   Used 14 sequences.
+[spades]   0:00:00.688   100M / 2G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.704   100M / 2G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 1720 kmers in total.
+[spades]   0:00:00.704   100M / 2G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.709   100M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.728   100M / 2G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
+[spades]   0:00:00.729   100M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 10088 bytes occupied (46.9209 bits per kmer).
+[spades]   0:00:00.730   100M / 2G    INFO    General                 (edge_index_builders.hpp   : 107)   Collecting edge information from graph, this takes a while.
+[spades]   0:00:00.733   100M / 2G    INFO    General                 (edge_index.hpp            :  92)   Index refilled
+[spades]   0:00:00.735   100M / 2G    INFO    General                 (gap_closer.cpp            : 147)   Preparing shift maps
+[spades]   0:00:00.735   100M / 2G    INFO    General                 (gap_closer.cpp            : 107)   Processing paired reads (takes a while)
+[spades]   0:00:00.738   100M / 2G    INFO    General                 (gap_closer.cpp            : 126)   Used 23 paired reads
+[spades]   0:00:00.739   100M / 2G    INFO    General                 (gap_closer.cpp            : 128)   Merging paired indices
+[spades]   0:00:00.739   100M / 2G    INFO   GapCloser                (gap_closer.cpp            : 332)   Closing short gaps
+[spades]   0:00:00.739   100M / 2G    INFO   GapCloser                (gap_closer.cpp            : 364)   Closing short gaps complete: filled 0 gaps after checking 0 candidates
+[spades]   0:00:00.743   100M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Simplification Cleanup
+[spades]   0:00:00.744   100M / 2G    INFO    General                 (simplification.cpp        : 196)   PROCEDURE == Post simplification
+[spades]   0:00:00.744   100M / 2G    INFO    General                 (graph_simplification.hpp  : 456)   Disconnection of relatively low covered edges disabled
+[spades]   0:00:00.744   100M / 2G    INFO    General                 (graph_simplification.hpp  : 493)   Complex tip clipping disabled
+[spades]   0:00:00.744   100M / 2G    INFO    General                 (graph_simplification.hpp  : 643)   Creating parallel br instance
+[spades]   0:00:00.745   100M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.748   100M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.748   100M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.753   100M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.753   100M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.760   100M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.761   100M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.766   100M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.766   100M / 2G    INFO    General                 (simplification.cpp        : 343)   Disrupting self-conjugate edges
+[spades]   0:00:00.766   100M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Removing isolated edges
+[spades]   0:00:00.770   100M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Removing isolated edges triggered 6 times
+[spades]   0:00:00.770   100M / 2G    INFO    General                 (simplification.cpp        : 496)   Counting average coverage
+[spades]   0:00:00.770   100M / 2G    INFO    General                 (simplification.cpp        : 502)   Average coverage = 39.6025
+[spades]   0:00:00.770   100M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Contig Output
+[spades]   0:00:00.771   100M / 2G    INFO    General                 (read_converter.cpp        : 102)   Outputting contigs to /home/piemari/shovill_bam/spades/K71/simplified_contigs
+[spades]   0:00:00.775   100M / 2G    INFO    General                 (binary_converter.cpp      : 111)   1 reads written
+[spades]   0:00:00.780   100M / 2G    INFO    General                 (pipeline.cpp              : 259)   SPAdes finished
+[spades]   0:00:00.781   100M / 2G    INFO    General                 (main.cpp                  : 107)   Assembling time: 0 hours 0 minutes 0 seconds
+[spades] 
+[spades] ===== K71 finished. 
+[spades] 
+[spades] 
+[spades] ===== K91 started. 
+[spades] 
+[spades] 
+[spades] == Running: /home/piemari/apps/conda/envs/metaphlan/bin/spades-core /home/piemari/shovill_bam/spades/K91/configs/config.info /home/piemari/shovill_bam/spades/K91/configs/isolate_mode.info
+[spades] 
+[spades] WARNING: Try to use logger before create one. Level=INFO. Message=Additional contigs is /home/piemari/shovill_bam/spades/K71/simplified_contigs
+[spades]   0:00:00.000     4M / 9M    INFO    General                 (main.cpp                  :  75)   Loaded config from /home/piemari/shovill_bam/spades/K91/configs/config.info
+[spades]   0:00:00.000     4M / 9M    INFO    General                 (main.cpp                  :  75)   Loaded config from /home/piemari/shovill_bam/spades/K91/configs/isolate_mode.info
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (memory_limit.cpp          :  49)   Memory limit set to 4 Gb
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  85)   Starting SPAdes, built from N/A, git revision N/A
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  86)   Maximum k-mer length: 128
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  87)   Assembling dataset (/home/piemari/shovill_bam/spades/dataset.info) with K=91
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  88)   Maximum # of threads to use (adjusted due to OMP capabilities): 8
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 194)   SPAdes started
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 201)   Starting from stage: read_conversion
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 207)   Two-step RR enabled: 0
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 218)   Will need read mapping, kmer mapper will be attached
+[spades]   0:00:00.000     4M / 10M   INFO   StageManager             (stage.cpp                 : 166)   STAGE == Binary Read Conversion
+[spades]   0:00:00.002     4M / 12M   INFO    General                 (read_converter.cpp        :  53)   Binary reads detected
+[spades]   0:00:00.003     4M / 16M   INFO   StageManager             (stage.cpp                 : 166)   STAGE == de Bruijn graph construction
+[spades]   0:00:00.003     4M / 16M   INFO    General                 (construction.cpp          : 115)   Contigs from previous K will be used: /home/piemari/shovill_bam/spades/K71/simplified_contigs
+[spades]   0:00:00.014     4M / 16M   INFO    General                 (construction.cpp          : 150)   Max read length 280
+[spades]   0:00:00.014     4M / 16M   INFO    General                 (construction.cpp          : 153)   Max read length without merged 150
+[spades]   0:00:00.014     4M / 16M   INFO    General                 (construction.cpp          : 156)   Average read length 193.032
+[spades]   0:00:00.014     4M / 16M   INFO    General                 (stage.cpp                 : 113)   PROCEDURE == k+1-mer counting
+[spades]   0:00:00.014     4M / 16M   INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 64 files using 8 threads. This might take a while.
+[spades]   0:00:00.014     4M / 16M   INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.014     4M / 16M   INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166632 Gb
+[spades]   0:00:00.015     4M / 16M   INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 116484
+[spades]   0:00:00.092    83M / 554M  INFO    General                 (kmer_splitters.hpp        : 293)   Used 868 reads
+[spades]   0:00:00.092    83M / 554M  INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.104    83M / 554M  INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 8793 kmers in total.
+[spades]   0:00:00.105    83M / 554M  INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.108    83M / 554M  INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Extension index construction
+[spades]   0:00:00.108    83M / 554M  INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.108    83M / 554M  INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 128 files using 8 threads. This might take a while.
+[spades]   0:00:00.108    83M / 554M  INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.108    83M / 554M  INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166534 Gb
+[spades]   0:00:00.108    83M / 554M  INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 58208
+[spades]   0:00:00.181     2G / 2G    INFO    General                 (kmer_splitters.hpp        : 364)   Processed 8793 kmers
+[spades]   0:00:00.181     2G / 2G    INFO    General                 (kmer_splitters.hpp        : 369)   Used 8793 kmers.
+[spades]   0:00:00.204    98M / 2G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.221    98M / 2G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 8798 kmers in total.
+[spades]   0:00:00.221    98M / 2G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.227    98M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.250    96M / 2G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
+[spades]   0:00:00.252    96M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 13136 bytes occupied (11.9445 bits per kmer).
+[spades]   0:00:00.252    96M / 2G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build:  99)   Building k-mer extensions from k+1-mers
+[spades]   0:00:00.256    96M / 2G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build: 103)   Building k-mer extensions from k+1-mers finished.
+[spades]   0:00:00.256    96M / 2G    INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Condensing graph
+[spades]   0:00:00.256    96M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 354)   Extracting unbranching paths
+[spades]   0:00:00.262    96M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 373)   Extracting unbranching paths finished. 294 sequences extracted
+[spades]   0:00:00.263    96M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 309)   Collecting perfect loops
+[spades]   0:00:00.264    96M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 342)   Collecting perfect loops finished. 0 loops collected
+[spades]   0:00:00.265    96M / 2G    INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Filling coverage indices (PHM)
+[spades]   0:00:00.265    96M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.265    96M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.276    97M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 8576 bytes occupied (7.80257 bits per kmer).
+[spades]   0:00:00.276    97M / 2G    INFO    General                 (construction.cpp          : 429)   Collecting k-mer coverage information from reads, this takes a while.
+[spades]   0:00:00.280    97M / 2G    INFO    General                 (construction.cpp          : 549)   Filling coverage and flanking coverage from PHM
+[spades]   0:00:00.282    97M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == EC Threshold Finding
+[spades]   0:00:00.282    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 181)   Kmer coverage valley at: 2
+[spades]   0:00:00.283    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 201)   K-mer histogram maximum: 32
+[spades]   0:00:00.283    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 237)   Estimated median coverage: 33. Coverage mad: 5.9304
+[spades]   0:00:00.283    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 259)   Fitting coverage model
+[spades]   0:00:00.289    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 2
+[spades]   0:00:00.304    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 4
+[spades]   0:00:00.356    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 8
+[spades]   0:00:00.392    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 309)   Fitted mean coverage: 33.4369. Fitted coverage std. dev: 4.99367
+[spades]   0:00:00.392    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 334)   Probability of erroneous kmer at valley: 1
+[spades]   0:00:00.393    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 358)   Preliminary threshold calculated as: 23
+[spades]   0:00:00.393    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 362)   Threshold adjusted to: 17
+[spades]   0:00:00.393    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 375)   Estimated genome size (ignoring repeats): 1078
+[spades]   0:00:00.393    97M / 2G    INFO    General                 (genomic_info_filler.cpp   :  53)   Mean coverage was calculated as 33.4369
+[spades]   0:00:00.393    97M / 2G    INFO    General                 (genomic_info_filler.cpp   :  68)   EC coverage threshold value was calculated as 17
+[spades]   0:00:00.393    97M / 2G    INFO    General                 (genomic_info_filler.cpp   :  69)   Trusted kmer low bound: 0
+[spades]   0:00:00.394    97M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Gap Closer
+[spades]   0:00:00.394    97M / 2G    INFO    General                 (graph_pack.hpp            : 105)   Index refill
+[spades]   0:00:00.394    97M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.394    97M / 2G    INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 128 files using 8 threads. This might take a while.
+[spades]   0:00:00.394    97M / 2G    INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.395    97M / 2G    INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166468 Gb
+[spades]   0:00:00.395    97M / 2G    INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 58184
+[spades]   0:00:00.459     2G / 2G    INFO    General                 (edge_index_builders.hpp   :  82)   Used 588 sequences.
+[spades]   0:00:00.476   113M / 2G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.494   113M / 2G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 8793 kmers in total.
+[spades]   0:00:00.495   113M / 2G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.501   113M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.521   113M / 2G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
+[spades]   0:00:00.523   113M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 13144 bytes occupied (11.9586 bits per kmer).
+[spades]   0:00:00.523   113M / 2G    INFO    General                 (edge_index_builders.hpp   : 107)   Collecting edge information from graph, this takes a while.
+[spades]   0:00:00.527   113M / 2G    INFO    General                 (edge_index.hpp            :  92)   Index refilled
+[spades]   0:00:00.529   113M / 2G    INFO    General                 (gap_closer.cpp            : 147)   Preparing shift maps
+[spades]   0:00:00.529   113M / 2G    INFO    General                 (gap_closer.cpp            : 107)   Processing paired reads (takes a while)
+[spades]   0:00:00.532   113M / 2G    INFO    General                 (gap_closer.cpp            : 126)   Used 23 paired reads
+[spades]   0:00:00.532   113M / 2G    INFO    General                 (gap_closer.cpp            : 128)   Merging paired indices
+[spades]   0:00:00.533   113M / 2G    INFO   GapCloser                (gap_closer.cpp            : 332)   Closing short gaps
+[spades]   0:00:00.533   113M / 2G    INFO   GapCloser                (gap_closer.cpp            : 364)   Closing short gaps complete: filled 0 gaps after checking 0 candidates
+[spades]   0:00:00.537   113M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Raw Simplification
+[spades]   0:00:00.538   113M / 2G    INFO    General                 (simplification.cpp        : 128)   PROCEDURE == InitialCleaning
+[spades]   0:00:00.538   113M / 2G    INFO    General                 (graph_simplification.hpp  : 671)   Flanking coverage based disconnection disabled
+[spades]   0:00:00.538   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Self conjugate edge remover
+[spades]   0:00:00.543   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Self conjugate edge remover triggered 0 times
+[spades]   0:00:00.543   113M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Simplification
+[spades]   0:00:00.544   113M / 2G    INFO    General                 (simplification.cpp        : 383)   Graph simplification started
+[spades]   0:00:00.544   113M / 2G    INFO    General                 (graph_simplification.hpp  : 643)   Creating parallel br instance
+[spades]   0:00:00.544   113M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 1
+[spades]   0:00:00.545   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.549   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 132 times
+[spades]   0:00:00.550   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.555   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 8 times
+[spades]   0:00:00.555   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.558   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.559   113M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 2
+[spades]   0:00:00.559   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.559   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.560   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.560   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.560   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.561   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.561   113M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 3
+[spades]   0:00:00.561   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.561   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.561   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.562   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.562   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.562   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.562   113M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 4
+[spades]   0:00:00.562   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.563   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.563   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.563   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.563   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.563   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.564   113M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 5
+[spades]   0:00:00.564   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.564   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.564   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.564   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.565   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.565   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.565   113M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 6
+[spades]   0:00:00.565   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.566   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.566   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.566   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.566   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.566   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.567   113M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 7
+[spades]   0:00:00.567   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.567   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.567   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.567   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.568   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.568   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.568   113M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 8
+[spades]   0:00:00.568   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.568   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.569   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.569   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.569   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.569   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.569   113M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 9
+[spades]   0:00:00.570   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.570   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.570   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.570   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.570   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.571   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.571   113M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 10
+[spades]   0:00:00.571   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.571   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.571   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.572   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.572   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.572   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.572   113M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 11
+[spades]   0:00:00.573   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.574   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.574   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.576   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.576   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.577   113M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.577   113M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Gap Closer
+[spades]   0:00:00.577   113M / 2G    INFO    General                 (graph_pack.hpp            : 105)   Index refill
+[spades]   0:00:00.578   113M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.578   113M / 2G    INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 128 files using 8 threads. This might take a while.
+[spades]   0:00:00.579   113M / 2G    INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.579   113M / 2G    INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166448 Gb
+[spades]   0:00:00.579   113M / 2G    INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 58177
+[spades]   0:00:00.641     2G / 2G    INFO    General                 (edge_index_builders.hpp   :  82)   Used 26 sequences.
+[spades]   0:00:00.649   121M / 2G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.665   121M / 2G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 2088 kmers in total.
+[spades]   0:00:00.665   121M / 2G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.670   121M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.688   121M / 2G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
+[spades]   0:00:00.689   121M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 10200 bytes occupied (39.0805 bits per kmer).
+[spades]   0:00:00.690   121M / 2G    INFO    General                 (edge_index_builders.hpp   : 107)   Collecting edge information from graph, this takes a while.
+[spades]   0:00:00.693   121M / 2G    INFO    General                 (edge_index.hpp            :  92)   Index refilled
+[spades]   0:00:00.695   121M / 2G    INFO    General                 (gap_closer.cpp            : 147)   Preparing shift maps
+[spades]   0:00:00.696   121M / 2G    INFO    General                 (gap_closer.cpp            : 107)   Processing paired reads (takes a while)
+[spades]   0:00:00.698   121M / 2G    INFO    General                 (gap_closer.cpp            : 126)   Used 23 paired reads
+[spades]   0:00:00.699   121M / 2G    INFO    General                 (gap_closer.cpp            : 128)   Merging paired indices
+[spades]   0:00:00.699   121M / 2G    INFO   GapCloser                (gap_closer.cpp            : 332)   Closing short gaps
+[spades]   0:00:00.699   121M / 2G    INFO   GapCloser                (gap_closer.cpp            : 364)   Closing short gaps complete: filled 0 gaps after checking 0 candidates
+[spades]   0:00:00.703   121M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Simplification Cleanup
+[spades]   0:00:00.704   121M / 2G    INFO    General                 (simplification.cpp        : 196)   PROCEDURE == Post simplification
+[spades]   0:00:00.704   121M / 2G    INFO    General                 (graph_simplification.hpp  : 456)   Disconnection of relatively low covered edges disabled
+[spades]   0:00:00.705   121M / 2G    INFO    General                 (graph_simplification.hpp  : 493)   Complex tip clipping disabled
+[spades]   0:00:00.705   121M / 2G    INFO    General                 (graph_simplification.hpp  : 643)   Creating parallel br instance
+[spades]   0:00:00.705   121M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.708   121M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.709   121M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.713   121M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.714   121M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.718   121M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.719   121M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.720   121M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.720   121M / 2G    INFO    General                 (simplification.cpp        : 343)   Disrupting self-conjugate edges
+[spades]   0:00:00.721   121M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Removing isolated edges
+[spades]   0:00:00.722   121M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Removing isolated edges triggered 12 times
+[spades]   0:00:00.722   121M / 2G    INFO    General                 (simplification.cpp        : 496)   Counting average coverage
+[spades]   0:00:00.723   121M / 2G    INFO    General                 (simplification.cpp        : 502)   Average coverage = 31.9224
+[spades]   0:00:00.723   121M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Contig Output
+[spades]   0:00:00.724   121M / 2G    INFO    General                 (read_converter.cpp        : 102)   Outputting contigs to /home/piemari/shovill_bam/spades/K91/simplified_contigs
+[spades]   0:00:00.727   121M / 2G    INFO    General                 (binary_converter.cpp      : 111)   1 reads written
+[spades]   0:00:00.732   121M / 2G    INFO    General                 (pipeline.cpp              : 259)   SPAdes finished
+[spades]   0:00:00.733   121M / 2G    INFO    General                 (main.cpp                  : 107)   Assembling time: 0 hours 0 minutes 0 seconds
+[spades] 
+[spades] ===== K91 finished. 
+[spades] 
+[spades] 
+[spades] ===== K111 started. 
+[spades] 
+[spades] 
+[spades] == Running: /home/piemari/apps/conda/envs/metaphlan/bin/spades-core /home/piemari/shovill_bam/spades/K111/configs/config.info /home/piemari/shovill_bam/spades/K111/configs/isolate_mode.info
+[spades] 
+[spades] WARNING: Try to use logger before create one. Level=INFO. Message=Additional contigs is /home/piemari/shovill_bam/spades/K91/simplified_contigs
+[spades]   0:00:00.000     4M / 9M    INFO    General                 (main.cpp                  :  75)   Loaded config from /home/piemari/shovill_bam/spades/K111/configs/config.info
+[spades]   0:00:00.000     4M / 9M    INFO    General                 (main.cpp                  :  75)   Loaded config from /home/piemari/shovill_bam/spades/K111/configs/isolate_mode.info
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (memory_limit.cpp          :  49)   Memory limit set to 4 Gb
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  85)   Starting SPAdes, built from N/A, git revision N/A
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  86)   Maximum k-mer length: 128
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  87)   Assembling dataset (/home/piemari/shovill_bam/spades/dataset.info) with K=111
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (main.cpp                  :  88)   Maximum # of threads to use (adjusted due to OMP capabilities): 8
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 194)   SPAdes started
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 201)   Starting from stage: read_conversion
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 207)   Two-step RR enabled: 0
+[spades]   0:00:00.000     4M / 10M   INFO    General                 (pipeline.cpp              : 218)   Will need read mapping, kmer mapper will be attached
+[spades]   0:00:00.000     4M / 10M   INFO   StageManager             (stage.cpp                 : 166)   STAGE == Binary Read Conversion
+[spades]   0:00:00.001     4M / 12M   INFO    General                 (read_converter.cpp        :  53)   Binary reads detected
+[spades]   0:00:00.002     4M / 16M   INFO   StageManager             (stage.cpp                 : 166)   STAGE == de Bruijn graph construction
+[spades]   0:00:00.002     4M / 16M   INFO    General                 (construction.cpp          : 115)   Contigs from previous K will be used: /home/piemari/shovill_bam/spades/K91/simplified_contigs
+[spades]   0:00:00.007     4M / 16M   INFO    General                 (construction.cpp          : 150)   Max read length 280
+[spades]   0:00:00.007     4M / 16M   INFO    General                 (construction.cpp          : 153)   Max read length without merged 150
+[spades]   0:00:00.007     4M / 16M   INFO    General                 (construction.cpp          : 156)   Average read length 193.032
+[spades]   0:00:00.007     4M / 16M   INFO    General                 (stage.cpp                 : 113)   PROCEDURE == k+1-mer counting
+[spades]   0:00:00.007     4M / 16M   INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 64 files using 8 threads. This might take a while.
+[spades]   0:00:00.007     4M / 16M   INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.007     4M / 16M   INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166632 Gb
+[spades]   0:00:00.007     4M / 16M   INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 87363
+[spades]   0:00:00.085    83M / 552M  INFO    General                 (kmer_splitters.hpp        : 293)   Used 868 reads
+[spades]   0:00:00.085    83M / 552M  INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.101    83M / 552M  INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 8451 kmers in total.
+[spades]   0:00:00.101    83M / 552M  INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.105    83M / 552M  INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Extension index construction
+[spades]   0:00:00.105    83M / 552M  INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.105    83M / 552M  INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 128 files using 8 threads. This might take a while.
+[spades]   0:00:00.105    83M / 552M  INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.105    83M / 552M  INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166533 Gb
+[spades]   0:00:00.105    83M / 552M  INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 43655
+[spades]   0:00:00.179     2G / 2G    INFO    General                 (kmer_splitters.hpp        : 364)   Processed 8451 kmers
+[spades]   0:00:00.180     2G / 2G    INFO    General                 (kmer_splitters.hpp        : 369)   Used 8451 kmers.
+[spades]   0:00:00.203    97M / 2G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.220    99M / 2G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 8478 kmers in total.
+[spades]   0:00:00.220    99M / 2G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.226    99M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.250    96M / 2G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
+[spades]   0:00:00.252    96M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 12992 bytes occupied (12.2595 bits per kmer).
+[spades]   0:00:00.252    96M / 2G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build:  99)   Building k-mer extensions from k+1-mers
+[spades]   0:00:00.257    96M / 2G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build: 103)   Building k-mer extensions from k+1-mers finished.
+[spades]   0:00:00.258    96M / 2G    INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Condensing graph
+[spades]   0:00:00.258    96M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 354)   Extracting unbranching paths
+[spades]   0:00:00.263    97M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 373)   Extracting unbranching paths finished. 272 sequences extracted
+[spades]   0:00:00.264    97M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 309)   Collecting perfect loops
+[spades]   0:00:00.265    97M / 2G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 342)   Collecting perfect loops finished. 0 loops collected
+[spades]   0:00:00.266    97M / 2G    INFO    General                 (stage.cpp                 : 113)   PROCEDURE == Filling coverage indices (PHM)
+[spades]   0:00:00.266    97M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.267    97M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.280    97M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 8376 bytes occupied (7.929 bits per kmer).
+[spades]   0:00:00.280    97M / 2G    INFO    General                 (construction.cpp          : 429)   Collecting k-mer coverage information from reads, this takes a while.
+[spades]   0:00:00.284    97M / 2G    INFO    General                 (construction.cpp          : 549)   Filling coverage and flanking coverage from PHM
+[spades]   0:00:00.290    97M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == EC Threshold Finding
+[spades]   0:00:00.291    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 181)   Kmer coverage valley at: 2
+[spades]   0:00:00.291    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 201)   K-mer histogram maximum: 28
+[spades]   0:00:00.291    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 237)   Estimated median coverage: 28. Coverage mad: 5.9304
+[spades]   0:00:00.291    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 259)   Fitting coverage model
+[spades]   0:00:00.297    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 2
+[spades]   0:00:00.310    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 4
+[spades]   0:00:00.342    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 295)   ... iteration 8
+[spades]   0:00:00.373    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 309)   Fitted mean coverage: 26.1152. Fitted coverage std. dev: 4.16511
+[spades]   0:00:00.373    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 334)   Probability of erroneous kmer at valley: 0.999998
+[spades]   0:00:00.374    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 358)   Preliminary threshold calculated as: 18
+[spades]   0:00:00.374    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 362)   Threshold adjusted to: 14
+[spades]   0:00:00.374    97M / 2G    INFO    General                 (kmer_coverage_model.cpp   : 375)   Estimated genome size (ignoring repeats): 1059
+[spades]   0:00:00.374    97M / 2G    INFO    General                 (genomic_info_filler.cpp   :  53)   Mean coverage was calculated as 26.1152
+[spades]   0:00:00.374    97M / 2G    INFO    General                 (genomic_info_filler.cpp   :  68)   EC coverage threshold value was calculated as 14
+[spades]   0:00:00.374    97M / 2G    INFO    General                 (genomic_info_filler.cpp   :  69)   Trusted kmer low bound: 0
+[spades]   0:00:00.375    97M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Gap Closer
+[spades]   0:00:00.375    97M / 2G    INFO    General                 (graph_pack.hpp            : 105)   Index refill
+[spades]   0:00:00.375    97M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.375    97M / 2G    INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 128 files using 8 threads. This might take a while.
+[spades]   0:00:00.375    97M / 2G    INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.376    97M / 2G    INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166477 Gb
+[spades]   0:00:00.376    97M / 2G    INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 43640
+[spades]   0:00:00.444     2G / 2G    INFO    General                 (edge_index_builders.hpp   :  82)   Used 544 sequences.
+[spades]   0:00:00.465   105M / 2G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.487   105M / 2G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 8451 kmers in total.
+[spades]   0:00:00.487   105M / 2G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.493   105M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.513   106M / 2G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
+[spades]   0:00:00.515   106M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 12976 bytes occupied (12.2835 bits per kmer).
+[spades]   0:00:00.515   106M / 2G    INFO    General                 (edge_index_builders.hpp   : 107)   Collecting edge information from graph, this takes a while.
+[spades]   0:00:00.518   106M / 2G    INFO    General                 (edge_index.hpp            :  92)   Index refilled
+[spades]   0:00:00.524   106M / 2G    INFO    General                 (gap_closer.cpp            : 147)   Preparing shift maps
+[spades]   0:00:00.525   106M / 2G    INFO    General                 (gap_closer.cpp            : 107)   Processing paired reads (takes a while)
+[spades]   0:00:00.527   106M / 2G    INFO    General                 (gap_closer.cpp            : 126)   Used 23 paired reads
+[spades]   0:00:00.527   106M / 2G    INFO    General                 (gap_closer.cpp            : 128)   Merging paired indices
+[spades]   0:00:00.527   106M / 2G    INFO   GapCloser                (gap_closer.cpp            : 332)   Closing short gaps
+[spades]   0:00:00.528   106M / 2G    INFO   GapCloser                (gap_closer.cpp            : 364)   Closing short gaps complete: filled 0 gaps after checking 0 candidates
+[spades]   0:00:00.528   106M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Raw Simplification
+[spades]   0:00:00.529   106M / 2G    INFO    General                 (simplification.cpp        : 128)   PROCEDURE == InitialCleaning
+[spades]   0:00:00.529   106M / 2G    INFO    General                 (simplification.cpp        :  63)   Most init cleaning disabled on main iteration
+[spades]   0:00:00.530   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Self conjugate edge remover
+[spades]   0:00:00.530   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Self conjugate edge remover triggered 0 times
+[spades]   0:00:00.530   106M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Simplification
+[spades]   0:00:00.531   106M / 2G    INFO    General                 (simplification.cpp        : 383)   Graph simplification started
+[spades]   0:00:00.531   106M / 2G    INFO    General                 (graph_simplification.hpp  : 643)   Creating parallel br instance
+[spades]   0:00:00.531   106M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 1
+[spades]   0:00:00.532   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.533   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 114 times
+[spades]   0:00:00.534   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.536   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 5 times
+[spades]   0:00:00.536   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.537   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.537   106M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 2
+[spades]   0:00:00.537   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.538   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.538   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.538   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.539   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.539   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.539   106M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 3
+[spades]   0:00:00.539   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.540   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.540   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.540   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.540   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.540   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.541   106M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 4
+[spades]   0:00:00.541   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.541   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.541   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.541   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.542   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.542   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.542   106M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 5
+[spades]   0:00:00.542   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.542   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.543   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.543   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.543   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.543   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.543   106M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 6
+[spades]   0:00:00.544   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.544   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.544   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.544   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.544   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.545   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.545   106M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 7
+[spades]   0:00:00.545   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.545   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.545   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.546   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.546   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.546   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.546   106M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 8
+[spades]   0:00:00.546   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.547   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.547   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.547   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.547   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.547   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.548   106M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 9
+[spades]   0:00:00.548   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.548   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.548   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.548   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.549   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.549   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.549   106M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 10
+[spades]   0:00:00.549   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.549   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.550   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.550   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.550   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.550   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.550   106M / 2G    INFO    General                 (simplification.cpp        : 388)   PROCEDURE == Simplification cycle, iteration 11
+[spades]   0:00:00.551   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.553   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.554   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.558   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.559   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
+[spades]   0:00:00.564   106M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
+[spades]   0:00:00.568   106M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Gap Closer
+[spades]   0:00:00.569   106M / 2G    INFO    General                 (graph_pack.hpp            : 105)   Index refill
+[spades]   0:00:00.569   106M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
+[spades]   0:00:00.569   106M / 2G    INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 128 files using 8 threads. This might take a while.
+[spades]   0:00:00.570   106M / 2G    INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 131072
+[spades]   0:00:00.570   106M / 2G    INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 0.166454 Gb
+[spades]   0:00:00.570   106M / 2G    INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 43635
+[spades]   0:00:00.631     2G / 2G    INFO    General                 (edge_index_builders.hpp   :  82)   Used 64 sequences.
+[spades]   0:00:00.641   119M / 2G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
+[spades]   0:00:00.656   119M / 2G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 3182 kmers in total.
+[spades]   0:00:00.656   119M / 2G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
+[spades]   0:00:00.661   119M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
+[spades]   0:00:00.681   119M / 2G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
+[spades]   0:00:00.682   119M / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 10600 bytes occupied (26.6499 bits per kmer).
+[spades]   0:00:00.683   119M / 2G    INFO    General                 (edge_index_builders.hpp   : 107)   Collecting edge information from graph, this takes a while.
+[spades]   0:00:00.686   119M / 2G    INFO    General                 (edge_index.hpp            :  92)   Index refilled
+[spades]   0:00:00.689   119M / 2G    INFO    General                 (gap_closer.cpp            : 147)   Preparing shift maps
+[spades]   0:00:00.689   119M / 2G    INFO    General                 (gap_closer.cpp            : 107)   Processing paired reads (takes a while)
+[spades]   0:00:00.691   119M / 2G    INFO    General                 (gap_closer.cpp            : 126)   Used 23 paired reads
+[spades]   0:00:00.692   119M / 2G    INFO    General                 (gap_closer.cpp            : 128)   Merging paired indices
+[spades]   0:00:00.692   119M / 2G    INFO   GapCloser                (gap_closer.cpp            : 332)   Closing short gaps
+[spades]   0:00:00.693   119M / 2G    INFO   GapCloser                (gap_closer.cpp            : 364)   Closing short gaps complete: filled 0 gaps after checking 0 candidates
+[spades]   0:00:00.693   119M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Simplification Cleanup
+[spades]   0:00:00.694   119M / 2G    INFO    General                 (simplification.cpp        : 196)   PROCEDURE == Post simplification
+[spades]   0:00:00.694   119M / 2G    INFO    General                 (graph_simplification.hpp  : 456)   Disconnection of relatively low covered edges disabled
+[spades]   0:00:00.694   119M / 2G    INFO    General                 (graph_simplification.hpp  : 493)   Complex tip clipping disabled
+[spades]   0:00:00.695   119M / 2G    INFO    General                 (graph_simplification.hpp  : 643)   Creating parallel br instance
+[spades]   0:00:00.695   119M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.695   119M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.696   119M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.696   119M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.697   119M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
+[spades]   0:00:00.697   119M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
+[spades]   0:00:00.697   119M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
+[spades]   0:00:00.698   119M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
+[spades]   0:00:00.698   119M / 2G    INFO    General                 (simplification.cpp        : 343)   Disrupting self-conjugate edges
+[spades]   0:00:00.698   119M / 2G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Removing isolated edges
+[spades]   0:00:00.700   119M / 2G    INFO   Simplification           (parallel_processing.hpp   : 167)   Removing isolated edges triggered 31 times
+[spades]   0:00:00.701   119M / 2G    INFO    General                 (simplification.cpp        : 496)   Counting average coverage
+[spades]   0:00:00.701   119M / 2G    INFO    General                 (simplification.cpp        : 502)   Average coverage = 25.1649
+[spades]   0:00:00.701   119M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Mismatch Correction
+[spades]   0:00:00.701   119M / 2G    INFO    General                 (graph_pack.hpp            : 113)   Normalizing k-mer map. Total 1220 kmers to process
+[spades]   0:00:00.702   119M / 2G    INFO    General                 (graph_pack.hpp            : 115)   Normalizing done
+[spades]   0:00:00.714   119M / 2G    INFO    General                 (mismatch_shall_not_pass.hp: 195)   Finished collecting potential mismatches positions
+[spades]   0:00:00.714   119M / 2G    INFO    General                 (mismatch_shall_not_pass.hp: 310)   All edges processed
+[spades]   0:00:00.715   119M / 2G    INFO    General                 (mismatch_correction.cpp   :  27)   Corrected 0 nucleotides
+[spades]   0:00:00.715   119M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Contig Output
+[spades]   0:00:00.716   119M / 2G    INFO    General                 (contig_output.hpp         :  21)   Outputting contigs to /home/piemari/shovill_bam/spades/K111/before_rr.fasta
+[spades]   0:00:00.719   119M / 2G    INFO    General                 (contig_output_stage.cpp   : 146)   Writing GFA graph to /home/piemari/shovill_bam/spades/K111/assembly_graph_after_simplification.gfa
+[spades]   0:00:00.719   119M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Paired Information Counting
+[spades]   0:00:00.719   119M / 2G    INFO    General                 (graph_pack.hpp            : 113)   Normalizing k-mer map. Total 1220 kmers to process
+[spades]   0:00:00.720   119M / 2G    INFO    General                 (graph_pack.hpp            : 115)   Normalizing done
+[spades]   0:00:00.720   119M / 2G    INFO    General                 (pair_info_count.cpp       : 322)   Min edge length for estimation: 1140
+[spades]   0:00:00.720   119M / 2G    INFO    General                 (pair_info_count.cpp       : 333)   Estimating insert size for library #0
+[spades]   0:00:00.720   119M / 2G    INFO    General                 (pair_info_count.cpp       : 190)   Estimating insert size (takes a while)
+[spades]   0:00:00.763   263M / 2G    INFO    General                 (pair_info_count.cpp       :  39)   Selecting usual mapper
+[spades]   0:00:00.967   263M / 2G    INFO    General                 (sequence_mapper_notifier.h:  94)   Total 410 reads processed
+[spades]   0:00:01.259   263M / 2G    INFO    General                 (pair_info_count.cpp       : 208)   Edge pairs: 2
+[spades]   0:00:01.261   263M / 2G    INFO    General                 (pair_info_count.cpp       : 210)   334 paired reads (81.4634% of all) aligned to long edges
+[spades]   0:00:01.263   119M / 2G    INFO    General                 (pair_info_count.cpp       : 352)     Insert size = 201.347, deviation = 42.1646, left quantile = 150, right quantile = 261, read length = 150
+[spades]   0:00:01.263   119M / 2G    INFO    General                 (pair_info_count.cpp       : 373)   Filtering data for library #0
+[spades]   0:00:01.266   119M / 2G    INFO    General                 (pair_info_count.cpp       :  39)   Selecting usual mapper
+[spades]   0:00:01.268   119M / 2G    INFO    General                 (sequence_mapper_notifier.h:  94)   Total 410 reads processed
+[spades]   0:00:01.268   119M / 2G    INFO    General                 (pair_info_count.cpp       : 385)   Mapping library #0
+[spades]   0:00:01.269   119M / 2G    INFO    General                 (pair_info_count.cpp       : 387)   Mapping paired reads (takes a while)
+[spades]   0:00:01.269   119M / 2G    INFO    General                 (pair_info_count.cpp       : 285)   Left insert size quantile 150, right insert size quantile 261, filtering threshold 2, rounding threshold 0
+[spades]   0:00:01.277   119M / 2G    INFO    General                 (pair_info_count.cpp       :  39)   Selecting usual mapper
+[spades]   0:00:01.280   119M / 2G    INFO    General                 (sequence_mapper_notifier.h:  94)   Total 410 reads processed
+[spades]   0:00:01.283   119M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Distance Estimation
+[spades]   0:00:01.283   119M / 2G    INFO    General                 (distance_estimation.cpp   : 174)   Processing library #0
+[spades]   0:00:01.284   119M / 2G    INFO    General                 (distance_estimation.cpp   : 150)   Weight Filter Done
+[spades]   0:00:01.284   119M / 2G    INFO   DistanceEstimator        (distance_estimation.hpp   : 116)   Using SIMPLE distance estimator
+[spades]   0:00:01.286   119M / 2G    INFO    General                 (distance_estimation.cpp   :  35)   Filtering info
+[spades]   0:00:01.287   119M / 2G    INFO    General                 (pair_info_filters.hpp     : 242)   Start filtering; index size: 2
+[spades]   0:00:01.287   119M / 2G    INFO    General                 (pair_info_filters.hpp     : 263)   Done filtering
+[spades]   0:00:01.287   119M / 2G    INFO    General                 (distance_estimation.cpp   : 157)   Refining clustered pair information
+[spades]   0:00:01.287   119M / 2G    INFO    General                 (distance_estimation.cpp   : 159)   The refining of clustered pair information has been finished
+[spades]   0:00:01.288   119M / 2G    INFO    General                 (distance_estimation.cpp   : 161)   Improving paired information
+[spades]   0:00:01.288   119M / 2G    INFO   PairInfoImprover         (pair_info_improver.hpp    : 102)   Paired info stats: missing = 0; contradictional = 0
+[spades]   0:00:01.289   119M / 2G    INFO   PairInfoImprover         (pair_info_improver.hpp    : 102)   Paired info stats: missing = 0; contradictional = 0
+[spades]   0:00:01.289   119M / 2G    INFO    General                 (distance_estimation.cpp   : 104)   Filling scaffolding index
+[spades]   0:00:01.290   119M / 2G    INFO   DistanceEstimator        (distance_estimation.hpp   : 116)   Using SMOOTHING distance estimator
+[spades]   0:00:01.290   119M / 2G    INFO    General                 (distance_estimation.cpp   :  35)   Filtering info
+[spades]   0:00:01.290   119M / 2G    INFO    General                 (pair_info_filters.hpp     : 242)   Start filtering; index size: 2
+[spades]   0:00:01.291   119M / 2G    INFO    General                 (pair_info_filters.hpp     : 263)   Done filtering
+[spades]   0:00:01.291   119M / 2G    INFO    General                 (distance_estimation.cpp   : 183)   Clearing raw paired index
+[spades]   0:00:01.291   119M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Repeat Resolving
+[spades]   0:00:01.291   119M / 2G    INFO    General                 (repeat_resolving.cpp      :  69)   Using Path-Extend repeat resolving
+[spades]   0:00:01.292   119M / 2G    INFO    General                 (launcher.cpp              : 538)   ExSPAnder repeat resolving tool started
+[spades]   0:00:01.293   119M / 2G    INFO    General                 (launcher.cpp              : 404)   Creating main extenders, unique edge length = 2000
+[spades]   0:00:01.293   119M / 2G    INFO    General                 (extenders_logic.cpp       : 311)   Estimated coverage of library #0 is 25.1649
+[spades]   0:00:01.293   119M / 2G    INFO    General                 (extenders_logic.cpp       : 311)   Estimated coverage of library #0 is 25.1649
+[spades]   0:00:01.294   119M / 2G    INFO    General                 (extenders_logic.cpp       : 519)   Using 1 paired-end library
+[spades]   0:00:01.294   119M / 2G    INFO    General                 (extenders_logic.cpp       : 520)   Using 1 paired-end scaffolding library
+[spades]   0:00:01.294   119M / 2G    INFO    General                 (extenders_logic.cpp       : 521)   Using 0 single read libraries
+[spades]   0:00:01.294   119M / 2G    INFO    General                 (launcher.cpp              : 432)   Total number of extenders is 3
+[spades]   0:00:01.294   119M / 2G    INFO    General                 (launcher.cpp              : 244)   Finalizing paths
+[spades]   0:00:01.295   119M / 2G    INFO    General                 (launcher.cpp              : 246)   Deduplicating paths
+[spades]   0:00:01.295   119M / 2G    INFO    General                 (launcher.cpp              : 250)   Paths deduplicated
+[spades]   0:00:01.295   119M / 2G    INFO   PEResolver               (pe_resolver.hpp           : 295)   Removing overlaps
+[spades]   0:00:01.295   119M / 2G    INFO   PEResolver               (pe_resolver.hpp           : 298)   Sorting paths
+[spades]   0:00:01.295   119M / 2G    INFO   PEResolver               (pe_resolver.hpp           : 305)   Marking overlaps
+[spades]   0:00:01.295   119M / 2G    INFO   OverlapRemover           (pe_resolver.hpp           : 130)   Marking start/end overlaps
+[spades]   0:00:01.296   119M / 2G    INFO   OverlapRemover           (pe_resolver.hpp           : 133)   Marking remaining overlaps
+[spades]   0:00:01.296   119M / 2G    INFO   PEResolver               (pe_resolver.hpp           : 308)   Splitting paths
+[spades]   0:00:01.296   119M / 2G    INFO   PEResolver               (pe_resolver.hpp           : 313)   Deduplicating paths
+[spades]   0:00:01.296   119M / 2G    INFO   PEResolver               (pe_resolver.hpp           : 315)   Overlaps removed
+[spades]   0:00:01.296   119M / 2G    INFO    General                 (launcher.cpp              : 267)   Paths finalized
+[spades]   0:00:01.296   119M / 2G    INFO    General                 (launcher.cpp              : 439)   Closing gaps in paths
+[spades]   0:00:01.297   119M / 2G    INFO    General                 (launcher.cpp              : 467)   Gap closing completed
+[spades]   0:00:01.297   119M / 2G    INFO    General                 (launcher.cpp              : 296)   Traversing tandem repeats
+[spades]   0:00:01.297   119M / 2G    INFO    General                 (launcher.cpp              : 306)   Traversed 0 loops
+[spades]   0:00:01.297   119M / 2G    INFO    General                 (launcher.cpp              : 244)   Finalizing paths
+[spades]   0:00:01.297   119M / 2G    INFO    General                 (launcher.cpp              : 246)   Deduplicating paths
+[spades]   0:00:01.298   119M / 2G    INFO    General                 (launcher.cpp              : 250)   Paths deduplicated
+[spades]   0:00:01.298   119M / 2G    INFO   PEResolver               (pe_resolver.hpp           : 295)   Removing overlaps
+[spades]   0:00:01.298   119M / 2G    INFO   PEResolver               (pe_resolver.hpp           : 298)   Sorting paths
+[spades]   0:00:01.298   119M / 2G    INFO   PEResolver               (pe_resolver.hpp           : 305)   Marking overlaps
+[spades]   0:00:01.298   119M / 2G    INFO   OverlapRemover           (pe_resolver.hpp           : 130)   Marking start/end overlaps
+[spades]   0:00:01.298   119M / 2G    INFO   OverlapRemover           (pe_resolver.hpp           : 133)   Marking remaining overlaps
+[spades]   0:00:01.299   119M / 2G    INFO   PEResolver               (pe_resolver.hpp           : 308)   Splitting paths
+[spades]   0:00:01.299   119M / 2G    INFO   PEResolver               (pe_resolver.hpp           : 313)   Deduplicating paths
+[spades]   0:00:01.299   119M / 2G    INFO   PEResolver               (pe_resolver.hpp           : 315)   Overlaps removed
+[spades]   0:00:01.299   119M / 2G    INFO    General                 (launcher.cpp              : 267)   Paths finalized
+[spades]   0:00:01.299   119M / 2G    INFO    General                 (launcher.cpp              : 596)   ExSPAnder repeat resolving tool finished
+[spades]   0:00:01.299   119M / 2G    INFO   StageManager             (stage.cpp                 : 166)   STAGE == Contig Output
+[spades]   0:00:01.300   119M / 2G    INFO    General                 (contig_output.hpp         :  21)   Outputting contigs to /home/piemari/shovill_bam/spades/K111/before_rr.fasta
+[spades]   0:00:01.302   119M / 2G    INFO    General                 (contig_output_stage.cpp   : 146)   Writing GFA graph to /home/piemari/shovill_bam/spades/K111/assembly_graph_with_scaffolds.gfa
+[spades]   0:00:01.302   119M / 2G    INFO    General                 (contig_output_stage.cpp   : 160)   Outputting FastG graph to /home/piemari/shovill_bam/spades/K111/assembly_graph.fastg
+[spades]   0:00:01.304   119M / 2G    INFO    General                 (contig_output_stage.cpp   : 190)   Breaking scaffolds
+[spades]   0:00:01.304   119M / 2G    INFO    General                 (contig_output_stage.cpp   :  95)   Outputting contigs to /home/piemari/shovill_bam/spades/K111/final_contigs.fasta
+[spades]   0:00:01.306   119M / 2G    INFO    General                 (contig_output_stage.cpp   : 101)   Outputting FastG paths to /home/piemari/shovill_bam/spades/K111/final_contigs.paths
+[spades]   0:00:01.307   119M / 2G    INFO    General                 (contig_output_stage.cpp   :  95)   Outputting contigs to /home/piemari/shovill_bam/spades/K111/scaffolds.fasta
+[spades]   0:00:01.308   119M / 2G    INFO    General                 (contig_output_stage.cpp   : 101)   Outputting FastG paths to /home/piemari/shovill_bam/spades/K111/scaffolds.paths
+[spades]   0:00:01.310   119M / 2G    INFO    General                 (contig_output_stage.cpp   : 108)   Populating GFA with scaffold paths
+[spades]   0:00:01.312   119M / 2G    INFO    General                 (pipeline.cpp              : 259)   SPAdes finished
+[spades]   0:00:01.313   116M / 2G    INFO    General                 (main.cpp                  : 107)   Assembling time: 0 hours 0 minutes 1 seconds
+[spades] 
+[spades] ===== K111 finished. 
+[spades] 
+[spades] 
+[spades] ===== Copy files started. 
+[spades] 
+[spades] 
+[spades] == Running: /home/piemari/apps/conda/envs/metaphlan/bin/python /home/piemari/apps/conda/envs/metaphlan/share/spades/spades_pipeline/scripts/copy_files.py /home/piemari/shovill_bam/spades/K111/before_rr.fasta /home/piemari/shovill_bam/spades/before_rr.fasta /home/piemari/shovill_bam/spades/K111/assembly_graph_after_simplification.gfa /home/piemari/shovill_bam/spades/assembly_graph_after_simplification.gfa /home/piemari/shovill_bam/spades/K111/final_contigs.fasta /home/piemari/shovill_bam/spades/contigs.fasta /home/piemari/shovill_bam/spades/K111/first_pe_contigs.fasta /home/piemari/shovill_bam/spades/first_pe_contigs.fasta /home/piemari/shovill_bam/spades/K111/strain_graph.gfa /home/piemari/shovill_bam/spades/strain_graph.gfa /home/piemari/shovill_bam/spades/K111/scaffolds.fasta /home/piemari/shovill_bam/spades/scaffolds.fasta /home/piemari/shovill_bam/spades/K111/scaffolds.paths /home/piemari/shovill_bam/spades/scaffolds.paths /home/piemari/shovill_bam/spades/K111/assembly_graph_with_scaffolds.gfa /home/piemari/shovill_bam/spades/assembly_graph_with_scaffolds.gfa /home/piemari/shovill_bam/spades/K111/assembly_graph.fastg /home/piemari/shovill_bam/spades/assembly_graph.fastg /home/piemari/shovill_bam/spades/K111/final_contigs.paths /home/piemari/shovill_bam/spades/contigs.paths
+[spades] 
+[spades] 
+[spades] ===== Copy files finished. 
+[spades] 
+[spades] 
+[spades] ===== Assembling finished. 
+[spades] 
+[spades] 
+[spades] ===== Breaking scaffolds started. 
+[spades] 
+[spades] 
+[spades] == Running: /home/piemari/apps/conda/envs/metaphlan/bin/python /home/piemari/apps/conda/envs/metaphlan/share/spades/spades_pipeline/scripts/breaking_scaffolds_script.py --result_scaffolds_filename /home/piemari/shovill_bam/spades/scaffolds.fasta --misc_dir /home/piemari/shovill_bam/spades/misc --threshold_for_breaking_scaffolds 3
+[spades] 
+[spades] 
+[spades] ===== Breaking scaffolds finished. 
+[spades] 
+[spades] 
+[spades] ===== Terminate started. 
+[spades] 
+[spades] 
+[spades] ===== Terminate finished. 
+[spades] 
+[spades]  * Assembled contigs are in /home/piemari/shovill_bam/spades/contigs.fasta
+[spades]  * Assembled scaffolds are in /home/piemari/shovill_bam/spades/scaffolds.fasta
+[spades]  * Paths in the assembly graph corresponding to the contigs are in /home/piemari/shovill_bam/spades/contigs.paths
+[spades]  * Paths in the assembly graph corresponding to the scaffolds are in /home/piemari/shovill_bam/spades/scaffolds.paths
+[spades]  * Assembly graph is in /home/piemari/shovill_bam/spades/assembly_graph.fastg
+[spades]  * Assembly graph in GFA format is in /home/piemari/shovill_bam/spades/assembly_graph_with_scaffolds.gfa
+[spades] 
+[spades] ======= SPAdes pipeline finished.
+[spades] 
+[spades] SPAdes log can be found here: /home/piemari/shovill_bam/spades/spades.log
+[spades] 
+[spades] Thank you for using SPAdes!
+[shovill] Checking for assembly errors in spades.fasta
+[shovill] Running: bwa index spades.fasta 2>&1 | sed 's/^/[bwa-index] /' | tee -a shovill.log
+[bwa-index] [bwa_index] Pack FASTA... 0.00 sec
+[bwa-index] [bwa_index] Construct BWT for the packed sequence...
+[bwa-index] [bwa_index] 0.00 seconds elapse.
+[bwa-index] [bwa_index] Update BWT... 0.00 sec
+[bwa-index] [bwa_index] Pack forward-only FASTA... 0.00 sec
+[bwa-index] [bwa_index] Construct SA from BWT and Occ... 0.00 sec
+[bwa-index] [main] Version: 0.7.17-r1188
+[bwa-index] [main] CMD: bwa index spades.fasta
+[bwa-index] [main] Real time: 0.012 sec; CPU: 0.004 sec
+[shovill] Running: samtools faidx spades.fasta 2>&1 | sed 's/^/[faidx] /' | tee -a shovill.log
+[shovill] Running: (bwa mem -v 3 -x intractg -t 8 spades.fasta R1.fq.gz R2.fq.gz | samclip --ref spades.fasta.fai | samtools sort --threads 2 -m 1024m --reference spades.fasta -T /tmp -o shovill.bam) 2>&1 | sed 's/^/[bwa+samtools-sort] /' | tee -a shovill.log
+[bwa+samtools-sort] [M::bwa_idx_load_from_disk] read 0 ALT contigs
+[bwa+samtools-sort] [M::process] read 820 sequences (123000 bp)...
+[bwa+samtools-sort] [M::mem_pestat] # candidate unique pairs for (FF, FR, RF, RR): (0, 410, 0, 0)
+[bwa+samtools-sort] [M::mem_pestat] skip orientation FF as there are not enough pairs
+[bwa+samtools-sort] [M::mem_pestat] analyzing insert size distribution for orientation FR...
+[bwa+samtools-sort] [M::mem_pestat] (25, 50, 75) percentile: (163, 197, 230)
+[bwa+samtools-sort] [M::mem_pestat] low and high boundaries for computing mean and std.dev: (29, 364)
+[bwa+samtools-sort] [M::mem_pestat] mean and std.dev: (200.81, 42.23)
+[bwa+samtools-sort] [M::mem_pestat] low and high boundaries for proper pairs: (1, 431)
+[bwa+samtools-sort] [M::mem_pestat] skip orientation RF as there are not enough pairs
+[bwa+samtools-sort] [M::mem_pestat] skip orientation RR as there are not enough pairs
+[bwa+samtools-sort] [M::mem_process_seqs] Processed 820 reads in 0.101 CPU sec, 0.021 real sec
+[bwa+samtools-sort] [samclip] samclip 0.4.0 by Torsten Seemann (@torstenseemann)
+[bwa+samtools-sort] [samclip] Loading: spades.fasta.fai
+[bwa+samtools-sort] [samclip] Found 1 sequences in spades.fasta.fai
+[bwa+samtools-sort] [main] Version: 0.7.17-r1188
+[bwa+samtools-sort] [main] CMD: bwa mem -v 3 -x intractg -t 8 spades.fasta R1.fq.gz R2.fq.gz
+[bwa+samtools-sort] [main] Real time: 0.053 sec; CPU: 0.107 sec
+[bwa+samtools-sort] [samclip] Total SAM records 820, removed 63, allowed 123, passed 757
+[bwa+samtools-sort] [samclip] Header contained 2 lines
+[bwa+samtools-sort] [samclip] Done.
+[bwa+samtools-sort] [bam_sort_core] merging from 0 files and 2 in-memory blocks...
+[shovill] Running: samtools index shovill.bam 2>&1 | sed 's/^/[samtools-index] /' | tee -a shovill.log
+[shovill] Correcting errors in spades.fasta
+[shovill] Running: pilon --genome spades.fasta --frags shovill.bam --minmq 60 --minqual 3 --fix bases --output pilon --threads 8 --changes --mindepth 0.25 2>&1 | sed 's/^/[pilon] /' | tee -a shovill.log
+[pilon] Picked up _JAVA_OPTIONS:  -Xmx4g
+[pilon] Pilon version 1.24 Thu Jan 28 13:00:45 2021 -0500
+[pilon] --threads argument no longer supported; ignoring!
+[pilon] Genome: spades.fasta
+[pilon] Fixing snps, indels
+[pilon] Input genome size: 1251
+[pilon] Processing NODE_1_length_1251_cov_25.164912:1-1251
+[pilon] frags shovill.bam: coverage 79
+[pilon] Total Reads: 757, Coverage: 79, minDepth: 20
+[pilon] Confirmed 1152 of 1251 bases (92,09%)
+[pilon] Corrected 0 snps; 0 ambiguous bases; corrected 0 small insertions totaling 0 bases, 0 small deletions totaling 0 bases
+[pilon] NODE_1_length_1251_cov_25.164912:1-1251 log:
+[pilon] Finished processing NODE_1_length_1251_cov_25.164912:1-1251
+[pilon] Writing NODE_1_length_1251_cov_25.164912:1-1251 changes to pilon.changes
+[pilon] Writing updated NODE_1_length_1251_cov_25.164912_pilon to pilon.fasta
+[pilon] Mean frags coverage: 79
+[pilon] Mean total coverage: 79
+[shovill] Repaired 0 contigs from spades.fasta at 0 positions.
+[shovill] Assembly is 1251, estimated genome size was 1188 (+5.30%)
+[shovill] Using genome graph file 'spades/assembly_graph_with_scaffolds.gfa' => 'contigs.gfa'
+[shovill] Walltime used: 0 min 10 sec
+[shovill] Results in: /home/piemari/shovill_bam
+[shovill] Final assembly graph: /home/piemari/shovill_bam/contigs.gfa
+[shovill] Final assembly contigs: /home/piemari/shovill_bam/contigs.fa
+[shovill] It contains 1 (min=75) contigs totalling 1251 bp.
+[shovill] Have a suggestion for shovill? Tell me at https://github.com/tseemann/shovill/issues
+[shovill] Done.