IlluminaBasecallsToSam raises unexpected exception with an index out of bounds access (race condition?)

[clintval]

Bug Report

Affected tool(s)

• IlluminaBasecallsToSam

Affected version(s)

• 2.26.10

Description

An exception can be raised indicating an index out of bound access:

INFO	2022-02-25 22:44:55	IlluminaBasecallsToSam
WARNING	2022-02-25 22:44:56	IlluminaBasecallsToSam	Setting deprecated parameter `MAX_READS_IN_RAM_PER_TILE` use ` MAX_RECORDS_IN_RAM` instead
22:44:56.035 INFO  NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/picard.jar!/com/intel/gkl/native/libgkl_compression.so
[Fri Feb 25 22:44:56 PST 2022] IlluminaBasecallsToSam BARCODES_DIR=/output/analysis/basecalling/barcodes.3 RUN_BARCODE=REDACTED SEQUENCING_CENTER=REDACTED RUN_START_DATE=Wed Feb 23 00:00:00 PST 2022 LIBRARY_PARAMS=/output/analysis/basecalling/library_params.3.txt ADAPTERS_TO_CHECK=[REDACTED] NUM_PROCESSORS=12 MAX_READS_IN_RAM_PER_TILE=300000 INCLUDE_NON_PF_READS=false SORT=false LANE=[3] READ_STRUCTURE=redacted BASECALLS_DIR=/redacted/run-folder-redacted/Data/Intensities/BaseCalls TMP_DIR=[/output/tmp] VALIDATION_STRINGENCY=SILENT CREATE_INDEX=true USE_JDK_DEFLATER=false USE_JDK_INFLATER=false    PLATFORM=ILLUMINA INCLUDE_BC_IN_RG_TAG=false APPLY_EAMSS_FILTER=true IGNORE_UNEXPECTED_BARCODES=false MOLECULAR_INDEX_TAG=RX MOLECULAR_INDEX_BASE_QUALITY_TAG=QX BARCODE_POPULATION_STRATEGY=ORPHANS_ONLY INCLUDE_BARCODE_QUALITY=false MATCH_BARCODES_INLINE=false DISTANCE_MODE=HAMMING MAX_MISMATCHES=1 MIN_MISMATCH_DELTA=1 MAX_NO_CALLS=2 MINIMUM_BASE_QUALITY=0 MINIMUM_QUALITY=2 COMPRESS_OUTPUTS=false VERBOSITY=INFO QUIET=false COMPRESSION_LEVEL=5 MAX_RECORDS_IN_RAM=500000 CREATE_MD5_FILE=false GA4GH_CLIENT_SECRETS=client_secrets.json
[Fri Feb 25 22:44:56 PST 2022] Executing as [email protected] on Linux amd64; OpenJDK 64-Bit Server VM 11.0.14+9; Deflater: Intel; Inflater: Intel; Provider GCS is not available; Picard version: 2.26.10-SNAPSHOT
INFO	2022-02-25 22:44:56	IlluminaBasecallsToSam	DONE_READING STRUCTURE IS REDACTED
INFO	2022-02-25 22:44:57	CbclReader	Processing tile 1101
ERROR	2022-02-25 22:45:57	ThreadPoolExecutorWithExceptions	A thread failed:
java.lang.ArrayIndexOutOfBoundsException: Index 1 out of bounds for length 0
	at java.base/java.util.ArrayList.add(ArrayList.java:487)
	at java.base/java.util.ArrayList.add(ArrayList.java:499)
	at picard.util.AdapterMarker.lambda$tallyAndFixAdapters$0(AdapterMarker.java:236)
	at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
	at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:658)
	at picard.util.AdapterMarker.tallyAndFixAdapters(AdapterMarker.java:236)
	at picard.util.AdapterMarker.adapterTrimIlluminaPairedReads(AdapterMarker.java:247)
	at picard.util.AdapterMarker.adapterTrimIlluminaPairedReads(AdapterMarker.java:196)
	at picard.illumina.ClusterDataToSamConverter.convertClusterToOutputRecord(ClusterDataToSamConverter.java:299)
	at picard.illumina.ClusterDataToSamConverter.convertClusterToOutputRecord(ClusterDataToSamConverter.java:52)
	at picard.illumina.UnsortedBasecallsConverter$TileRecordToWriterPump.run(UnsortedBasecallsConverter.java:114)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
