BaseRecalibrator stops before finishing and does not throw an error

Hi GATK team,

I'm running into a new problem. I'm running BaseRecalibrator (GATK v3.5-0-g36282e4) and it's just stopping mid-run while it is creating the recal tables. For instance, it will run for an hour or so and just stop when it should have 7m left. Then, in my script, it goes to the next command, which is "PrintReads" and throws the error:
Bad input: The GATK report has no version specified in the header

I think this means that the recal.table file isn't written properly and is incomplete. Could that be the case?

Note that the first command just stops on the line that begins with "INFO 17:10:13,787"

INFO 16:32:37,571 HelpFormatter - --------------------------------------------------------------------------------
INFO 16:32:37,576 HelpFormatter - The Genome Analysis Toolkit (GATK) v3.5-0-g36282e4, Compiled 2015/11/25 04:03:56
INFO 16:32:37,576 HelpFormatter - Copyright (c) 2010 The Broad Institute
INFO 16:32:37,576 HelpFormatter - For support and documentation go to http://www.broadinstitute.org/gatk
INFO 16:32:37,580 HelpFormatter - Program Args: -nct 8 -R /project/mplattlab/data/genomes/rhemac2/rhemac2.fa -knownSites /project/mplattlab/data/variant_calling/rhemac2/intermediatebams/cayo.UG1_mpileup.vcf.gz -rf BadCigar -I /project/mplattlab/data/variant_calling/rhemac2/intermediatebams/3F4.realigned.bam -T BaseRecalibrator -o /project/mplattlab/data/variant_calling/rhemac2/intermediatebams/3F4.recal.table
INFO 16:32:37,583 HelpFormatter - Executing as [email protected] on Linux 2.6.32-504.el6.x86_64 amd64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_65-b17.
INFO 16:32:37,584 HelpFormatter - Date/Time: 2016/02/22 16:32:37
INFO 16:32:37,584 HelpFormatter - --------------------------------------------------------------------------------
INFO 16:32:37,584 HelpFormatter - --------------------------------------------------------------------------------
INFO 16:32:38,048 GenomeAnalysisEngine - Strictness is SILENT
INFO 16:32:38,120 GenomeAnalysisEngine - Downsampling Settings: No downsampling
INFO 16:32:38,126 SAMDataSource$SAMReaders - Initializing SAMRecords in serial
INFO 16:32:38,169 SAMDataSource$SAMReaders - Done initializing BAM readers: total time 0.04
WARN 16:32:38,338 IndexDictionaryUtils - Track knownSites doesn't have a sequence dictionary built in, skipping dictionary validation
INFO 16:32:38,345 MicroScheduler - Running the GATK in parallel mode with 8 total threads, 8 CPU thread(s) for each of 1 data thread(s), of 32 processors available on this machine
INFO 16:32:38,413 GenomeAnalysisEngine - Preparing for traversal over 1 BAM files
INFO 16:32:38,417 GenomeAnalysisEngine - Done preparing for traversal
INFO 16:32:38,417 ProgressMeter - [INITIALIZATION COMPLETE; STARTING PROCESSING]
INFO 16:32:38,418 ProgressMeter - | processed | time | per 1M | | total | remaining
INFO 16:32:38,418 ProgressMeter - Location | reads | elapsed | reads | completed | runtime | runtime
INFO 16:32:38,441 BaseRecalibrator - The covariates being used here:
INFO 16:32:38,441 BaseRecalibrator - ReadGroupCovariate
INFO 16:32:38,441 BaseRecalibrator - QualityScoreCovariate
INFO 16:32:38,441 BaseRecalibrator - ContextCovariate
INFO 16:32:38,441 ContextCovariate - Context sizes: base substitution model 2, indel substitution model 3
INFO 16:32:38,442 BaseRecalibrator - CycleCovariate
INFO 16:32:38,445 ReadShardBalancer$1 - Loading BAM index data
INFO 16:32:38,447 ReadShardBalancer$1 - Done loading BAM index data
INFO 16:33:08,424 ProgressMeter - chr1:17156225 200002.0 30.0 s 2.5 m 0.6% 83.5 m 83.0 m
INFO 16:33:38,425 ProgressMeter - chr1:45361623 700007.0 60.0 s 85.0 s 1.6% 63.1 m 62.1 m
INFO 16:34:08,752 ProgressMeter - chr1:72017432 1200012.0 90.0 s 75.0 s 2.5% 59.7 m 58.2 m
INFO 16:34:39,063 ProgressMeter - chr1:104984857 1600017.0 120.0 s 75.0 s 3.7% 54.6 m 52.6 m
INFO 16:35:09,079 ProgressMeter - chr1:134337834 2000023.0 2.5 m 75.0 s 4.7% 53.3 m 50.8 m
INFO 16:35:39,082 ProgressMeter - chr1:164978926 2500028.0 3.0 m 72.0 s 5.8% 52.1 m 49.1 m
INFO 16:36:09,083 ProgressMeter - chr1:194735456 2900032.0 3.5 m 72.0 s 6.8% 51.5 m 48.0 m
INFO 16:36:39,085 ProgressMeter - chr1:221199137 3300036.0 4.0 m 72.0 s 7.7% 51.8 m 47.8 m
INFO 16:37:09,088 ProgressMeter - chr2:25443780 3686028.0 4.5 m 73.0 s 8.9% 50.8 m 46.3 m
INFO 16:37:39,190 ProgressMeter - chr2:61539361 4186036.0 5.0 m 71.0 s 10.1% 49.4 m 44.4 m
INFO 16:38:09,191 ProgressMeter - chr2:97847826 4786042.0 5.5 m 69.0 s 11.4% 48.3 m 42.8 m
INFO 16:38:39,227 ProgressMeter - chr2:133160916 5286047.0 6.0 m 68.0 s 12.6% 47.5 m 41.5 m
INFO 16:39:09,228 ProgressMeter - chr2:169269389 5786053.0 6.5 m 67.0 s 13.9% 46.8 m 40.3 m
INFO 16:39:39,242 ProgressMeter - chr3:11454899 6249081.0 7.0 m 67.0 s 15.0% 46.7 m 39.7 m
INFO 16:40:09,290 ProgressMeter - chr3:40227299 6749148.0 7.5 m 66.0 s 16.0% 46.9 m 39.4 m
INFO 16:40:39,294 ProgressMeter - chr3:78319439 7249156.0 8.0 m 66.0 s 17.3% 46.2 m 38.2 m
INFO 16:41:09,376 ProgressMeter - chr3:112562912 7749161.0 8.5 m 65.0 s 18.5% 45.9 m 37.4 m
INFO 16:41:40,903 ProgressMeter - chr3:155256070 8249169.0 9.0 m 65.0 s 20.0% 45.1 m 36.1 m
INFO 16:42:10,904 ProgressMeter - chr3:190721485 8749175.0 9.5 m 65.0 s 21.3% 44.9 m 35.3 m
INFO 16:42:40,906 ProgressMeter - chr4:24882535 9246702.0 10.0 m 65.0 s 22.3% 44.9 m 34.9 m
INFO 16:43:10,907 ProgressMeter - chr4:49850788 9746728.0 10.5 m 64.0 s 23.2% 45.4 m 34.9 m
INFO 16:43:40,918 ProgressMeter - chr4:88886306 1.0146733E7 11.0 m 65.0 s 24.6% 44.9 m 33.9 m
INFO 16:44:10,922 ProgressMeter - chr4:126305800 1.064674E7 11.5 m 65.0 s 25.9% 44.6 m 33.1 m
INFO 16:44:40,924 ProgressMeter - chr4:162848331 1.1146746E7 12.0 m 64.0 s 27.1% 44.3 m 32.3 m
INFO 16:45:10,928 ProgressMeter - chr5:23495201 1.1614781E7 12.5 m 64.0 s 28.1% 44.6 m 32.0 m
INFO 16:45:40,929 ProgressMeter - chr5:54955190 1.2014785E7 13.0 m 65.0 s 29.2% 44.6 m 31.6 m
INFO 16:46:10,933 ProgressMeter - chr5:91794349 1.2514805E7 13.5 m 64.0 s 30.5% 44.4 m 30.8 m
INFO 16:46:40,934 ProgressMeter - chr5:128678439 1.2914809E7 14.0 m 65.0 s 31.8% 44.1 m 30.1 m
INFO 16:47:10,935 ProgressMeter - chr5:160103569 1.3314813E7 14.5 m 65.0 s 32.9% 44.2 m 29.6 m
INFO 16:47:41,764 ProgressMeter - chr6:11636944 1.378561E7 15.1 m 65.0 s 34.1% 44.2 m 29.1 m
INFO 16:48:11,767 ProgressMeter - chr6:43059322 1.4285617E7 15.6 m 65.0 s 35.2% 44.2 m 28.7 m
INFO 16:48:41,768 ProgressMeter - chr6:69367623 1.4785631E7 16.1 m 65.0 s 36.1% 44.5 m 28.4 m
INFO 16:49:11,837 ProgressMeter - chr6:106402853 1.5285636E7 16.6 m 64.0 s 37.4% 44.3 m 27.7 m
INFO 16:49:41,838 ProgressMeter - chr6:143036256 1.5785641E7 17.1 m 64.0 s 38.7% 44.1 m 27.1 m
INFO 16:50:11,842 ProgressMeter - chr6:174124643 1.6285647E7 17.6 m 64.0 s 39.7% 44.2 m 26.6 m
INFO 16:50:41,843 ProgressMeter - chr7:29322048 1.6750392E7 18.1 m 64.0 s 40.9% 44.1 m 26.1 m
INFO 16:51:11,845 ProgressMeter - chr7:59229721 1.7250397E7 18.6 m 64.0 s 42.0% 44.2 m 25.7 m
INFO 16:51:41,847 ProgressMeter - chr7:85301617 1.7850419E7 19.1 m 64.0 s 42.9% 44.4 m 25.4 m
INFO 16:52:11,852 ProgressMeter - chr7:127170968 1.8350424E7 19.6 m 63.0 s 44.3% 44.1 m 24.6 m
INFO 16:52:41,853 ProgressMeter - chr7:161516598 1.8850429E7 20.1 m 63.0 s 45.5% 44.0 m 24.0 m
INFO 16:53:11,856 ProgressMeter - chr8:10619904 1.9318596E7 20.6 m 63.0 s 46.2% 44.5 m 23.9 m
INFO 16:53:41,863 ProgressMeter - chr8:42355688 1.9818601E7 21.1 m 63.0 s 47.3% 44.5 m 23.5 m
INFO 16:54:11,865 ProgressMeter - chr8:78323666 2.0418609E7 21.6 m 63.0 s 48.5% 44.4 m 22.8 m
INFO 16:54:41,867 ProgressMeter - chr8:116054511 2.0818615E7 22.1 m 63.0 s 49.9% 44.2 m 22.2 m
INFO 16:55:11,868 ProgressMeter - chr8:147792144 2.1418623E7 22.6 m 63.0 s 51.0% 44.2 m 21.7 m
INFO 16:55:41,872 ProgressMeter - chr9:20426750 2.1868507E7 23.1 m 63.0 s 51.7% 44.6 m 21.5 m
INFO 16:56:11,877 ProgressMeter - chr9:53707301 2.2368512E7 23.6 m 63.0 s 52.8% 44.6 m 21.0 m
INFO 16:56:41,882 ProgressMeter - chr9:89871581 2.2868517E7 24.1 m 63.0 s 54.1% 44.4 m 20.4 m
INFO 16:57:12,054 ProgressMeter - chr9:122731316 2.3468524E7 24.6 m 62.0 s 55.3% 44.4 m 19.9 m
INFO 16:57:42,062 ProgressMeter - chr10:17454779 2.3986596E7 25.1 m 62.0 s 56.2% 44.5 m 19.5 m
INFO 16:58:12,067 ProgressMeter - chr10:50223841 2.4486601E7 25.6 m 62.0 s 57.4% 44.5 m 19.0 m
INFO 16:58:42,073 ProgressMeter - chr10:77360320 2.4986606E7 26.1 m 62.0 s 58.3% 44.7 m 18.6 m
INFO 16:59:12,177 ProgressMeter - chr11:8993476 2.5518831E7 26.6 m 62.0 s 59.3% 44.8 m 18.3 m
INFO 16:59:42,182 ProgressMeter - chr11:38620538 2.5918836E7 27.1 m 62.0 s 60.3% 44.9 m 17.8 m
INFO 17:00:12,184 ProgressMeter - chr11:74497791 2.6418841E7 27.6 m 62.0 s 61.5% 44.8 m 17.2 m
INFO 17:00:42,282 ProgressMeter - chr11:114588057 2.7018847E7 28.1 m 62.0 s 62.9% 44.6 m 16.5 m
INFO 17:01:13,608 ProgressMeter - chr12:2663171 2.7545983E7 28.6 m 62.0 s 63.7% 44.9 m 16.3 m
INFO 17:01:43,668 ProgressMeter - chr12:49229431 2.8045989E7 29.1 m 62.0 s 65.4% 44.5 m 15.4 m
INFO 17:02:13,672 ProgressMeter - chr12:88250627 2.8545994E7 29.6 m 62.0 s 66.7% 44.3 m 14.8 m
INFO 17:02:43,673 ProgressMeter - chr13:10031645 2.9040692E7 30.1 m 62.0 s 67.7% 44.4 m 14.3 m
INFO 17:03:13,675 ProgressMeter - chr13:45017985 2.9540698E7 30.6 m 62.0 s 68.9% 44.4 m 13.8 m
INFO 17:03:43,676 ProgressMeter - chr13:80475888 3.0040704E7 31.1 m 62.0 s 70.2% 44.3 m 13.2 m
INFO 17:04:13,681 ProgressMeter - chr13:113180238 3.054071E7 31.6 m 62.0 s 71.3% 44.3 m 12.7 m
INFO 17:04:43,757 ProgressMeter - chr13:138024042 3.1040715E7 32.1 m 62.0 s 72.2% 44.5 m 12.4 m
INFO 17:05:13,758 ProgressMeter - chr14:38332097 3.1482365E7 32.6 m 62.0 s 73.5% 44.3 m 11.7 m
INFO 17:05:43,762 ProgressMeter - chr14:67024340 3.2182506E7 33.1 m 61.0 s 74.5% 44.4 m 11.3 m
INFO 17:06:13,763 ProgressMeter - chr14:96669997 3.2582511E7 33.6 m 61.0 s 75.6% 44.5 m 10.9 m
INFO 17:06:43,764 ProgressMeter - chr14:133001237 3.3182517E7 34.1 m 61.0 s 76.8% 44.4 m 10.3 m
INFO 17:07:13,766 ProgressMeter - chr15:27355549 3.3668498E7 34.6 m 61.0 s 77.8% 44.5 m 9.9 m
INFO 17:07:43,772 ProgressMeter - chr15:62906952 3.4168503E7 35.1 m 61.0 s 79.0% 44.4 m 9.3 m
INFO 17:08:13,773 ProgressMeter - chr15:98131719 3.466851E7 35.6 m 61.0 s 80.2% 44.3 m 8.8 m
INFO 17:08:43,777 ProgressMeter - chr16:18848885 3.5157972E7 36.1 m 61.0 s 81.3% 44.4 m 8.3 m
INFO 17:09:13,783 ProgressMeter - chr16:55389626 3.575798E7 36.6 m 61.0 s 82.6% 44.3 m 7.7 m
INFO 17:09:43,785 ProgressMeter - chr17:6084995 3.6278968E7 37.1 m 61.0 s 83.6% 44.3 m 7.3 m
INFO 17:10:13,787 ProgressMeter - chr17:40912603 3.6779029E7 37.6 m 61.0 s 84.8% 44.3 m 6.7 m
INFO 17:10:36,122 HelpFormatter - --------------------------------------------------------------------------------
INFO 17:10:36,124 HelpFormatter - The Genome Analysis Toolkit (GATK) v3.5-0-g36282e4, Compiled 2015/11/25 04:03:56
INFO 17:10:36,124 HelpFormatter - Copyright (c) 2010 The Broad Institute
INFO 17:10:36,124 HelpFormatter - For support and documentation go to http://www.broadinstitute.org/gatk
INFO 17:10:36,127 HelpFormatter - Program Args: -nct 8 -R /project/mplattlab/data/genomes/rhemac2/rhemac2.fa -knownSites /project/mplattlab/data/variant_calling/rhemac2/intermediatebams/cayo.UG1_mpileup.vcf.gz -rf BadCigar -I /project/mplattlab/data/variant_calling/rhemac2/intermediatebams/3F4.realigned.bam -T BaseRecalibrator -BQSR /project/mplattlab/data/variant_calling/rhemac2/intermediatebams/3F4.recal.table -o /project/mplattlab/data/variant_calling/rhemac2/intermediatebams/3F4.post_recal.table
INFO 17:10:36,131 HelpFormatter - Executing as [email protected] on Linux 2.6.32-504.el6.x86_64 amd64; Java HotSpot(TM) 64-Bit Server VM 1.8.0_65-b17.
INFO 17:10:36,131 HelpFormatter - Date/Time: 2016/02/22 17:10:36
INFO 17:10:36,132 HelpFormatter - --------------------------------------------------------------------------------
INFO 17:10:36,132 HelpFormatter - --------------------------------------------------------------------------------
INFO 17:10:36,591 GenomeAnalysisEngine - Strictness is SILENT
INFO 17:10:37,116 GATKRunReport - Uploaded run statistics report to AWS S3

