TransferReadTags is unable to delete temp files

[tobsecret]

Bug Report

Affected tool(s) or class(es)

TransferReadTags

Affected version(s)

❯ gatk --version                                         
Using GATK jar /data1/shahs3/users/schrait/envs/bioinfo/share/gatk4-4.6.1.0-0/gatk-package-4.6.1.0-local.jar
Running:
    java -Dsamjdk.use_async_io_read_samtools=false -Dsamjdk.use_async_io_write_samtools=true -Dsamjdk.use_async_io_write_tribble=false -Dsamjdk.compression_level=2 -jar /data1/shahs3/users/schrait/envs/bioinfo/share/gatk4-4.6.1.0-0/gatk-package-4.6.1.0-local.jar --version
The Genome Analysis Toolkit (GATK) v4.6.1.0
HTSJDK Version: 4.1.3
Picard Version: 3.3.0

Description

Tried running TransferReadTags and it finishes transferring tags but then fails when trying to delete temp files.

Command I ran:

samtools sort \
    -N /data1/shahs3/isabl_data_lake/analyses/56/67/45667/results/dorado.bam \
    -o /data1/shahs3/isabl_data_lake/analyses/66/00/46600/dorado.temp.lexsorted.bam

samtools sort \
    -N /data1/shahs3/isabl_data_lake/analyses/66/00/46600/results/minimap2/minimap2.sorted.bam \
    -o /data1/shahs3/isabl_data_lake/analyses/66/00/46600/minimap2.temp.lexsorted.bam

gatk TransferReadTags \
    --input  /data1/shahs3/isabl_data_lake/analyses/66/00/46600/minimap2.temp.lexsorted.bam \
    --output /data1/shahs3/isabl_data_lake/analyses/66/00/46600/output.temp.readtags.bam \
    --unmapped-sam /data1/shahs3/isabl_data_lake/analyses/66/00/46600/dorado.temp.lexsorted.bam \
    --read-tags MM

Output:

[bam_sort_core] merging from 36 files and 1 in-memory blocks...
[bam_sort_core] merging from 19 files and 1 in-memory blocks...
Using GATK jar /data1/shahs3/users/schrait/envs/bioinfo/share/gatk4-4.6.1.0-0/gatk-package-4.6.1.0-local.jar
Running:
java -Dsamjdk.use_async_io_read_samtools=false -Dsamjdk.use_async_io_write_samtools=true -Dsamjdk.use_async_io_write_tribble=false -Dsamjdk.compression_level=2 -Xmx30g -Xms4g -jar /data1/shahs3/users/schrait/envs/bioinfo/share/gatk4-4.6.1.0-0/gatk-package-4.6.1.0-local.jar TransferReadTags --input /data1/shahs3/isabl_data_lake/analyses/66/00/46600/minimap2.temp.lexsorted.bam --output /data1/shahs3/isabl_data_lake/analyses/66/00/46600/output.temp.readtags.bam --unmapped-sam /data1/shahs3/isabl_data_lake/analyses/66/00/46600/dorado.temp.lexsorted.bam --read-tags MM
01:05:25.501 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/data1/shahs3/users/schrait/envs/bioinfo/share/gatk4-4.6.1.0-0/gatk-package-4.6.1.0-local.jar!/com/intel/gkl/native/libgkl_compression.so
SLF4J(W): Class path contains multiple SLF4J providers.
SLF4J(W): Found provider [org.apache.logging.slf4j.SLF4JServiceProvider@1c84d80a]
SLF4J(W): Found provider [ch.qos.logback.classic.spi.LogbackServiceProvider@7ceb6c45]
SLF4J(W): See https://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J(I): Actual provider is of type [org.apache.logging.slf4j.SLF4JServiceProvider@1c84d80a]
01:05:25.843 INFO TransferReadTags - ------------------------------------------------------------
01:05:25.848 INFO TransferReadTags - The Genome Analysis Toolkit (GATK) v4.6.1.0
01:05:25.848 INFO TransferReadTags - For support and documentation go to https://software.broadinstitute.org/gatk/
01:05:25.849 INFO TransferReadTags - Executing as [email protected] on Linux v4.18.0-425.19.2.el8_7.x86_64 amd64
01:05:25.849 INFO TransferReadTags - Java runtime: OpenJDK 64-Bit Server VM v17.0.14-internal+0-adhoc..src
01:05:25.849 INFO TransferReadTags - Start Date/Time: May 7, 2025 at 1:05:25 AM EDT
01:05:25.849 INFO TransferReadTags - ------------------------------------------------------------
01:05:25.849 INFO TransferReadTags - ------------------------------------------------------------
01:05:25.850 INFO TransferReadTags - HTSJDK Version: 4.1.3
01:05:25.851 INFO TransferReadTags - Picard Version: 3.3.0
01:05:25.851 INFO TransferReadTags - Built for Spark Version: 3.5.0
01:05:25.855 INFO TransferReadTags - HTSJDK Defaults.COMPRESSION_LEVEL : 2
01:05:25.860 INFO TransferReadTags - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
01:05:25.860 INFO TransferReadTags - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
01:05:25.860 INFO TransferReadTags - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
01:05:25.860 INFO TransferReadTags - Deflater: IntelDeflater
01:05:25.861 INFO TransferReadTags - Inflater: IntelInflater
01:05:25.861 INFO TransferReadTags - GCS max retries/reopens: 20
01:05:25.861 INFO TransferReadTags - Requester pays: disabled
01:05:25.861 WARN TransferReadTags -