ERROR	2022-02-25 22:45:57	ThreadPoolExecutorWithExceptions	A thread failed:
picard.PicardException: Index 1 out of bounds for length 0
	at picard.util.ThreadPoolExecutorWithExceptions.afterExecute(ThreadPoolExecutorWithExceptions.java:49)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1129)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.lang.ArrayIndexOutOfBoundsException: Index 1 out of bounds for length 0
	at java.base/java.util.ArrayList.add(ArrayList.java:487)
	at java.base/java.util.ArrayList.add(ArrayList.java:499)
	at picard.util.AdapterMarker.lambda$tallyAndFixAdapters$0(AdapterMarker.java:236)
	at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
	at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:658)
	at picard.util.AdapterMarker.tallyAndFixAdapters(AdapterMarker.java:236)
	at picard.util.AdapterMarker.adapterTrimIlluminaPairedReads(AdapterMarker.java:247)
	at picard.util.AdapterMarker.adapterTrimIlluminaPairedReads(AdapterMarker.java:196)
	at picard.illumina.ClusterDataToSamConverter.convertClusterToOutputRecord(ClusterDataToSamConverter.java:299)
	at picard.illumina.ClusterDataToSamConverter.convertClusterToOutputRecord(ClusterDataToSamConverter.java:52)
	at picard.illumina.UnsortedBasecallsConverter$TileRecordToWriterPump.run(UnsortedBasecallsConverter.java:114)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	... 2 more

Exception: picard.PicardException thrown from the UncaughtExceptionHandler in thread "pool-2-thread-1"
INFO	2022-02-25 22:46:05	UnsortedBasecallsConverter	Processed     1,000,000 records.  Elapsed time: 00:01:08s.  Time for last 1,000,000:    7s.  Last read position: */*
INFO	2022-02-25 22:46:13	UnsortedBasecallsConverter	Processed     2,000,000 records.  Elapsed time: 00:01:16s.  Time for last 1,000,000:    7s.  Last read position: */*
INFO	2022-02-25 22:46:21	UnsortedBasecallsConverter	Processed     3,000,000 records.  Elapsed time: 00:01:25s.  Time for last 1,000,000:    8s.  Last read position: */*
[Fri Feb 25 22:46:28 PST 2022] picard.illumina.IlluminaBasecallsToSam done. Elapsed time: 1.55 minutes.
Runtime.totalMemory()=6476005376
To get help, see http://broadinstitute.github.io/picard/index.html#GettingHelp
Exception in thread "main" picard.PicardException: Exceptions in tile processing. There were 0 tasks still running or queued and they have been cancelled. Errors: picard.PicardException: Index 1 out of bounds for length 0
	at picard.illumina.BasecallsConverter.interruptAndShutdownExecutors(BasecallsConverter.java:318)
	at picard.illumina.UnsortedBasecallsConverter.awaitTileWriting(UnsortedBasecallsConverter.java:180)
	at picard.illumina.UnsortedBasecallsConverter.processTilesAndWritePerSampleOutputs(UnsortedBasecallsConverter.java:134)
	at picard.illumina.IlluminaBasecallsToSam.doWork(IlluminaBasecallsToSam.java:278)
	at picard.cmdline.CommandLineProgram.instanceMain(CommandLineProgram.java:308)
	at picard.cmdline.PicardCommandLine.instanceMain(PicardCommandLine.java:103)
	at picard.cmdline.PicardCommandLine.main(PicardCommandLine.java:113)

Re-running the job with identical parameters and environment allowed the demux to succeed which suggests this is caused by a race condition.

This could be related to:

• UnsortedBasecallsConverter java.lang.NullPointerException #1696

Steps to reproduce

Run Picard's demultiplexer enough times and you'll hit it.

Given this issue, the race condition in #1696, and the overall performance degradation that results in painful runtimes, we no longer recommend Picard's demultiplexer as fit for competitive production use.