BUG: kb count failing but s2s does not register

[Maarten-vd-Sande]

Describe the bug kallistobus count fails, but does not give an error code. @Rebecza has logs of this. @Rebecza proposed to check if in the logfile some keyword is present, and if so, fail/succeed based on that. Should be easy to implement. Another option would be to actually fix kb-python, but that is more involved, and will only work once they release that fix.

[tilschaef]

@Rebecza , could you attach your logfie to this issues? I also noticed that kb-python would sometimes "silently" fail and not produce any output files while the kb count rule would still succeed! This was usually the case when the barcode layout /technology was not recognized.

[tilschaef]

I think it should be enough to check if the log file contains ERROR and then let the rule exit

[Maarten-vd-Sande]

Sure anything is fine by me. Are you sure a succesful run does not get sth like error? And a failed run?

[Rebecza]

@Rebecza , could you attach your logfie to this issues? I also noticed that kb-python would sometimes "silently" fail and not produce any output files while the kb count rule would still succeed! This was usually the case when the barcode layout /technology was not recognized.

I finally found back an example!

This is the kind of error one randomly gets sometimes (because of storage issue?), so far for this error I never found any other reason, than just a short blib on the server causing it, because after trying again it works for that plate as well.

Therefore for this type of error specifically, it would be good to check the logs after s2s is finished, and run again for the plates where it finds: std::bad_alloc.

An example log file for this:

[2020-12-15 20:31:55,800]   DEBUG Printing verbose output
[2020-12-15 20:31:55,800]   DEBUG kallisto binary located at /vol/mbconda/snabel/anaconda3/envs/seq2science/lib/python3.7/site-packages/seq2science/.snakemake/dc8b83b3/lib/python3.8/site-packages/kb_python/bins/linux/kallisto/kallisto
[2020-12-15 20:31:55,800]   DEBUG bustools binary located at /vol/mbconda/snabel/anaconda3/envs/seq2science/lib/python3.7/site-packages/seq2science/.snakemake/dc8b83b3/lib/python3.8/site-packages/kb_python/bins/linux/bustools/bustools
[2020-12-15 20:31:55,800]   DEBUG Creating /scratch/snabel/scrna/data_d4-26_all_s2s/results/kallistobus/GRCh38-Mon-AM-m5-1-Z41_S3/tmp directory
[2020-12-15 20:31:55,800]   DEBUG Namespace(c1='/scratch/snabel/scrna/data_d4-26_all_s2s/genomes/GRCh38/index/kallistobus//GRCh38_cdna_t2c.txt', c2='/scratch/snabel/scrna/data_d4-26_all_s2s/genomes/GRCh38/index/kallistobus//GRCh38_intron_t2c.txt', cellranger=False, command='count', dry_run=False, fastqs=['/scratch/snabel/scrna/data_d4-26_all_s2s/results/fastq_cleaned/Mon-AM-m5-1-Z41_S3_clean_R1.fastq.paired.fq', '/scratch/snabel/scrna/data_d4-26_all_s2s/results/fastq_cleaned/Mon-AM-m5-1-Z41_S3_clean_R2.fastq.paired.fq'], filter=None, g='/scratch/snabel/scrna/data_d4-26_all_s2s/genomes/GRCh38/index/kallistobus//GRCh38_t2g.txt', h5ad=True, i='/scratch/snabel/scrna/data_d4-26_all_s2s/genomes/GRCh38/index/kallistobus//GRCh38.idx', keep_tmp=False, lamanno=False, list=False, loom=False, m='4G', mm=False, no_inspect=False, no_validate=False, nucleus=False, o='/scratch/snabel/scrna/data_d4-26_all_s2s/results/kallistobus/GRCh38-Mon-AM-m5-1-Z41_S3', overwrite=False, report=False, t=8, tcc=False, tmp=None, verbose=True, w='../1col_barcode_384.tab', workflow='lamanno', x='1,8,16:1,0,8:0,0,0')
[2020-12-15 20:31:55,801]    INFO Using index /scratch/snabel/scrna/data_d4-26_all_s2s/genomes/GRCh38/index/kallistobus//GRCh38.idx to generate BUS file to /scratch/snabel/scrna/data_d4-26_all_s2s/results/kallistobus/GRCh38-m5-1-Z41_S3 from
[2020-12-15 20:31:55,801]    INFO         /scratch/snabel/scrna/data_d4-26_all_s2s/results/fastq_cleaned/m5-1-Z41_S3_clean_R1.fastq.paired.fq
[2020-12-15 20:31:55,801]    INFO         /scratch/snabel/scrna/data_d4-26_all_s2s/results/fastq_cleaned/m5-1-Z41_S3_clean_R2.fastq.paired.fq
[2020-12-15 20:31:55,801]   DEBUG kallisto bus -i /scratch/snabel/scrna/data_d4-26_all_s2s/genomes/GRCh38/index/kallistobus//GRCh38.idx -o /scratch/snabel/scrna/data_d4-26_all_s2s/results/kallistobus/GRCh38-m5-1-Z41_S3 -x 1,8,16:1,0,8:0,0,0 -t 8 /scratch/snabel/scrna/data_d4-26_all_s2s/results/fastq_cleaned/m5-1-Z41_S3_clean_R1.fastq.paired.fq /scratch/snabel/scrna/data_d4-26_all_s2s/results/fastq_cleaned/m5-1-Z41_S3_clean_R2.fastq.paired.fq
[2020-12-15 20:36:00,161]   DEBUG 
[2020-12-15 20:36:00,161]   DEBUG [index] k-mer length: 31
[2020-12-15 20:36:00,161]   DEBUG [index] number of targets: 954,771
[2020-12-15 20:36:00,161]   DEBUG [index] number of k-mers: 1,214,037,798
[2020-12-15 20:36:00,161]   DEBUG [index] number of equivalence classes: 8,954,983
[2020-12-15 20:36:00,161]   DEBUG [quant] will process sample 1: /scratch/snabel/scrna/data_d4-26_all_s2s/results/fastq_cleaned/m5-1-Z41_S3_clean_R1.fastq.paired.fq
[2020-12-15 20:36:00,161]   DEBUG /scratch/snabel/scrna/data_d4-26_all_s2s/results/fastq_cleaned/m5-1-Z41_S3_clean_R2.fastq.paired.fq
[2020-12-15 20:36:00,161]   DEBUG [quant] finding pseudoalignments for the reads ...terminate called after throwing an instance of 'std::bad_alloc'
[2020-12-15 20:36:00,161]   DEBUG what():  std::bad_alloc
[2020-12-15 20:36:00,161]   ERROR 
[index] k-mer length: 31
[index] number of targets: 954,771
[index] number of k-mers: 1,214,037,798
[index] number of equivalence classes: 8,954,983
[quant] will process sample 1: /scratch/snabel/scrna/data_d4-26_all_s2s/results/fastq_cleaned/m5-1-Z41_S3_clean_R1.fastq.paired.fq
/scratch/snabel/scrna/data_d4-26_all_s2s/results/fastq_cleaned/m5-1-Z41_S3_clean_R2.fastq.paired.fq
[quant] finding pseudoalignments for the reads ...terminate called after throwing an instance of 'std::bad_alloc'
what():  std::bad_alloc
[2020-12-15 20:36:00,162]   ERROR An exception occurred
Traceback (most recent call last):
  File "/vol/mbconda/snabel/anaconda3/envs/seq2science/lib/python3.7/site-packages/seq2science/.snakemake/dc8b83b3/lib/python3.8/site-packages/kb_python/main.py", line 785, in main
    COMMAND_TO_FUNCTION[args.command](parser, args, temp_dir=temp_dir)
  File "/vol/mbconda/snabel/anaconda3/envs/seq2science/lib/python3.7/site-packages/seq2science/.snakemake/dc8b83b3/lib/python3.8/site-packages/kb_python/main.py", line 195, in parse_count
    count_velocity(
  File "/vol/mbconda/snabel/anaconda3/envs/seq2science/lib/python3.7/site-packages/seq2science/.snakemake/dc8b83b3/lib/python3.8/site-packages/kb_python/count.py", line 1462, in count_velocity
    bus_result = kallisto_bus(
  File "/vol/mbconda/snabel/anaconda3/envs/seq2science/lib/python3.7/site-packages/seq2science/.snakemake/dc8b83b3/lib/python3.8/site-packages/kb_python/validate.py", line 112, in inner
    results = func(*args, **kwargs)
  File "/vol/mbconda/snabel/anaconda3/envs/seq2science/lib/python3.7/site-packages/seq2science/.snakemake/dc8b83b3/lib/python3.8/site-packages/kb_python/count.py", line 147, in kallisto_bus
    run_executable(command)
  File "/vol/mbconda/snabel/anaconda3/envs/seq2science/lib/python3.7/site-packages/seq2science/.snakemake/dc8b83b3/lib/python3.8/site-packages/kb_python/dry/__init__.py", line 24, in inner
    return func(*args, **kwargs)
  File "/vol/mbconda/snabel/anaconda3/envs/seq2science/lib/python3.7/site-packages/seq2science/.snakemake/dc8b83b3/lib/python3.8/site-packages/kb_python/utils.py", line 232, in run_executable
    raise sp.CalledProcessError(p.returncode, ' '.join(command))
subprocess.CalledProcessError: Command '/vol/mbconda/snabel/anaconda3/envs/seq2science/lib/python3.7/site-packages/seq2science/.snakemake/dc8b83b3/lib/python3.8/site-packages/kb_python/bins/linux/kallisto/kallisto bus -i /scratch/snabel/scrna/data_d4-26_all_s2s/genomes/GRCh38/index/kallistobus//GRCh38.idx -o /scratch/snabel/scrna/data_d4-26_all_s2s/results/kallistobus/GRCh38-m5-1-Z41_S3 -x 1,8,16:1,0,8:0,0,0 -t 8 /scratch/snabel/scrna/data_d4-26_all_s2s/results/fastq_cleaned/m5-1-Z41_S3_clean_R1.fastq.paired.fq /scratch/snabel/scrna/data_d4-26_all_s2s/results/fastq_cleaned/m5-1-Z41_S3_clean_R2.fastq.paired.fq' died with <Signals.SIGABRT: 6>.
[2020-12-15 20:36:00,163]   DEBUG Removing /scratch/snabel/scrna/data_d4-26_all_s2s/results/kallistobus/GRCh38-m5-1-Z41_S3/tmp directory

[Rebecza]

I think it should be enough to check if the log file contains ERROR and then let the rule exit

This can still be a good idea, because also in case of other errors kb silently stops.

Recently Chet ran the pipeline and received another type of error (see below), but this was also not causing the whole s2s run to stop, he received "finished successfully", so kb count also here silently stopped and produced a matrix file, although the mapping didn't finish correctly (no counts_unfiltered/ was produced, reason: the barcode file was incorrect, which was only stated in the kb count log file).

[2021-06-15 18:09:32,351]   DEBUG Found 384 barcodes in the whitelist
[2021-06-15 18:09:32,351]   DEBUG Error: barcode length and whitelist length differ, barcodes = 16, whitelist = 8
[2021-06-15 18:09:32,351]   DEBUG check that your whitelist matches the technology used
[2021-06-15 18:09:32,351]   ERROR Found 384 barcodes in the whitelist
Error: barcode length and whitelist length differ, barcodes = 16, whitelist = 8
check that your whitelist matches the technology used
[2021-06-15 18:09:32,351]   ERROR An exception occurred

Sure anything is fine by me. Are you sure a succesful run does not get sth like error? And a failed run?

In the logs of successful plates I cannot find any ERROR statements.

[Rebecza]

So would it be an idea/possible to check for ERROR in the kallistobus_count logs, and:

• if it also states std::bad_alloc the pipeline re-runs for those plates.
• if not, the pipeline breaks and prints the error/path to the log?

[tilschaef]

It would propose that we implement checks like the following:

• Check for ERROR keywords and let the pipeline fail if encourtered.
• Check for std::bad_alloc and let the pipeline fail if encoutered.

If one or of these situations is encourted, the sample folder should also be deleted to not interfere with re-running s2s.

In general, I would like to keep these validations very rudimentary rather then checking for lots of different specific situations (hopefully kb implements more specific checks in the future).

@Rebecza, regarding the std::bad_alloc, this is usually a temporary issues with server memory and automatically rerunning the pipeline might not be the solution if memory is scarce since there is no guarantee it will work on retry. I think that is something the user should do manually once the pipeline fails.