[1m[31m !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!

Warning: TransferReadTags is an EXPERIMENTAL tool and should not be used for production

!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!![0m


01:05:25.862 INFO TransferReadTags - Initializing engine
01:05:25.981 INFO TransferReadTags - Done initializing engine
01:05:26.610 WARN ReadUtils - Skipping index file creation for: /data1/shahs3/isabl_data_lake/analyses/66/00/46600/output.temp.readtags.bam. Index file creation requires reads in coordinate sorted order.
01:05:26.633 INFO ProgressMeter - Starting traversal
01:05:26.633 INFO ProgressMeter - Current Locus Elapsed Minutes Records Processed Records/Minute
01:05:36.673 INFO ProgressMeter - 1:148628901 0.2 22000 131500.3
01:05:46.856 INFO ProgressMeter - 4:49109752 0.3 46000 136491.8
01:05:57.013 INFO ProgressMeter - 4:49093905 0.5 69000 136278.4
01:06:07.097 INFO ProgressMeter - 15:20134108 0.7 89000 131975.7
01:06:17.316 INFO ProgressMeter - 2:90384158 0.8 113000 133775.3
01:06:27.611 INFO ProgressMeter - 2:92323308 1.0 136000 133820.9
01:08:03.027 INFO ProgressMeter - 10:42531803 2.6 143000 54861.8
01:08:13.285 INFO ProgressMeter - 4:49148151 2.8 170000 61205.8
01:08:23.571 INFO ProgressMeter - 18:41129420 2.9 197000 66803.8
01:08:34.017 INFO ProgressMeter - GL000226.1:1 3.1 221000 70764.2
01:08:44.398 INFO ProgressMeter - 11:51576734 3.3 247000 74937.8
01:08:54.624 INFO ProgressMeter - 4:49097494 3.5 266000 76734.5
01:10:32.482 INFO ProgressMeter - 10:42390850 5.1 287000 56302.7
01:10:42.603 INFO ProgressMeter - 2:97943748 5.3 312000 59246.5
01:10:53.377 INFO ProgressMeter - 1:121351588 5.4 337000 61883.7
01:11:03.700 INFO ProgressMeter - 16:32388767 5.6 362000 64438.4
01:11:13.720 INFO ProgressMeter - 4:49100391 5.8 381000 65862.6
01:11:23.894 INFO ProgressMeter - 10:42529345 6.0 410000 68857.4
01:13:01.625 INFO ProgressMeter - 16:46401432 7.6 429000 56572.5
01:13:11.798 INFO ProgressMeter - 10:42374903 7.8 453000 58431.1
01:13:23.311 INFO ProgressMeter - 1:121437332 7.9 475000 59788.9
01:13:33.603 INFO ProgressMeter - 16:46402215 8.1 503000 61975.2
01:13:43.716 INFO ProgressMeter - GL000225.1:107608 8.3 530000 63973.3
01:13:54.263 INFO ProgressMeter - X:61682016 8.5 556000 65717.3
01:15:27.607 INFO ProgressMeter - 1:146414741 10.0 573000 57207.3
01:15:37.861 INFO ProgressMeter - 5:70005098 10.2 599000 58799.8
01:15:48.113 INFO ProgressMeter - 10:38886909 10.4 625000 60339.9
01:15:59.038 INFO ProgressMeter - 16:46416465 10.5 652000 61859.2
01:16:09.070 INFO ProgressMeter - 10:42529246 10.7 678000 63321.5
01:16:19.337 INFO ProgressMeter - 7:61969272 10.9 693000 63704.3
01:17:55.824 INFO ProgressMeter - 5:131855207 12.5 716000 57342.0
01:18:05.930 INFO ProgressMeter - 3:129873165 12.7 740000 58475.2
01:18:16.082 INFO ProgressMeter - 19:27735980 12.8 766000 59731.1
01:18:26.394 INFO ProgressMeter - 10:42366959 13.0 791000 60864.9
01:18:36.831 INFO ProgressMeter - 8:86756436 13.2 809000 61427.7
01:18:47.086 INFO ProgressMeter - 10:42541421 13.3 838000 62814.6
01:20:20.006 INFO ProgressMeter - GL000226.1:5042 14.9 859000 57691.5
01:20:30.174 INFO ProgressMeter - GL000199.1:145221 15.1 882000 58569.6
01:20:40.563 INFO ProgressMeter - GL000199.1:96939 15.2 907000 59545.1
01:20:51.146 INFO ProgressMeter - 4:49140046 15.4 927000 60161.5
01:21:01.256 INFO ProgressMeter - 12:124952371 15.6 955000 61308.2
01:21:11.259 INFO ProgressMeter - 1:121485028 15.7 981000 62310.4
01:22:46.244 INFO ProgressMeter - GL000199.1:60070 17.3 1001000 57771.7
01:22:56.362 INFO ProgressMeter - 8:43093967 17.5 1025000 58586.6
01:23:06.394 INFO ProgressMeter - 11:103664 17.7 1051000 59504.0
01:23:16.559 INFO ProgressMeter - 9:68687688 17.8 1078000 60452.8
01:23:27.290 INFO ProgressMeter - GL000199.1:46827 18.0 1104000 61296.1
01:23:37.521 INFO ProgressMeter - 4:49134014 18.2 1130000 62151.3
01:25:15.346 INFO ProgressMeter - 2:89851966 19.8 1144000 57743.2
01:25:25.596 INFO ProgressMeter - 1:144831600 20.0 1167000 58400.5
01:25:35.683 INFO ProgressMeter - 16:32106874 20.2 1193000 59203.6
01:25:45.970 INFO ProgressMeter - 4:49093915 20.3 1217000 59885.1
01:25:56.336 INFO ProgressMeter - 10:42395994 20.5 1243000 60648.8
01:26:06.448 INFO ProgressMeter - 9:40707696 20.7 1267000 61315.6
01:27:40.620 INFO ProgressMeter - 10:42360309 22.2 1286000 57841.7
01:27:50.763 INFO ProgressMeter - X:58563346 22.4 1310000 58476.5
01:28:04.094 INFO ProgressMeter - 10:42385022 22.6 1335000 59007.3
01:28:14.381 INFO ProgressMeter - 2:92289936 22.8 1362000 59747.9
01:28:24.502 INFO ProgressMeter - 2:92305325 23.0 1387000 60397.7
01:28:34.740 INFO ProgressMeter - GL000226.1:1 23.1 1413000 61076.0
01:30:10.612 INFO ProgressMeter - 4:49119710 24.7 1429000 57777.2
01:30:20.722 INFO ProgressMeter - 8:43094689 24.9 1453000 58350.0
01:30:31.244 INFO ProgressMeter - 4:49112451 25.1 1478000 58938.9
01:30:41.460 INFO ProgressMeter - 8:43092746 25.2 1503000 59531.6
01:30:51.532 INFO ProgressMeter - X:61822719 25.4 1526000 60043.4
01:31:01.773 INFO ProgressMeter - 11:51587886 25.6 1552000 60659.0
01:32:35.877 INFO ProgressMeter - 4:49093404 27.2 1571000 57855.1
01:32:46.016 INFO ProgressMeter - 8:86796153 27.3 1593000 58302.5
01:32:59.075 INFO ProgressMeter - 4:110843520 27.5 1617000 58713.1
01:33:09.158 INFO ProgressMeter - 10:42527023 27.7 1643000 59295.4
01:33:19.322 INFO ProgressMeter - 4:49638750 27.9 1670000 59903.6
01:33:29.637 INFO ProgressMeter - 4:80369565 28.1 1697000 60499.0
01:35:06.764 INFO ProgressMeter - 10:42527023 29.7 1713000 57737.4
01:35:16.873 INFO ProgressMeter - 20:13980909 29.8 1739000 58282.7
01:35:26.918 INFO ProgressMeter - 1:142696519 30.0 1765000 58824.1
01:35:36.991 INFO ProgressMeter - 16:29417176 30.2 1790000 59325.3
01:35:47.455 INFO ProgressMeter - 11:51587719 30.3 1815000 59808.2
01:35:57.517 INFO ProgressMeter - 1:144509261 30.5 1842000 60364.3
01:37:33.368 INFO ProgressMeter - 11:93151423 32.1 1855000 57766.2
01:37:43.545 INFO ProgressMeter - 4:49121539 32.3 1881000 58268.0
01:37:53.729 INFO ProgressMeter - 8:26526668 32.5 1908000 58795.3
01:38:03.879 INFO ProgressMeter - 8:7091841 32.6 1935000 59318.1
01:38:14.278 INFO ProgressMeter - 2:39379147 32.8 1960000 59766.9
01:38:27.342 INFO ProgressMeter - 2:92295814 33.0 1982000 60039.1
01:39:58.683 INFO ProgressMeter - 4:49097841 34.5 1999000 57884.8
01:40:09.306 INFO ProgressMeter - 15:32813125 34.7 2022000 58252.1
01:40:19.404 INFO ProgressMeter - 1:120566793 34.9 2049000 58745.1
01:40:29.636 INFO ProgressMeter - GL000206.1:4758 35.1 2077000 59258.1
01:40:39.717 INFO ProgressMeter - 10:42527029 35.2 2103000 59713.7
01:40:49.944 INFO ProgressMeter - 8:43093647 35.4 2127000 60104.3
01:42:25.680 INFO ProgressMeter - 4:49633315 37.0 2141000 57889.8
01:42:36.766 INFO ProgressMeter - 1:243348486 37.2 2166000 58274.6
01:42:46.857 INFO ProgressMeter - 11:51587980 37.3 2193000 58735.2
01:42:57.153 INFO ProgressMeter - GL000199.1:66929 37.5 2220000 59186.3
01:43:07.230 INFO ProgressMeter - 16:29516809 37.7 2247000 59639.1
01:43:18.301 INFO ProgressMeter - 10:42383228 37.9 2273000 60035.2
01:44:54.879 INFO ProgressMeter - 8:43093982 39.5 2284000 57865.7
01:45:04.974 INFO ProgressMeter - 2:151341970 39.6 2309000 58250.7
01:45:15.366 INFO ProgressMeter - 8:70605117 39.8 2334000 58625.2
01:45:25.685 INFO ProgressMeter - 7:61967158 40.0 2361000 59048.4
01:45:35.849 INFO ProgressMeter - 10:42389242 40.2 2387000 59446.8
01:45:46.100 INFO ProgressMeter - 7:87991797 40.3 2412000 59814.9
01:47:20.311 INFO ProgressMeter - GL000199.1:82902 41.9 2428000 57954.9
01:47:30.487 INFO ProgressMeter - 19:27731783 42.1 2454000 58339.4
01:47:40.654 INFO ProgressMeter - 1:232792690 42.2 2478000 58673.6
01:47:50.985 INFO ProgressMeter - Y:58975182 42.4 2505000 59072.1
01:48:01.248 INFO ProgressMeter - 21:10140166 42.6 2530000 59421.9
01:48:11.297 INFO ProgressMeter - GL000199.1:65165 42.7 2556000 59797.3
01:49:43.723 INFO ProgressMeter - GL000216.1:137055 44.3 2571000 58056.0
01:49:54.085 INFO ProgressMeter - 19:44812022 44.5 2590000 58257.9
01:50:04.105 INFO ProgressMeter - 19:20585171 44.6 2617000 58644.9
01:50:15.007 INFO ProgressMeter - 8:43822061 44.8 2643000 58987.4
01:50:25.070 INFO ProgressMeter - 17:22253432 45.0 2669000 59345.5
01:50:35.356 INFO ProgressMeter - 17:18426340 45.1 2696000 59718.2
01:52:07.937 INFO ProgressMeter - 11:51578863 46.7 2712000 58087.3
01:52:18.021 INFO ProgressMeter - 10:42383918 46.9 2736000 58391.1
01:52:28.243 INFO ProgressMeter - 2:92313525 47.0 2762000 58732.4
01:52:38.573 INFO ProgressMeter - 8:43093982 47.2 2786000 59026.7
01:52:50.105 INFO ProgressMeter - 2:92295887 47.4 2807000 59230.4
01:53:00.430 INFO ProgressMeter - 2:242948556 47.6 2836000 59625.8
01:54:37.708 INFO ProgressMeter - 10:42534857 49.2 2855000 58046.7
01:54:47.951 INFO ProgressMeter - 1:121279511 49.4 2880000 58352.4
01:54:58.327 INFO ProgressMeter - 2:92318057 49.5 2906000 58673.6
01:55:08.765 INFO ProgressMeter - X:58567484 49.7 2932000 58991.4
01:55:20.153 INFO ProgressMeter - 8:12374137 49.9 2954000 59207.9
01:55:30.289 INFO ProgressMeter - 4:49115929 50.1 2982000 59567.4
01:57:07.751 INFO ProgressMeter - 10:39125209 51.7 2998000 58004.9
01:57:18.088 INFO ProgressMeter - 4:49098816 51.9 3023000 58294.3
01:57:28.242 INFO ProgressMeter - 4:49154463 52.0 3050000 58623.6
01:57:38.287 INFO ProgressMeter - 1:121484058 52.2 3075000 58914.6
01:57:48.311 INFO ProgressMeter - GL000226.1:8389 52.4 3102000 59242.2
01:57:59.473 INFO ProgressMeter - 9:69763098 52.5 3117000 59318.0
01:59:34.897 INFO ProgressMeter - 7:61126994 54.1 3140000 58000.2
01:59:44.914 INFO ProgressMeter - 8:43093967 54.3 3166000 58300.7
01:59:55.146 INFO ProgressMeter - GL000226.1:5219 54.5 3193000 58613.8
02:00:03.697 INFO ProgressMeter - 8:43093970 54.6 3216162 58885.0
02:00:03.698 INFO ProgressMeter - Traversal complete. Processed 3216162 total records in 54.6 minutes.
Could not delete file /tmp/sortingcollection.9668252126730271187.tmp
Could not delete file /tmp/sortingcollection.9452243885888270287.tmp
Could not delete file /tmp/sortingcollection.7364283606548767487.tmp
Could not delete file /tmp/sortingcollection.7875973685239915467.tmp
Could not delete file /tmp/sortingcollection.752684419828232247.tmp
02:00:57.091 INFO TransferReadTags - Shutting down engine
[May 7, 2025 at 2:00:57 AM EDT] org.broadinstitute.hellbender.tools.walkers.qc.TransferReadTags done. Elapsed time: 55.53 minutes.
Runtime.totalMemory()=15212625920
htsjdk.samtools.util.RuntimeIOException: java.nio.file.NoSuchFileException: /tmp/sortingcollection.9668252126730271187.tmp
at htsjdk.samtools.util.SortingCollection$FileRecordIterator.<init style="background-repeat: no-repeat; box-sizing: inherit; padding: 0px; margin: 0px;">(SortingCollection.java:605)
at htsjdk.samtools.util.SortingCollection$MergingIterator.<init style="background-repeat: no-repeat; box-sizing: inherit; padding: 0px; margin: 0px;">(SortingCollection.java:511)
at htsjdk.samtools.util.SortingCollection.iterator(SortingCollection.java:296)
at htsjdk.samtools.SAMFileWriterImpl.close(SAMFileWriterImpl.java:226)
at htsjdk.samtools.AsyncSAMFileWriter.synchronouslyClose(AsyncSAMFileWriter.java:38)
at htsjdk.samtools.util.AbstractAsyncWriter.close(AbstractAsyncWriter.java:89)
at org.broadinstitute.hellbender.utils.read.SAMFileGATKReadWriter.close(SAMFileGATKReadWriter.java:26)
at org.broadinstitute.hellbender.tools.walkers.qc.TransferReadTags.onTraversalSuccess(TransferReadTags.java:171)
at org.broadinstitute.hellbender.engine.GATKTool.doWork(GATKTool.java:1123)
at org.broadinstitute.hellbender.cmdline.CommandLineProgram.runTool(CommandLineProgram.java:150)
at org.broadinstitute.hellbender.cmdline.CommandLineProgram.instanceMainPostParseArgs(CommandLineProgram.java:203)
at org.broadinstitute.hellbender.cmdline.CommandLineProgram.instanceMain(CommandLineProgram.java:222)
at org.broadinstitute.hellbender.Main.runCommandLineProgram(Main.java:166)
at org.broadinstitute.hellbender.Main.mainEntry(Main.java:209)
at org.broadinstitute.hellbender.Main.main(Main.java:306)
Caused by: java.nio.file.NoSuchFileException: /tmp/sortingcollection.9668252126730271187.tmp
at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:92)
at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:106)
at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
at java.base/sun.nio.fs.UnixFileSystemProvider.newByteChannel(UnixFileSystemProvider.java:218)
at java.base/java.nio.file.Files.newByteChannel(Files.java:380)
at java.base/java.nio.file.Files.newByteChannel(Files.java:432)
at java.base/java.nio.file.spi.FileSystemProvider.newInputStream(FileSystemProvider.java:422)
at java.base/java.nio.file.Files.newInputStream(Files.java:160)
at htsjdk.samtools.util.SortingCollection$FileRecordIterator.<init style="background-repeat: no-repeat; box-sizing: inherit; padding: 0px; margin: 0px;">(SortingCollection.java:600)
... 14 more</init></init></init></pre></code></div></div></div></div>

When looking in /temp these files are indeed not present, but also multiple other temp files with the /tmp/sortingcollection.{uuid}.tmp format do remain.