ERROR ------------------------------------------------------------------------------------------
ERROR A USER ERROR has occurred (version 3.5-0-g36282e4):
ERROR
ERROR This means that one or more arguments or inputs in your command are incorrect.
ERROR The error message below tells you what is the problem.
ERROR
ERROR If the problem is an invalid argument, please check the online documentation guide
ERROR (or rerun your command with --help) to view allowable command-line arguments for this tool.
ERROR
ERROR Visit our website and forum for extensive documentation and answers to
ERROR commonly asked questions http://www.broadinstitute.org/gatk
ERROR
ERROR Please do NOT post this error to the GATK forum unless you have really tried to fix it yourself.
ERROR
ERROR MESSAGE: Bad input: The GATK report has no version specified in the header
ERROR ------------------------------------------------------------------------------------------

Note that it doesn't do this for all of my samples, but it does for the majority of them. Some of them finish the recalibration without a problem printing out:
"INFO 17:39:20,763 BaseRecalibrator - Calculating quantized quality scores...
INFO 17:39:20,800 BaseRecalibrator - Writing recalibration report...
INFO 17:39:21,359 BaseRecalibrator - ...done!
INFO 17:39:21,359 BaseRecalibrator - BaseRecalibrator was able to recalibrate 16753906 reads
INFO 17:39:21,360 ProgressMeter - done 1.675392E7 32.3 m 115.0 s 100.0% 32.3 m 0.0 s
INFO 17:39:21,360 ProgressMeter - Total runtime 1938.57 secs, 32.31 min, 0.54 hours
INFO 17:39:21,360 MicroScheduler - 1625435 reads were filtered out during the traversal out of approximately 18379355 total reads (8.84%)
INFO 17:39:21,361 MicroScheduler - -> 0 reads (0.00% of total) failing BadCigarFilter
INFO 17:39:21,361 MicroScheduler - -> 0 reads (0.00% of total) failing DuplicateReadFilter
INFO 17:39:21,361 MicroScheduler - -> 0 reads (0.00% of total) failing FailsVendorQualityCheckFilter
INFO 17:39:21,361 MicroScheduler - -> 0 reads (0.00% of total) failing MalformedReadFilter
INFO 17:39:21,361 MicroScheduler - -> 0 reads (0.00% of total) failing MappingQualityUnavailableFilter
INFO 17:39:21,361 MicroScheduler - -> 1570404 reads (8.54% of total) failing MappingQualityZeroFilter
INFO 17:39:21,362 MicroScheduler - -> 55031 reads (0.30% of total) failing NotPrimaryAlignmentFilter
INFO 17:39:21,362 MicroScheduler - -> 0 reads (0.00% of total) failing UnmappedReadFilter
INFO 17:39:22,269 GATKRunReport - Uploaded run statistics report to AWS S3 "

Answers

  • Geraldine_VdAuweraGeraldine_VdAuwera Cambridge, MAMember, Administrator, Broadie

    Is it possible that the server you're running on is killing jobs after a certain amount of time?

    And yes it looks like the recal tables were not written properly, possibly due to the early termination of the previous step.

  • @Geraldine_VdAuwera said:
    Is it possible that the server you're running on is killing jobs after a certain amount of time?

    And yes it looks like the recal tables were not written properly, possibly due to the early termination of the previous step.

    I thought that might be the case, but it doesn't seem to hold since the recal table generation and printreads are two lines in the same shell script (and therefore part of the same job).

    I'll see if I can increase the memory footprint and fix the issue, but otherwise I don't really know what could be happening.

    Please let me know if you have any other ideas.

    Thanks!
    Noah

  • SheilaSheila Broad InstituteMember, Broadie, Moderator

    @hesheatingup
    Hi Noah,

    Another issue might be the multi-threading. User have reported some issues while using -nct.

    Sheila

  • HI Sheila,

    Thanks for letting me know. I'll see if that is the issue.

    Stay tuned...

    Noah

  • I doubled the memory to 32G and it seemed to work on samples where it failed previously. Thanks for the quick responses. I really appreciate the quick and thoughtful support offered by the GATK team!

Sign In or Register to comment.