Class org.broadinstitute.hellbender.engine.spark.datasources.ReadsSparkSourceUnitTest

17:38:26.171 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.173 INFO  MemoryStore - Block broadcast_536 stored as values in memory (estimated size 297.9 KiB, free 1918.1 MiB)
17:38:26.178 INFO  MemoryStore - Block broadcast_536_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1918.0 MiB)
17:38:26.179 INFO  BlockManagerInfo - Added broadcast_536_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.6 MiB)
17:38:26.179 INFO  SparkContext - Created broadcast 536 from newAPIHadoopFile at PathSplitSource.java:96
17:38:26.197 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.197 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.199 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.201 INFO  MemoryStore - Block broadcast_537 stored as values in memory (estimated size 297.9 KiB, free 1917.7 MiB)
17:38:26.206 INFO  MemoryStore - Block broadcast_537_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1917.7 MiB)
17:38:26.207 INFO  BlockManagerInfo - Added broadcast_537_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.5 MiB)
17:38:26.207 INFO  SparkContext - Created broadcast 537 from newAPIHadoopFile at PathSplitSource.java:96
17:38:26.228 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:111
17:38:26.229 INFO  DAGScheduler - Got job 201 (collect at ReadsSparkSourceUnitTest.java:111) with 4 output partitions
17:38:26.229 INFO  DAGScheduler - Final stage: ResultStage 265 (collect at ReadsSparkSourceUnitTest.java:111)
17:38:26.229 INFO  DAGScheduler - Parents of final stage: List()
17:38:26.229 INFO  DAGScheduler - Missing parents: List()
17:38:26.229 INFO  DAGScheduler - Submitting ResultStage 265 (ParallelCollectionRDD[1270] at parallelize at ReadsSparkSourceUnitTest.java:310), which has no missing parents
17:38:26.229 INFO  MemoryStore - Block broadcast_538 stored as values in memory (estimated size 3.0 KiB, free 1917.7 MiB)
17:38:26.229 INFO  MemoryStore - Block broadcast_538_piece0 stored as bytes in memory (estimated size 1777.0 B, free 1917.7 MiB)
17:38:26.230 INFO  BlockManagerInfo - Added broadcast_538_piece0 in memory on localhost:37953 (size: 1777.0 B, free: 1919.5 MiB)
17:38:26.230 INFO  SparkContext - Created broadcast 538 from broadcast at DAGScheduler.scala:1580
17:38:26.231 INFO  DAGScheduler - Submitting 4 missing tasks from ResultStage 265 (ParallelCollectionRDD[1270] at parallelize at ReadsSparkSourceUnitTest.java:310) (first 15 tasks are for partitions Vector(0, 1, 2, 3))
17:38:26.231 INFO  TaskSchedulerImpl - Adding task set 265.0 with 4 tasks resource profile 0
17:38:26.231 INFO  TaskSetManager - Starting task 0.0 in stage 265.0 (TID 321) (localhost, executor driver, partition 0, PROCESS_LOCAL, 47080 bytes) 
17:38:26.232 INFO  TaskSetManager - Starting task 1.0 in stage 265.0 (TID 322) (localhost, executor driver, partition 1, PROCESS_LOCAL, 47194 bytes) 
17:38:26.232 INFO  TaskSetManager - Starting task 2.0 in stage 265.0 (TID 323) (localhost, executor driver, partition 2, PROCESS_LOCAL, 47105 bytes) 
17:38:26.232 INFO  TaskSetManager - Starting task 3.0 in stage 265.0 (TID 324) (localhost, executor driver, partition 3, PROCESS_LOCAL, 47530 bytes) 
17:38:26.232 INFO  Executor - Running task 0.0 in stage 265.0 (TID 321)
17:38:26.232 INFO  Executor - Running task 1.0 in stage 265.0 (TID 322)
17:38:26.232 INFO  Executor - Running task 2.0 in stage 265.0 (TID 323)
17:38:26.233 INFO  Executor - Running task 3.0 in stage 265.0 (TID 324)
17:38:26.234 INFO  Executor - Finished task 0.0 in stage 265.0 (TID 321). 40312 bytes result sent to driver
17:38:26.234 INFO  Executor - Finished task 3.0 in stage 265.0 (TID 324). 40762 bytes result sent to driver
17:38:26.234 INFO  Executor - Finished task 2.0 in stage 265.0 (TID 323). 40380 bytes result sent to driver
17:38:26.235 INFO  Executor - Finished task 1.0 in stage 265.0 (TID 322). 40469 bytes result sent to driver
17:38:26.235 INFO  TaskSetManager - Finished task 2.0 in stage 265.0 (TID 323) in 3 ms on localhost (executor driver) (1/4)
17:38:26.235 INFO  TaskSetManager - Finished task 1.0 in stage 265.0 (TID 322) in 4 ms on localhost (executor driver) (2/4)
17:38:26.235 INFO  TaskSetManager - Finished task 3.0 in stage 265.0 (TID 324) in 3 ms on localhost (executor driver) (3/4)
17:38:26.235 INFO  TaskSetManager - Finished task 0.0 in stage 265.0 (TID 321) in 4 ms on localhost (executor driver) (4/4)
17:38:26.235 INFO  TaskSchedulerImpl - Removed TaskSet 265.0, whose tasks have all completed, from pool 
17:38:26.236 INFO  DAGScheduler - ResultStage 265 (collect at ReadsSparkSourceUnitTest.java:111) finished in 0.007 s
17:38:26.236 INFO  DAGScheduler - Job 201 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:26.236 INFO  TaskSchedulerImpl - Killing all running tasks in stage 265: Stage finished
17:38:26.236 INFO  DAGScheduler - Job 201 finished: collect at ReadsSparkSourceUnitTest.java:111, took 0.007822 s
17:38:26.237 INFO  FileInputFormat - Total input files to process : 1
17:38:26.271 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:112
17:38:26.271 INFO  DAGScheduler - Got job 202 (collect at ReadsSparkSourceUnitTest.java:112) with 1 output partitions
17:38:26.272 INFO  DAGScheduler - Final stage: ResultStage 266 (collect at ReadsSparkSourceUnitTest.java:112)
17:38:26.272 INFO  DAGScheduler - Parents of final stage: List()
17:38:26.272 INFO  DAGScheduler - Missing parents: List()
17:38:26.272 INFO  DAGScheduler - Submitting ResultStage 266 (MapPartitionsRDD[1277] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:26.287 INFO  MemoryStore - Block broadcast_539 stored as values in memory (estimated size 426.2 KiB, free 1917.3 MiB)
17:38:26.291 INFO  BlockManagerInfo - Removed broadcast_536_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.6 MiB)
17:38:26.291 INFO  BlockManagerInfo - Removed broadcast_532_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.6 MiB)
17:38:26.291 INFO  MemoryStore - Block broadcast_539_piece0 stored as bytes in memory (estimated size 153.6 KiB, free 1917.5 MiB)
17:38:26.292 INFO  BlockManagerInfo - Added broadcast_539_piece0 in memory on localhost:37953 (size: 153.6 KiB, free: 1919.5 MiB)
17:38:26.292 INFO  SparkContext - Created broadcast 539 from broadcast at DAGScheduler.scala:1580
17:38:26.292 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 266 (MapPartitionsRDD[1277] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:26.292 INFO  BlockManagerInfo - Removed broadcast_525_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.5 MiB)
17:38:26.292 INFO  TaskSchedulerImpl - Adding task set 266.0 with 1 tasks resource profile 0
17:38:26.292 INFO  BlockManagerInfo - Removed broadcast_533_piece0 on localhost:37953 in memory (size: 54.5 KiB, free: 1919.6 MiB)
17:38:26.293 INFO  TaskSetManager - Starting task 0.0 in stage 266.0 (TID 325) (localhost, executor driver, partition 0, PROCESS_LOCAL, 7838 bytes) 
17:38:26.293 INFO  Executor - Running task 0.0 in stage 266.0 (TID 325)
17:38:26.293 INFO  BlockManagerInfo - Removed broadcast_535_piece0 on localhost:37953 in memory (size: 54.5 KiB, free: 1919.6 MiB)
17:38:26.294 INFO  BlockManagerInfo - Removed broadcast_538_piece0 on localhost:37953 in memory (size: 1777.0 B, free: 1919.7 MiB)
17:38:26.294 INFO  BlockManagerInfo - Removed broadcast_531_piece0 on localhost:37953 in memory (size: 233.0 B, free: 1919.7 MiB)
17:38:26.295 INFO  BlockManagerInfo - Removed broadcast_534_piece0 on localhost:37953 in memory (size: 153.6 KiB, free: 1919.8 MiB)
17:38:26.325 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/NA12878.chr17_69k_70k.dictFix.bam:0+57538
17:38:26.325 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.326 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.327 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.329 INFO  Executor - Finished task 0.0 in stage 266.0 (TID 325). 159572 bytes result sent to driver
17:38:26.329 INFO  TaskSetManager - Finished task 0.0 in stage 266.0 (TID 325) in 36 ms on localhost (executor driver) (1/1)
17:38:26.329 INFO  TaskSchedulerImpl - Removed TaskSet 266.0, whose tasks have all completed, from pool 
17:38:26.329 INFO  DAGScheduler - ResultStage 266 (collect at ReadsSparkSourceUnitTest.java:112) finished in 0.057 s
17:38:26.329 INFO  DAGScheduler - Job 202 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:26.330 INFO  TaskSchedulerImpl - Killing all running tasks in stage 266: Stage finished
17:38:26.330 INFO  DAGScheduler - Job 202 finished: collect at ReadsSparkSourceUnitTest.java:112, took 0.058545 s
17:38:26.331 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.334 INFO  MemoryStore - Block broadcast_540 stored as values in memory (estimated size 298.0 KiB, free 1918.8 MiB)
17:38:26.339 INFO  MemoryStore - Block broadcast_540_piece0 stored as bytes in memory (estimated size 50.3 KiB, free 1918.8 MiB)
17:38:26.339 INFO  BlockManagerInfo - Added broadcast_540_piece0 in memory on localhost:37953 (size: 50.3 KiB, free: 1919.8 MiB)
17:38:26.339 INFO  SparkContext - Created broadcast 540 from newAPIHadoopFile at PathSplitSource.java:96
17:38:26.357 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.357 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.361 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.363 INFO  MemoryStore - Block broadcast_541 stored as values in memory (estimated size 298.0 KiB, free 1918.5 MiB)
17:38:26.368 INFO  MemoryStore - Block broadcast_541_piece0 stored as bytes in memory (estimated size 50.3 KiB, free 1918.4 MiB)
17:38:26.368 INFO  BlockManagerInfo - Added broadcast_541_piece0 in memory on localhost:37953 (size: 50.3 KiB, free: 1919.7 MiB)
17:38:26.368 INFO  SparkContext - Created broadcast 541 from newAPIHadoopFile at PathSplitSource.java:96
17:38:26.390 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:111
17:38:26.390 INFO  DAGScheduler - Got job 203 (collect at ReadsSparkSourceUnitTest.java:111) with 4 output partitions
17:38:26.390 INFO  DAGScheduler - Final stage: ResultStage 267 (collect at ReadsSparkSourceUnitTest.java:111)
17:38:26.390 INFO  DAGScheduler - Parents of final stage: List()
17:38:26.390 INFO  DAGScheduler - Missing parents: List()
17:38:26.390 INFO  DAGScheduler - Submitting ResultStage 267 (ParallelCollectionRDD[1283] at parallelize at ReadsSparkSourceUnitTest.java:310), which has no missing parents
17:38:26.391 INFO  MemoryStore - Block broadcast_542 stored as values in memory (estimated size 3.0 KiB, free 1918.4 MiB)
17:38:26.391 INFO  MemoryStore - Block broadcast_542_piece0 stored as bytes in memory (estimated size 1778.0 B, free 1918.4 MiB)
17:38:26.391 INFO  BlockManagerInfo - Added broadcast_542_piece0 in memory on localhost:37953 (size: 1778.0 B, free: 1919.7 MiB)
17:38:26.391 INFO  SparkContext - Created broadcast 542 from broadcast at DAGScheduler.scala:1580
17:38:26.391 INFO  DAGScheduler - Submitting 4 missing tasks from ResultStage 267 (ParallelCollectionRDD[1283] at parallelize at ReadsSparkSourceUnitTest.java:310) (first 15 tasks are for partitions Vector(0, 1, 2, 3))
17:38:26.391 INFO  TaskSchedulerImpl - Adding task set 267.0 with 4 tasks resource profile 0
17:38:26.392 INFO  TaskSetManager - Starting task 0.0 in stage 267.0 (TID 326) (localhost, executor driver, partition 0, PROCESS_LOCAL, 169886 bytes) 
17:38:26.393 INFO  TaskSetManager - Starting task 1.0 in stage 267.0 (TID 327) (localhost, executor driver, partition 1, PROCESS_LOCAL, 170093 bytes) 
17:38:26.393 INFO  TaskSetManager - Starting task 2.0 in stage 267.0 (TID 328) (localhost, executor driver, partition 2, PROCESS_LOCAL, 170081 bytes) 
17:38:26.393 INFO  TaskSetManager - Starting task 3.0 in stage 267.0 (TID 329) (localhost, executor driver, partition 3, PROCESS_LOCAL, 169419 bytes) 
17:38:26.393 INFO  Executor - Running task 0.0 in stage 267.0 (TID 326)
17:38:26.393 INFO  Executor - Running task 2.0 in stage 267.0 (TID 328)
17:38:26.393 INFO  Executor - Running task 3.0 in stage 267.0 (TID 329)
17:38:26.393 INFO  Executor - Running task 1.0 in stage 267.0 (TID 327)
17:38:26.395 INFO  Executor - Finished task 2.0 in stage 267.0 (TID 328). 163313 bytes result sent to driver
17:38:26.396 INFO  Executor - Finished task 0.0 in stage 267.0 (TID 326). 163161 bytes result sent to driver
17:38:26.396 INFO  Executor - Finished task 3.0 in stage 267.0 (TID 329). 162694 bytes result sent to driver
17:38:26.396 INFO  Executor - Finished task 1.0 in stage 267.0 (TID 327). 163368 bytes result sent to driver
17:38:26.396 INFO  TaskSetManager - Finished task 2.0 in stage 267.0 (TID 328) in 3 ms on localhost (executor driver) (1/4)
17:38:26.397 INFO  TaskSetManager - Finished task 0.0 in stage 267.0 (TID 326) in 5 ms on localhost (executor driver) (2/4)
17:38:26.397 INFO  TaskSetManager - Finished task 1.0 in stage 267.0 (TID 327) in 5 ms on localhost (executor driver) (3/4)
17:38:26.397 INFO  TaskSetManager - Finished task 3.0 in stage 267.0 (TID 329) in 4 ms on localhost (executor driver) (4/4)
17:38:26.397 INFO  TaskSchedulerImpl - Removed TaskSet 267.0, whose tasks have all completed, from pool 
17:38:26.397 INFO  DAGScheduler - ResultStage 267 (collect at ReadsSparkSourceUnitTest.java:111) finished in 0.007 s
17:38:26.398 INFO  DAGScheduler - Job 203 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:26.398 INFO  TaskSchedulerImpl - Killing all running tasks in stage 267: Stage finished
17:38:26.398 INFO  DAGScheduler - Job 203 finished: collect at ReadsSparkSourceUnitTest.java:111, took 0.007880 s
17:38:26.398 INFO  FileInputFormat - Total input files to process : 1
17:38:26.430 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:112
17:38:26.430 INFO  DAGScheduler - Got job 204 (collect at ReadsSparkSourceUnitTest.java:112) with 1 output partitions
17:38:26.431 INFO  DAGScheduler - Final stage: ResultStage 268 (collect at ReadsSparkSourceUnitTest.java:112)
17:38:26.431 INFO  DAGScheduler - Parents of final stage: List()
17:38:26.431 INFO  DAGScheduler - Missing parents: List()
17:38:26.431 INFO  DAGScheduler - Submitting ResultStage 268 (MapPartitionsRDD[1290] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:26.446 INFO  MemoryStore - Block broadcast_543 stored as values in memory (estimated size 426.2 KiB, free 1918.0 MiB)
17:38:26.447 INFO  MemoryStore - Block broadcast_543_piece0 stored as bytes in memory (estimated size 153.6 KiB, free 1917.8 MiB)
17:38:26.447 INFO  BlockManagerInfo - Added broadcast_543_piece0 in memory on localhost:37953 (size: 153.6 KiB, free: 1919.6 MiB)
17:38:26.447 INFO  SparkContext - Created broadcast 543 from broadcast at DAGScheduler.scala:1580
17:38:26.447 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 268 (MapPartitionsRDD[1290] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:26.447 INFO  TaskSchedulerImpl - Adding task set 268.0 with 1 tasks resource profile 0
17:38:26.448 INFO  TaskSetManager - Starting task 0.0 in stage 268.0 (TID 330) (localhost, executor driver, partition 0, PROCESS_LOCAL, 7883 bytes) 
17:38:26.448 INFO  Executor - Running task 0.0 in stage 268.0 (TID 330)
17:38:26.479 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/tools/BQSR/HiSeq.1mb.1RG.2k_lines.alternate.bam:0+221635
17:38:26.480 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.481 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.488 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.495 INFO  BlockManagerInfo - Removed broadcast_539_piece0 on localhost:37953 in memory (size: 153.6 KiB, free: 1919.7 MiB)
17:38:26.496 INFO  BlockManagerInfo - Removed broadcast_537_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.8 MiB)
17:38:26.496 INFO  Executor - Finished task 0.0 in stage 268.0 (TID 330). 650227 bytes result sent to driver
17:38:26.496 INFO  BlockManagerInfo - Removed broadcast_542_piece0 on localhost:37953 in memory (size: 1778.0 B, free: 1919.8 MiB)
17:38:26.496 INFO  BlockManagerInfo - Removed broadcast_540_piece0 on localhost:37953 in memory (size: 50.3 KiB, free: 1919.8 MiB)
17:38:26.497 INFO  TaskSetManager - Finished task 0.0 in stage 268.0 (TID 330) in 49 ms on localhost (executor driver) (1/1)
17:38:26.497 INFO  TaskSchedulerImpl - Removed TaskSet 268.0, whose tasks have all completed, from pool 
17:38:26.497 INFO  DAGScheduler - ResultStage 268 (collect at ReadsSparkSourceUnitTest.java:112) finished in 0.066 s
17:38:26.497 INFO  DAGScheduler - Job 204 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:26.497 INFO  TaskSchedulerImpl - Killing all running tasks in stage 268: Stage finished
17:38:26.497 INFO  DAGScheduler - Job 204 finished: collect at ReadsSparkSourceUnitTest.java:112, took 0.067192 s
17:38:26.498 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.500 INFO  MemoryStore - Block broadcast_544 stored as values in memory (estimated size 298.0 KiB, free 1918.8 MiB)
17:38:26.506 INFO  MemoryStore - Block broadcast_544_piece0 stored as bytes in memory (estimated size 50.3 KiB, free 1918.8 MiB)
17:38:26.506 INFO  BlockManagerInfo - Added broadcast_544_piece0 in memory on localhost:37953 (size: 50.3 KiB, free: 1919.8 MiB)
17:38:26.506 INFO  SparkContext - Created broadcast 544 from newAPIHadoopFile at PathSplitSource.java:96
17:38:26.524 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.524 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.528 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.529 INFO  MemoryStore - Block broadcast_545 stored as values in memory (estimated size 298.0 KiB, free 1918.5 MiB)
17:38:26.535 INFO  MemoryStore - Block broadcast_545_piece0 stored as bytes in memory (estimated size 50.3 KiB, free 1918.4 MiB)
17:38:26.535 INFO  BlockManagerInfo - Added broadcast_545_piece0 in memory on localhost:37953 (size: 50.3 KiB, free: 1919.7 MiB)
17:38:26.535 INFO  SparkContext - Created broadcast 545 from newAPIHadoopFile at PathSplitSource.java:96
17:38:26.557 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:111
17:38:26.557 INFO  DAGScheduler - Got job 205 (collect at ReadsSparkSourceUnitTest.java:111) with 4 output partitions
17:38:26.557 INFO  DAGScheduler - Final stage: ResultStage 269 (collect at ReadsSparkSourceUnitTest.java:111)
17:38:26.557 INFO  DAGScheduler - Parents of final stage: List()
17:38:26.557 INFO  DAGScheduler - Missing parents: List()
17:38:26.557 INFO  DAGScheduler - Submitting ResultStage 269 (ParallelCollectionRDD[1296] at parallelize at ReadsSparkSourceUnitTest.java:310), which has no missing parents
17:38:26.557 INFO  MemoryStore - Block broadcast_546 stored as values in memory (estimated size 3.0 KiB, free 1918.4 MiB)
17:38:26.558 INFO  MemoryStore - Block broadcast_546_piece0 stored as bytes in memory (estimated size 1778.0 B, free 1918.4 MiB)
17:38:26.558 INFO  BlockManagerInfo - Added broadcast_546_piece0 in memory on localhost:37953 (size: 1778.0 B, free: 1919.7 MiB)
17:38:26.558 INFO  SparkContext - Created broadcast 546 from broadcast at DAGScheduler.scala:1580
17:38:26.558 INFO  DAGScheduler - Submitting 4 missing tasks from ResultStage 269 (ParallelCollectionRDD[1296] at parallelize at ReadsSparkSourceUnitTest.java:310) (first 15 tasks are for partitions Vector(0, 1, 2, 3))
17:38:26.558 INFO  TaskSchedulerImpl - Adding task set 269.0 with 4 tasks resource profile 0
17:38:26.559 INFO  TaskSetManager - Starting task 0.0 in stage 269.0 (TID 331) (localhost, executor driver, partition 0, PROCESS_LOCAL, 169886 bytes) 
17:38:26.559 INFO  TaskSetManager - Starting task 1.0 in stage 269.0 (TID 332) (localhost, executor driver, partition 1, PROCESS_LOCAL, 170093 bytes) 
17:38:26.559 INFO  TaskSetManager - Starting task 2.0 in stage 269.0 (TID 333) (localhost, executor driver, partition 2, PROCESS_LOCAL, 170081 bytes) 
17:38:26.560 INFO  TaskSetManager - Starting task 3.0 in stage 269.0 (TID 334) (localhost, executor driver, partition 3, PROCESS_LOCAL, 169419 bytes) 
17:38:26.560 INFO  Executor - Running task 0.0 in stage 269.0 (TID 331)
17:38:26.560 INFO  Executor - Running task 1.0 in stage 269.0 (TID 332)
17:38:26.560 INFO  Executor - Running task 2.0 in stage 269.0 (TID 333)
17:38:26.561 INFO  Executor - Running task 3.0 in stage 269.0 (TID 334)
17:38:26.562 INFO  Executor - Finished task 1.0 in stage 269.0 (TID 332). 163368 bytes result sent to driver
17:38:26.562 INFO  Executor - Finished task 3.0 in stage 269.0 (TID 334). 162651 bytes result sent to driver
17:38:26.562 INFO  Executor - Finished task 0.0 in stage 269.0 (TID 331). 163161 bytes result sent to driver
17:38:26.562 INFO  Executor - Finished task 2.0 in stage 269.0 (TID 333). 163356 bytes result sent to driver
17:38:26.563 INFO  TaskSetManager - Finished task 3.0 in stage 269.0 (TID 334) in 3 ms on localhost (executor driver) (1/4)
17:38:26.563 INFO  TaskSetManager - Finished task 0.0 in stage 269.0 (TID 331) in 4 ms on localhost (executor driver) (2/4)
17:38:26.563 INFO  TaskSetManager - Finished task 1.0 in stage 269.0 (TID 332) in 4 ms on localhost (executor driver) (3/4)
17:38:26.563 INFO  TaskSetManager - Finished task 2.0 in stage 269.0 (TID 333) in 4 ms on localhost (executor driver) (4/4)
17:38:26.563 INFO  TaskSchedulerImpl - Removed TaskSet 269.0, whose tasks have all completed, from pool 
17:38:26.564 INFO  DAGScheduler - ResultStage 269 (collect at ReadsSparkSourceUnitTest.java:111) finished in 0.006 s
17:38:26.564 INFO  DAGScheduler - Job 205 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:26.564 INFO  TaskSchedulerImpl - Killing all running tasks in stage 269: Stage finished
17:38:26.564 INFO  DAGScheduler - Job 205 finished: collect at ReadsSparkSourceUnitTest.java:111, took 0.007098 s
17:38:26.564 INFO  FileInputFormat - Total input files to process : 1
17:38:26.596 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:112
17:38:26.597 INFO  DAGScheduler - Got job 206 (collect at ReadsSparkSourceUnitTest.java:112) with 1 output partitions
17:38:26.597 INFO  DAGScheduler - Final stage: ResultStage 270 (collect at ReadsSparkSourceUnitTest.java:112)
17:38:26.597 INFO  DAGScheduler - Parents of final stage: List()
17:38:26.597 INFO  DAGScheduler - Missing parents: List()
17:38:26.597 INFO  DAGScheduler - Submitting ResultStage 270 (MapPartitionsRDD[1303] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:26.612 INFO  MemoryStore - Block broadcast_547 stored as values in memory (estimated size 426.2 KiB, free 1918.0 MiB)
17:38:26.613 INFO  MemoryStore - Block broadcast_547_piece0 stored as bytes in memory (estimated size 153.7 KiB, free 1917.8 MiB)
17:38:26.613 INFO  BlockManagerInfo - Added broadcast_547_piece0 in memory on localhost:37953 (size: 153.7 KiB, free: 1919.6 MiB)
17:38:26.613 INFO  SparkContext - Created broadcast 547 from broadcast at DAGScheduler.scala:1580
17:38:26.614 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 270 (MapPartitionsRDD[1303] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:26.614 INFO  TaskSchedulerImpl - Adding task set 270.0 with 1 tasks resource profile 0
17:38:26.614 INFO  TaskSetManager - Starting task 0.0 in stage 270.0 (TID 335) (localhost, executor driver, partition 0, PROCESS_LOCAL, 7912 bytes) 
17:38:26.614 INFO  Executor - Running task 0.0 in stage 270.0 (TID 335)
17:38:26.646 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/tools/BQSR/expected.HiSeq.1mb.1RG.2k_lines.alternate.recalibrated.DIQ.bam:0+216896
17:38:26.646 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.647 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.656 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.660 INFO  Executor - Finished task 0.0 in stage 270.0 (TID 335). 650141 bytes result sent to driver
17:38:26.662 INFO  TaskSetManager - Finished task 0.0 in stage 270.0 (TID 335) in 48 ms on localhost (executor driver) (1/1)
17:38:26.662 INFO  TaskSchedulerImpl - Removed TaskSet 270.0, whose tasks have all completed, from pool 
17:38:26.662 INFO  DAGScheduler - ResultStage 270 (collect at ReadsSparkSourceUnitTest.java:112) finished in 0.065 s
17:38:26.662 INFO  DAGScheduler - Job 206 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:26.662 INFO  TaskSchedulerImpl - Killing all running tasks in stage 270: Stage finished
17:38:26.662 INFO  DAGScheduler - Job 206 finished: collect at ReadsSparkSourceUnitTest.java:112, took 0.065636 s
17:38:26.665 INFO  MemoryStore - Block broadcast_548 stored as values in memory (estimated size 536.0 B, free 1917.8 MiB)
17:38:26.665 INFO  MemoryStore - Block broadcast_548_piece0 stored as bytes in memory (estimated size 187.0 B, free 1917.8 MiB)
17:38:26.665 INFO  BlockManagerInfo - Added broadcast_548_piece0 in memory on localhost:37953 (size: 187.0 B, free: 1919.6 MiB)
17:38:26.665 INFO  SparkContext - Created broadcast 548 from broadcast at CramSource.java:114
17:38:26.666 INFO  MemoryStore - Block broadcast_549 stored as values in memory (estimated size 297.9 KiB, free 1917.6 MiB)
17:38:26.671 INFO  BlockManagerInfo - Removed broadcast_547_piece0 on localhost:37953 in memory (size: 153.7 KiB, free: 1919.7 MiB)
17:38:26.672 INFO  BlockManagerInfo - Removed broadcast_545_piece0 on localhost:37953 in memory (size: 50.3 KiB, free: 1919.7 MiB)
17:38:26.672 INFO  BlockManagerInfo - Removed broadcast_543_piece0 on localhost:37953 in memory (size: 153.6 KiB, free: 1919.9 MiB)
17:38:26.672 INFO  BlockManagerInfo - Removed broadcast_546_piece0 on localhost:37953 in memory (size: 1778.0 B, free: 1919.9 MiB)
17:38:26.673 INFO  BlockManagerInfo - Removed broadcast_541_piece0 on localhost:37953 in memory (size: 50.3 KiB, free: 1920.0 MiB)
17:38:26.674 INFO  BlockManagerInfo - Removed broadcast_544_piece0 on localhost:37953 in memory (size: 50.3 KiB, free: 1920.0 MiB)
17:38:26.675 INFO  MemoryStore - Block broadcast_549_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1919.7 MiB)
17:38:26.675 INFO  BlockManagerInfo - Added broadcast_549_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1920.0 MiB)
17:38:26.675 INFO  SparkContext - Created broadcast 549 from newAPIHadoopFile at PathSplitSource.java:96
17:38:26.695 INFO  MemoryStore - Block broadcast_550 stored as values in memory (estimated size 536.0 B, free 1919.7 MiB)
17:38:26.695 INFO  MemoryStore - Block broadcast_550_piece0 stored as bytes in memory (estimated size 187.0 B, free 1919.7 MiB)
17:38:26.695 INFO  BlockManagerInfo - Added broadcast_550_piece0 in memory on localhost:37953 (size: 187.0 B, free: 1920.0 MiB)
17:38:26.695 INFO  SparkContext - Created broadcast 550 from broadcast at CramSource.java:114
17:38:26.696 INFO  MemoryStore - Block broadcast_551 stored as values in memory (estimated size 297.9 KiB, free 1919.4 MiB)
17:38:26.701 INFO  MemoryStore - Block broadcast_551_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1919.3 MiB)
17:38:26.702 INFO  BlockManagerInfo - Added broadcast_551_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.9 MiB)
17:38:26.702 INFO  SparkContext - Created broadcast 551 from newAPIHadoopFile at PathSplitSource.java:96
17:38:26.718 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:111
17:38:26.718 INFO  DAGScheduler - Got job 207 (collect at ReadsSparkSourceUnitTest.java:111) with 4 output partitions
17:38:26.718 INFO  DAGScheduler - Final stage: ResultStage 271 (collect at ReadsSparkSourceUnitTest.java:111)
17:38:26.718 INFO  DAGScheduler - Parents of final stage: List()
17:38:26.718 INFO  DAGScheduler - Missing parents: List()
17:38:26.718 INFO  DAGScheduler - Submitting ResultStage 271 (ParallelCollectionRDD[1308] at parallelize at ReadsSparkSourceUnitTest.java:310), which has no missing parents
17:38:26.719 INFO  MemoryStore - Block broadcast_552 stored as values in memory (estimated size 3.0 KiB, free 1919.3 MiB)
17:38:26.719 INFO  MemoryStore - Block broadcast_552_piece0 stored as bytes in memory (estimated size 1778.0 B, free 1919.3 MiB)
17:38:26.719 INFO  BlockManagerInfo - Added broadcast_552_piece0 in memory on localhost:37953 (size: 1778.0 B, free: 1919.9 MiB)
17:38:26.719 INFO  SparkContext - Created broadcast 552 from broadcast at DAGScheduler.scala:1580
17:38:26.719 INFO  DAGScheduler - Submitting 4 missing tasks from ResultStage 271 (ParallelCollectionRDD[1308] at parallelize at ReadsSparkSourceUnitTest.java:310) (first 15 tasks are for partitions Vector(0, 1, 2, 3))
17:38:26.719 INFO  TaskSchedulerImpl - Adding task set 271.0 with 4 tasks resource profile 0
17:38:26.720 INFO  TaskSetManager - Starting task 0.0 in stage 271.0 (TID 336) (localhost, executor driver, partition 0, PROCESS_LOCAL, 45675 bytes) 
17:38:26.721 INFO  TaskSetManager - Starting task 1.0 in stage 271.0 (TID 337) (localhost, executor driver, partition 1, PROCESS_LOCAL, 45855 bytes) 
17:38:26.721 INFO  TaskSetManager - Starting task 2.0 in stage 271.0 (TID 338) (localhost, executor driver, partition 2, PROCESS_LOCAL, 45795 bytes) 
17:38:26.721 INFO  TaskSetManager - Starting task 3.0 in stage 271.0 (TID 339) (localhost, executor driver, partition 3, PROCESS_LOCAL, 46068 bytes) 
17:38:26.721 INFO  Executor - Running task 1.0 in stage 271.0 (TID 337)
17:38:26.721 INFO  Executor - Running task 3.0 in stage 271.0 (TID 339)
17:38:26.721 INFO  Executor - Running task 2.0 in stage 271.0 (TID 338)
17:38:26.721 INFO  Executor - Running task 0.0 in stage 271.0 (TID 336)
17:38:26.723 INFO  Executor - Finished task 1.0 in stage 271.0 (TID 337). 39087 bytes result sent to driver
17:38:26.723 INFO  Executor - Finished task 0.0 in stage 271.0 (TID 336). 38907 bytes result sent to driver
17:38:26.723 INFO  Executor - Finished task 3.0 in stage 271.0 (TID 339). 39300 bytes result sent to driver
17:38:26.723 INFO  TaskSetManager - Finished task 3.0 in stage 271.0 (TID 339) in 2 ms on localhost (executor driver) (1/4)
17:38:26.724 INFO  TaskSetManager - Finished task 1.0 in stage 271.0 (TID 337) in 4 ms on localhost (executor driver) (2/4)
17:38:26.724 INFO  TaskSetManager - Finished task 0.0 in stage 271.0 (TID 336) in 4 ms on localhost (executor driver) (3/4)
17:38:26.724 INFO  Executor - Finished task 2.0 in stage 271.0 (TID 338). 39070 bytes result sent to driver
17:38:26.724 INFO  TaskSetManager - Finished task 2.0 in stage 271.0 (TID 338) in 3 ms on localhost (executor driver) (4/4)
17:38:26.724 INFO  TaskSchedulerImpl - Removed TaskSet 271.0, whose tasks have all completed, from pool 
17:38:26.725 INFO  DAGScheduler - ResultStage 271 (collect at ReadsSparkSourceUnitTest.java:111) finished in 0.007 s
17:38:26.725 INFO  DAGScheduler - Job 207 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:26.725 INFO  TaskSchedulerImpl - Killing all running tasks in stage 271: Stage finished
17:38:26.725 INFO  DAGScheduler - Job 207 finished: collect at ReadsSparkSourceUnitTest.java:111, took 0.006880 s
17:38:26.725 INFO  FileInputFormat - Total input files to process : 1
17:38:26.748 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:112
17:38:26.749 INFO  DAGScheduler - Got job 208 (collect at ReadsSparkSourceUnitTest.java:112) with 1 output partitions
17:38:26.749 INFO  DAGScheduler - Final stage: ResultStage 272 (collect at ReadsSparkSourceUnitTest.java:112)
17:38:26.749 INFO  DAGScheduler - Parents of final stage: List()
17:38:26.749 INFO  DAGScheduler - Missing parents: List()
17:38:26.749 INFO  DAGScheduler - Submitting ResultStage 272 (MapPartitionsRDD[1314] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:26.759 INFO  MemoryStore - Block broadcast_553 stored as values in memory (estimated size 286.8 KiB, free 1919.0 MiB)
17:38:26.760 INFO  MemoryStore - Block broadcast_553_piece0 stored as bytes in memory (estimated size 103.6 KiB, free 1918.9 MiB)
17:38:26.760 INFO  BlockManagerInfo - Added broadcast_553_piece0 in memory on localhost:37953 (size: 103.6 KiB, free: 1919.8 MiB)
17:38:26.760 INFO  SparkContext - Created broadcast 553 from broadcast at DAGScheduler.scala:1580
17:38:26.761 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 272 (MapPartitionsRDD[1314] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:26.761 INFO  TaskSchedulerImpl - Adding task set 272.0 with 1 tasks resource profile 0
17:38:26.761 INFO  TaskSetManager - Starting task 0.0 in stage 272.0 (TID 340) (localhost, executor driver, partition 0, PROCESS_LOCAL, 7839 bytes) 
17:38:26.761 INFO  Executor - Running task 0.0 in stage 272.0 (TID 340)
17:38:26.785 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/NA12878.chr17_69k_70k.dictFix.cram:0+50619
17:38:26.793 INFO  Executor - Finished task 0.0 in stage 272.0 (TID 340). 154058 bytes result sent to driver
17:38:26.793 INFO  TaskSetManager - Finished task 0.0 in stage 272.0 (TID 340) in 32 ms on localhost (executor driver) (1/1)
17:38:26.793 INFO  TaskSchedulerImpl - Removed TaskSet 272.0, whose tasks have all completed, from pool 
17:38:26.794 INFO  DAGScheduler - ResultStage 272 (collect at ReadsSparkSourceUnitTest.java:112) finished in 0.044 s
17:38:26.794 INFO  DAGScheduler - Job 208 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:26.794 INFO  TaskSchedulerImpl - Killing all running tasks in stage 272: Stage finished
17:38:26.794 INFO  DAGScheduler - Job 208 finished: collect at ReadsSparkSourceUnitTest.java:112, took 0.045499 s
17:38:26.797 INFO  MemoryStore - Block broadcast_554 stored as values in memory (estimated size 608.0 B, free 1918.9 MiB)
17:38:26.801 INFO  MemoryStore - Block broadcast_554_piece0 stored as bytes in memory (estimated size 206.0 B, free 1918.9 MiB)
17:38:26.801 INFO  BlockManagerInfo - Added broadcast_554_piece0 in memory on localhost:37953 (size: 206.0 B, free: 1919.8 MiB)
17:38:26.801 INFO  BlockManagerInfo - Removed broadcast_552_piece0 on localhost:37953 in memory (size: 1778.0 B, free: 1919.8 MiB)
17:38:26.801 INFO  SparkContext - Created broadcast 554 from broadcast at CramSource.java:114
17:38:26.802 INFO  BlockManagerInfo - Removed broadcast_553_piece0 on localhost:37953 in memory (size: 103.6 KiB, free: 1919.9 MiB)
17:38:26.802 INFO  BlockManagerInfo - Removed broadcast_551_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1920.0 MiB)
17:38:26.802 INFO  MemoryStore - Block broadcast_555 stored as values in memory (estimated size 297.9 KiB, free 1919.4 MiB)
17:38:26.803 INFO  BlockManagerInfo - Removed broadcast_549_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1920.0 MiB)
17:38:26.803 INFO  BlockManagerInfo - Removed broadcast_548_piece0 on localhost:37953 in memory (size: 187.0 B, free: 1920.0 MiB)
17:38:26.803 INFO  BlockManagerInfo - Removed broadcast_550_piece0 on localhost:37953 in memory (size: 187.0 B, free: 1920.0 MiB)
17:38:26.808 INFO  MemoryStore - Block broadcast_555_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1919.7 MiB)
17:38:26.808 INFO  BlockManagerInfo - Added broadcast_555_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1920.0 MiB)
17:38:26.808 INFO  SparkContext - Created broadcast 555 from newAPIHadoopFile at PathSplitSource.java:96
17:38:26.826 INFO  MemoryStore - Block broadcast_556 stored as values in memory (estimated size 608.0 B, free 1919.7 MiB)
17:38:26.826 INFO  MemoryStore - Block broadcast_556_piece0 stored as bytes in memory (estimated size 206.0 B, free 1919.7 MiB)
17:38:26.826 INFO  BlockManagerInfo - Added broadcast_556_piece0 in memory on localhost:37953 (size: 206.0 B, free: 1920.0 MiB)
17:38:26.826 INFO  SparkContext - Created broadcast 556 from broadcast at CramSource.java:114
17:38:26.827 INFO  MemoryStore - Block broadcast_557 stored as values in memory (estimated size 297.9 KiB, free 1919.4 MiB)
17:38:26.833 INFO  MemoryStore - Block broadcast_557_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1919.3 MiB)
17:38:26.833 INFO  BlockManagerInfo - Added broadcast_557_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.9 MiB)
17:38:26.833 INFO  SparkContext - Created broadcast 557 from newAPIHadoopFile at PathSplitSource.java:96
17:38:26.849 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:111
17:38:26.849 INFO  DAGScheduler - Got job 209 (collect at ReadsSparkSourceUnitTest.java:111) with 4 output partitions
17:38:26.849 INFO  DAGScheduler - Final stage: ResultStage 273 (collect at ReadsSparkSourceUnitTest.java:111)
17:38:26.849 INFO  DAGScheduler - Parents of final stage: List()
17:38:26.849 INFO  DAGScheduler - Missing parents: List()
17:38:26.850 INFO  DAGScheduler - Submitting ResultStage 273 (ParallelCollectionRDD[1319] at parallelize at ReadsSparkSourceUnitTest.java:310), which has no missing parents
17:38:26.850 INFO  MemoryStore - Block broadcast_558 stored as values in memory (estimated size 3.0 KiB, free 1919.3 MiB)
17:38:26.850 INFO  MemoryStore - Block broadcast_558_piece0 stored as bytes in memory (estimated size 1778.0 B, free 1919.3 MiB)
17:38:26.850 INFO  BlockManagerInfo - Added broadcast_558_piece0 in memory on localhost:37953 (size: 1778.0 B, free: 1919.9 MiB)
17:38:26.851 INFO  SparkContext - Created broadcast 558 from broadcast at DAGScheduler.scala:1580
17:38:26.851 INFO  DAGScheduler - Submitting 4 missing tasks from ResultStage 273 (ParallelCollectionRDD[1319] at parallelize at ReadsSparkSourceUnitTest.java:310) (first 15 tasks are for partitions Vector(0, 1, 2, 3))
17:38:26.851 INFO  TaskSchedulerImpl - Adding task set 273.0 with 4 tasks resource profile 0
17:38:26.851 INFO  TaskSetManager - Starting task 0.0 in stage 273.0 (TID 341) (localhost, executor driver, partition 0, PROCESS_LOCAL, 8303 bytes) 
17:38:26.852 INFO  TaskSetManager - Starting task 1.0 in stage 273.0 (TID 342) (localhost, executor driver, partition 1, PROCESS_LOCAL, 8292 bytes) 
17:38:26.852 INFO  TaskSetManager - Starting task 2.0 in stage 273.0 (TID 343) (localhost, executor driver, partition 2, PROCESS_LOCAL, 8292 bytes) 
17:38:26.852 INFO  TaskSetManager - Starting task 3.0 in stage 273.0 (TID 344) (localhost, executor driver, partition 3, PROCESS_LOCAL, 8184 bytes) 
17:38:26.852 INFO  Executor - Running task 0.0 in stage 273.0 (TID 341)
17:38:26.852 INFO  Executor - Running task 2.0 in stage 273.0 (TID 343)
17:38:26.852 INFO  Executor - Running task 1.0 in stage 273.0 (TID 342)
17:38:26.852 INFO  Executor - Running task 3.0 in stage 273.0 (TID 344)
17:38:26.853 INFO  Executor - Finished task 3.0 in stage 273.0 (TID 344). 1416 bytes result sent to driver
17:38:26.854 INFO  TaskSetManager - Finished task 3.0 in stage 273.0 (TID 344) in 2 ms on localhost (executor driver) (1/4)
17:38:26.854 INFO  Executor - Finished task 0.0 in stage 273.0 (TID 341). 1578 bytes result sent to driver
17:38:26.854 INFO  TaskSetManager - Finished task 0.0 in stage 273.0 (TID 341) in 3 ms on localhost (executor driver) (2/4)
17:38:26.854 INFO  Executor - Finished task 1.0 in stage 273.0 (TID 342). 1567 bytes result sent to driver
17:38:26.855 INFO  TaskSetManager - Finished task 1.0 in stage 273.0 (TID 342) in 4 ms on localhost (executor driver) (3/4)
17:38:26.855 INFO  Executor - Finished task 2.0 in stage 273.0 (TID 343). 1567 bytes result sent to driver
17:38:26.855 INFO  TaskSetManager - Finished task 2.0 in stage 273.0 (TID 343) in 3 ms on localhost (executor driver) (4/4)
17:38:26.855 INFO  TaskSchedulerImpl - Removed TaskSet 273.0, whose tasks have all completed, from pool 
17:38:26.855 INFO  DAGScheduler - ResultStage 273 (collect at ReadsSparkSourceUnitTest.java:111) finished in 0.005 s
17:38:26.856 INFO  DAGScheduler - Job 209 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:26.856 INFO  TaskSchedulerImpl - Killing all running tasks in stage 273: Stage finished
17:38:26.856 INFO  DAGScheduler - Job 209 finished: collect at ReadsSparkSourceUnitTest.java:111, took 0.006459 s
17:38:26.856 INFO  FileInputFormat - Total input files to process : 1
17:38:26.879 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:112
17:38:26.879 INFO  DAGScheduler - Got job 210 (collect at ReadsSparkSourceUnitTest.java:112) with 1 output partitions
17:38:26.879 INFO  DAGScheduler - Final stage: ResultStage 274 (collect at ReadsSparkSourceUnitTest.java:112)
17:38:26.879 INFO  DAGScheduler - Parents of final stage: List()
17:38:26.879 INFO  DAGScheduler - Missing parents: List()
17:38:26.879 INFO  DAGScheduler - Submitting ResultStage 274 (MapPartitionsRDD[1325] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:26.889 INFO  MemoryStore - Block broadcast_559 stored as values in memory (estimated size 286.8 KiB, free 1919.0 MiB)
17:38:26.893 INFO  BlockManagerInfo - Removed broadcast_555_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.9 MiB)
17:38:26.893 INFO  MemoryStore - Block broadcast_559_piece0 stored as bytes in memory (estimated size 103.6 KiB, free 1919.3 MiB)
17:38:26.893 INFO  BlockManagerInfo - Added broadcast_559_piece0 in memory on localhost:37953 (size: 103.6 KiB, free: 1919.8 MiB)
17:38:26.893 INFO  BlockManagerInfo - Removed broadcast_554_piece0 on localhost:37953 in memory (size: 206.0 B, free: 1919.8 MiB)
17:38:26.893 INFO  SparkContext - Created broadcast 559 from broadcast at DAGScheduler.scala:1580
17:38:26.894 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 274 (MapPartitionsRDD[1325] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:26.894 INFO  TaskSchedulerImpl - Adding task set 274.0 with 1 tasks resource profile 0
17:38:26.894 INFO  TaskSetManager - Starting task 0.0 in stage 274.0 (TID 345) (localhost, executor driver, partition 0, PROCESS_LOCAL, 7851 bytes) 
17:38:26.894 INFO  BlockManagerInfo - Removed broadcast_558_piece0 on localhost:37953 in memory (size: 1778.0 B, free: 1919.8 MiB)
17:38:26.895 INFO  Executor - Running task 0.0 in stage 274.0 (TID 345)
17:38:26.917 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/tools/valid.cram:0+13330
17:38:26.920 INFO  Executor - Finished task 0.0 in stage 274.0 (TID 345). 3736 bytes result sent to driver
17:38:26.920 INFO  TaskSetManager - Finished task 0.0 in stage 274.0 (TID 345) in 26 ms on localhost (executor driver) (1/1)
17:38:26.921 INFO  TaskSchedulerImpl - Removed TaskSet 274.0, whose tasks have all completed, from pool 
17:38:26.921 INFO  DAGScheduler - ResultStage 274 (collect at ReadsSparkSourceUnitTest.java:112) finished in 0.042 s
17:38:26.921 INFO  DAGScheduler - Job 210 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:26.921 INFO  TaskSchedulerImpl - Killing all running tasks in stage 274: Stage finished
17:38:26.921 INFO  DAGScheduler - Job 210 finished: collect at ReadsSparkSourceUnitTest.java:112, took 0.042300 s
17:38:26.922 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.924 INFO  MemoryStore - Block broadcast_560 stored as values in memory (estimated size 297.9 KiB, free 1919.0 MiB)
17:38:26.929 INFO  MemoryStore - Block broadcast_560_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1918.9 MiB)
17:38:26.929 INFO  BlockManagerInfo - Added broadcast_560_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.8 MiB)
17:38:26.930 INFO  SparkContext - Created broadcast 560 from newAPIHadoopFile at PathSplitSource.java:96
17:38:26.947 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.948 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 130, Read name 809R9ABXX101220:5:6:17918:145992, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 130, Read name 809R9ABXX101220:5:6:17918:145992, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 130, Read name 809R9ABXX101220:5:6:17918:145992, The unaligned mate start position is 69400, should be 0
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 275, Read name 809R9ABXX101220:5:8:7119:101555, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 275, Read name 809R9ABXX101220:5:8:7119:101555, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 275, Read name 809R9ABXX101220:5:8:7119:101555, The unaligned mate start position is 69471, should be 0
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 419, Read name 809R9ABXX101220:5:48:20204:50350, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 419, Read name 809R9ABXX101220:5:48:20204:50350, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 419, Read name 809R9ABXX101220:5:48:20204:50350, The unaligned mate start position is 69569, should be 0
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 440, Read name 809R9ABXX101220:5:44:13776:49360, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 440, Read name 809R9ABXX101220:5:44:13776:49360, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 440, Read name 809R9ABXX101220:5:44:13776:49360, The unaligned mate start position is 69592, should be 0
17:38:26.951 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:26.952 INFO  MemoryStore - Block broadcast_561 stored as values in memory (estimated size 297.9 KiB, free 1918.6 MiB)
17:38:26.958 INFO  MemoryStore - Block broadcast_561_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1918.6 MiB)
17:38:26.958 INFO  BlockManagerInfo - Added broadcast_561_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.8 MiB)
17:38:26.958 INFO  SparkContext - Created broadcast 561 from newAPIHadoopFile at PathSplitSource.java:96
17:38:26.979 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:111
17:38:26.980 INFO  DAGScheduler - Got job 211 (collect at ReadsSparkSourceUnitTest.java:111) with 4 output partitions
17:38:26.980 INFO  DAGScheduler - Final stage: ResultStage 275 (collect at ReadsSparkSourceUnitTest.java:111)
17:38:26.980 INFO  DAGScheduler - Parents of final stage: List()
17:38:26.980 INFO  DAGScheduler - Missing parents: List()
17:38:26.980 INFO  DAGScheduler - Submitting ResultStage 275 (ParallelCollectionRDD[1331] at parallelize at ReadsSparkSourceUnitTest.java:310), which has no missing parents
17:38:26.980 INFO  MemoryStore - Block broadcast_562 stored as values in memory (estimated size 3.0 KiB, free 1918.6 MiB)
17:38:26.980 INFO  MemoryStore - Block broadcast_562_piece0 stored as bytes in memory (estimated size 1778.0 B, free 1918.6 MiB)
17:38:26.981 INFO  BlockManagerInfo - Added broadcast_562_piece0 in memory on localhost:37953 (size: 1778.0 B, free: 1919.7 MiB)
17:38:26.981 INFO  SparkContext - Created broadcast 562 from broadcast at DAGScheduler.scala:1580
17:38:26.981 INFO  DAGScheduler - Submitting 4 missing tasks from ResultStage 275 (ParallelCollectionRDD[1331] at parallelize at ReadsSparkSourceUnitTest.java:310) (first 15 tasks are for partitions Vector(0, 1, 2, 3))
17:38:26.981 INFO  TaskSchedulerImpl - Adding task set 275.0 with 4 tasks resource profile 0
17:38:26.981 INFO  TaskSetManager - Starting task 0.0 in stage 275.0 (TID 346) (localhost, executor driver, partition 0, PROCESS_LOCAL, 47080 bytes) 
17:38:26.982 INFO  TaskSetManager - Starting task 1.0 in stage 275.0 (TID 347) (localhost, executor driver, partition 1, PROCESS_LOCAL, 47194 bytes) 
17:38:26.982 INFO  TaskSetManager - Starting task 2.0 in stage 275.0 (TID 348) (localhost, executor driver, partition 2, PROCESS_LOCAL, 47105 bytes) 
17:38:26.982 INFO  TaskSetManager - Starting task 3.0 in stage 275.0 (TID 349) (localhost, executor driver, partition 3, PROCESS_LOCAL, 47530 bytes) 
17:38:26.982 INFO  Executor - Running task 1.0 in stage 275.0 (TID 347)
17:38:26.982 INFO  Executor - Running task 0.0 in stage 275.0 (TID 346)
17:38:26.982 INFO  Executor - Running task 3.0 in stage 275.0 (TID 349)
17:38:26.984 INFO  Executor - Running task 2.0 in stage 275.0 (TID 348)
17:38:26.984 INFO  Executor - Finished task 3.0 in stage 275.0 (TID 349). 40762 bytes result sent to driver
17:38:26.984 INFO  Executor - Finished task 0.0 in stage 275.0 (TID 346). 40312 bytes result sent to driver
17:38:26.984 INFO  TaskSetManager - Finished task 3.0 in stage 275.0 (TID 349) in 2 ms on localhost (executor driver) (1/4)
17:38:26.985 INFO  TaskSetManager - Finished task 0.0 in stage 275.0 (TID 346) in 4 ms on localhost (executor driver) (2/4)
17:38:26.985 INFO  Executor - Finished task 1.0 in stage 275.0 (TID 347). 40469 bytes result sent to driver
17:38:26.986 INFO  Executor - Finished task 2.0 in stage 275.0 (TID 348). 40380 bytes result sent to driver
17:38:26.986 INFO  TaskSetManager - Finished task 2.0 in stage 275.0 (TID 348) in 4 ms on localhost (executor driver) (3/4)
17:38:26.986 INFO  TaskSetManager - Finished task 1.0 in stage 275.0 (TID 347) in 4 ms on localhost (executor driver) (4/4)
17:38:26.986 INFO  TaskSchedulerImpl - Removed TaskSet 275.0, whose tasks have all completed, from pool 
17:38:26.986 INFO  DAGScheduler - ResultStage 275 (collect at ReadsSparkSourceUnitTest.java:111) finished in 0.006 s
17:38:26.986 INFO  DAGScheduler - Job 211 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:26.986 INFO  TaskSchedulerImpl - Killing all running tasks in stage 275: Stage finished
17:38:26.987 INFO  DAGScheduler - Job 211 finished: collect at ReadsSparkSourceUnitTest.java:111, took 0.007238 s
17:38:26.987 INFO  FileInputFormat - Total input files to process : 1
17:38:27.019 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:112
17:38:27.019 INFO  DAGScheduler - Got job 212 (collect at ReadsSparkSourceUnitTest.java:112) with 1 output partitions
17:38:27.019 INFO  DAGScheduler - Final stage: ResultStage 276 (collect at ReadsSparkSourceUnitTest.java:112)
17:38:27.019 INFO  DAGScheduler - Parents of final stage: List()
17:38:27.019 INFO  DAGScheduler - Missing parents: List()
17:38:27.020 INFO  DAGScheduler - Submitting ResultStage 276 (MapPartitionsRDD[1338] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:27.035 INFO  MemoryStore - Block broadcast_563 stored as values in memory (estimated size 426.2 KiB, free 1918.2 MiB)
17:38:27.036 INFO  MemoryStore - Block broadcast_563_piece0 stored as bytes in memory (estimated size 153.7 KiB, free 1918.0 MiB)
17:38:27.036 INFO  BlockManagerInfo - Added broadcast_563_piece0 in memory on localhost:37953 (size: 153.7 KiB, free: 1919.6 MiB)
17:38:27.036 INFO  SparkContext - Created broadcast 563 from broadcast at DAGScheduler.scala:1580
17:38:27.036 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 276 (MapPartitionsRDD[1338] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:27.036 INFO  TaskSchedulerImpl - Adding task set 276.0 with 1 tasks resource profile 0
17:38:27.037 INFO  TaskSetManager - Starting task 0.0 in stage 276.0 (TID 350) (localhost, executor driver, partition 0, PROCESS_LOCAL, 7838 bytes) 
17:38:27.037 INFO  Executor - Running task 0.0 in stage 276.0 (TID 350)
17:38:27.069 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/NA12878.chr17_69k_70k.dictFix.bam:0+57538
17:38:27.070 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.070 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.071 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 130, Read name 809R9ABXX101220:5:6:17918:145992, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 130, Read name 809R9ABXX101220:5:6:17918:145992, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 130, Read name 809R9ABXX101220:5:6:17918:145992, The unaligned mate start position is 69400, should be 0
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 275, Read name 809R9ABXX101220:5:8:7119:101555, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 275, Read name 809R9ABXX101220:5:8:7119:101555, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 275, Read name 809R9ABXX101220:5:8:7119:101555, The unaligned mate start position is 69471, should be 0
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 419, Read name 809R9ABXX101220:5:48:20204:50350, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 419, Read name 809R9ABXX101220:5:48:20204:50350, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 419, Read name 809R9ABXX101220:5:48:20204:50350, The unaligned mate start position is 69569, should be 0
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 440, Read name 809R9ABXX101220:5:44:13776:49360, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 440, Read name 809R9ABXX101220:5:44:13776:49360, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 440, Read name 809R9ABXX101220:5:44:13776:49360, The unaligned mate start position is 69592, should be 0
17:38:27.077 INFO  BlockManagerInfo - Removed broadcast_557_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.6 MiB)
17:38:27.077 INFO  Executor - Finished task 0.0 in stage 276.0 (TID 350). 159658 bytes result sent to driver
17:38:27.078 INFO  TaskSetManager - Finished task 0.0 in stage 276.0 (TID 350) in 41 ms on localhost (executor driver) (1/1)
17:38:27.078 INFO  TaskSchedulerImpl - Removed TaskSet 276.0, whose tasks have all completed, from pool 
17:38:27.078 INFO  DAGScheduler - ResultStage 276 (collect at ReadsSparkSourceUnitTest.java:112) finished in 0.058 s
17:38:27.078 INFO  DAGScheduler - Job 212 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:27.078 INFO  TaskSchedulerImpl - Killing all running tasks in stage 276: Stage finished
17:38:27.078 INFO  DAGScheduler - Job 212 finished: collect at ReadsSparkSourceUnitTest.java:112, took 0.059316 s
17:38:27.079 INFO  BlockManagerInfo - Removed broadcast_559_piece0 on localhost:37953 in memory (size: 103.6 KiB, free: 1919.7 MiB)
17:38:27.079 INFO  BlockManagerInfo - Removed broadcast_556_piece0 on localhost:37953 in memory (size: 206.0 B, free: 1919.8 MiB)
17:38:27.080 INFO  BlockManagerInfo - Removed broadcast_560_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.8 MiB)
17:38:27.080 INFO  BlockManagerInfo - Removed broadcast_562_piece0 on localhost:37953 in memory (size: 1778.0 B, free: 1919.8 MiB)
17:38:27.081 INFO  MemoryStore - Block broadcast_564 stored as values in memory (estimated size 536.0 B, free 1919.1 MiB)
17:38:27.081 INFO  MemoryStore - Block broadcast_564_piece0 stored as bytes in memory (estimated size 187.0 B, free 1919.1 MiB)
17:38:27.081 INFO  BlockManagerInfo - Added broadcast_564_piece0 in memory on localhost:37953 (size: 187.0 B, free: 1919.8 MiB)
17:38:27.082 INFO  SparkContext - Created broadcast 564 from broadcast at CramSource.java:114
17:38:27.082 INFO  MemoryStore - Block broadcast_565 stored as values in memory (estimated size 297.9 KiB, free 1918.8 MiB)
17:38:27.088 INFO  MemoryStore - Block broadcast_565_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1918.8 MiB)
17:38:27.088 INFO  BlockManagerInfo - Added broadcast_565_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.8 MiB)
17:38:27.088 INFO  SparkContext - Created broadcast 565 from newAPIHadoopFile at PathSplitSource.java:96
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 129, Read name 809R9ABXX101220:5:6:17918:145992, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 129, Read name 809R9ABXX101220:5:6:17918:145992, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 129, Read name 809R9ABXX101220:5:6:17918:145992, The unaligned mate start position is 69400, should be 0
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 274, Read name 809R9ABXX101220:5:8:7119:101555, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 274, Read name 809R9ABXX101220:5:8:7119:101555, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 274, Read name 809R9ABXX101220:5:8:7119:101555, The unaligned mate start position is 69471, should be 0
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 418, Read name 809R9ABXX101220:5:48:20204:50350, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 418, Read name 809R9ABXX101220:5:48:20204:50350, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 418, Read name 809R9ABXX101220:5:48:20204:50350, The unaligned mate start position is 69569, should be 0
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 439, Read name 809R9ABXX101220:5:44:13776:49360, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 439, Read name 809R9ABXX101220:5:44:13776:49360, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 439, Read name 809R9ABXX101220:5:44:13776:49360, The unaligned mate start position is 69592, should be 0
17:38:27.108 INFO  MemoryStore - Block broadcast_566 stored as values in memory (estimated size 536.0 B, free 1918.8 MiB)
17:38:27.109 INFO  MemoryStore - Block broadcast_566_piece0 stored as bytes in memory (estimated size 187.0 B, free 1918.8 MiB)
17:38:27.109 INFO  BlockManagerInfo - Added broadcast_566_piece0 in memory on localhost:37953 (size: 187.0 B, free: 1919.8 MiB)
17:38:27.109 INFO  SparkContext - Created broadcast 566 from broadcast at CramSource.java:114
17:38:27.110 INFO  MemoryStore - Block broadcast_567 stored as values in memory (estimated size 297.9 KiB, free 1918.5 MiB)
17:38:27.115 INFO  MemoryStore - Block broadcast_567_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1918.4 MiB)
17:38:27.115 INFO  BlockManagerInfo - Added broadcast_567_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.7 MiB)
17:38:27.116 INFO  SparkContext - Created broadcast 567 from newAPIHadoopFile at PathSplitSource.java:96
17:38:27.132 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:111
17:38:27.132 INFO  DAGScheduler - Got job 213 (collect at ReadsSparkSourceUnitTest.java:111) with 4 output partitions
17:38:27.132 INFO  DAGScheduler - Final stage: ResultStage 277 (collect at ReadsSparkSourceUnitTest.java:111)
17:38:27.132 INFO  DAGScheduler - Parents of final stage: List()
17:38:27.132 INFO  DAGScheduler - Missing parents: List()
17:38:27.132 INFO  DAGScheduler - Submitting ResultStage 277 (ParallelCollectionRDD[1343] at parallelize at ReadsSparkSourceUnitTest.java:310), which has no missing parents
17:38:27.133 INFO  MemoryStore - Block broadcast_568 stored as values in memory (estimated size 3.0 KiB, free 1918.4 MiB)
17:38:27.133 INFO  MemoryStore - Block broadcast_568_piece0 stored as bytes in memory (estimated size 1778.0 B, free 1918.4 MiB)
17:38:27.133 INFO  BlockManagerInfo - Added broadcast_568_piece0 in memory on localhost:37953 (size: 1778.0 B, free: 1919.7 MiB)
17:38:27.133 INFO  SparkContext - Created broadcast 568 from broadcast at DAGScheduler.scala:1580
17:38:27.133 INFO  DAGScheduler - Submitting 4 missing tasks from ResultStage 277 (ParallelCollectionRDD[1343] at parallelize at ReadsSparkSourceUnitTest.java:310) (first 15 tasks are for partitions Vector(0, 1, 2, 3))
17:38:27.133 INFO  TaskSchedulerImpl - Adding task set 277.0 with 4 tasks resource profile 0
17:38:27.134 INFO  TaskSetManager - Starting task 0.0 in stage 277.0 (TID 351) (localhost, executor driver, partition 0, PROCESS_LOCAL, 45675 bytes) 
17:38:27.134 INFO  TaskSetManager - Starting task 1.0 in stage 277.0 (TID 352) (localhost, executor driver, partition 1, PROCESS_LOCAL, 45855 bytes) 
17:38:27.135 INFO  TaskSetManager - Starting task 2.0 in stage 277.0 (TID 353) (localhost, executor driver, partition 2, PROCESS_LOCAL, 45795 bytes) 
17:38:27.135 INFO  TaskSetManager - Starting task 3.0 in stage 277.0 (TID 354) (localhost, executor driver, partition 3, PROCESS_LOCAL, 46068 bytes) 
17:38:27.135 INFO  Executor - Running task 0.0 in stage 277.0 (TID 351)
17:38:27.135 INFO  Executor - Running task 3.0 in stage 277.0 (TID 354)
17:38:27.135 INFO  Executor - Running task 1.0 in stage 277.0 (TID 352)
17:38:27.135 INFO  Executor - Running task 2.0 in stage 277.0 (TID 353)
17:38:27.137 INFO  Executor - Finished task 0.0 in stage 277.0 (TID 351). 38907 bytes result sent to driver
17:38:27.137 INFO  Executor - Finished task 3.0 in stage 277.0 (TID 354). 39300 bytes result sent to driver
17:38:27.137 INFO  Executor - Finished task 1.0 in stage 277.0 (TID 352). 39087 bytes result sent to driver
17:38:27.137 INFO  TaskSetManager - Finished task 0.0 in stage 277.0 (TID 351) in 3 ms on localhost (executor driver) (1/4)
17:38:27.137 INFO  Executor - Finished task 2.0 in stage 277.0 (TID 353). 39027 bytes result sent to driver
17:38:27.137 INFO  TaskSetManager - Finished task 3.0 in stage 277.0 (TID 354) in 2 ms on localhost (executor driver) (2/4)
17:38:27.137 INFO  TaskSetManager - Finished task 1.0 in stage 277.0 (TID 352) in 3 ms on localhost (executor driver) (3/4)
17:38:27.138 INFO  TaskSetManager - Finished task 2.0 in stage 277.0 (TID 353) in 4 ms on localhost (executor driver) (4/4)
17:38:27.138 INFO  TaskSchedulerImpl - Removed TaskSet 277.0, whose tasks have all completed, from pool 
17:38:27.138 INFO  DAGScheduler - ResultStage 277 (collect at ReadsSparkSourceUnitTest.java:111) finished in 0.006 s
17:38:27.138 INFO  DAGScheduler - Job 213 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:27.138 INFO  TaskSchedulerImpl - Killing all running tasks in stage 277: Stage finished
17:38:27.138 INFO  DAGScheduler - Job 213 finished: collect at ReadsSparkSourceUnitTest.java:111, took 0.006177 s
17:38:27.138 INFO  FileInputFormat - Total input files to process : 1
17:38:27.161 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:112
17:38:27.161 INFO  DAGScheduler - Got job 214 (collect at ReadsSparkSourceUnitTest.java:112) with 1 output partitions
17:38:27.161 INFO  DAGScheduler - Final stage: ResultStage 278 (collect at ReadsSparkSourceUnitTest.java:112)
17:38:27.161 INFO  DAGScheduler - Parents of final stage: List()
17:38:27.161 INFO  DAGScheduler - Missing parents: List()
17:38:27.161 INFO  DAGScheduler - Submitting ResultStage 278 (MapPartitionsRDD[1349] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:27.172 INFO  MemoryStore - Block broadcast_569 stored as values in memory (estimated size 286.8 KiB, free 1918.1 MiB)
17:38:27.175 INFO  BlockManagerInfo - Removed broadcast_563_piece0 on localhost:37953 in memory (size: 153.7 KiB, free: 1919.9 MiB)
17:38:27.176 INFO  MemoryStore - Block broadcast_569_piece0 stored as bytes in memory (estimated size 103.6 KiB, free 1918.6 MiB)
17:38:27.176 INFO  BlockManagerInfo - Added broadcast_569_piece0 in memory on localhost:37953 (size: 103.6 KiB, free: 1919.7 MiB)
17:38:27.176 INFO  BlockManagerInfo - Removed broadcast_565_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.8 MiB)
17:38:27.176 INFO  SparkContext - Created broadcast 569 from broadcast at DAGScheduler.scala:1580
17:38:27.176 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 278 (MapPartitionsRDD[1349] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:27.176 INFO  TaskSchedulerImpl - Adding task set 278.0 with 1 tasks resource profile 0
17:38:27.176 INFO  BlockManagerInfo - Removed broadcast_564_piece0 on localhost:37953 in memory (size: 187.0 B, free: 1919.8 MiB)
17:38:27.177 INFO  TaskSetManager - Starting task 0.0 in stage 278.0 (TID 355) (localhost, executor driver, partition 0, PROCESS_LOCAL, 7839 bytes) 
17:38:27.177 INFO  BlockManagerInfo - Removed broadcast_561_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.8 MiB)
17:38:27.177 INFO  Executor - Running task 0.0 in stage 278.0 (TID 355)
17:38:27.177 INFO  BlockManagerInfo - Removed broadcast_568_piece0 on localhost:37953 in memory (size: 1778.0 B, free: 1919.8 MiB)
17:38:27.199 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/NA12878.chr17_69k_70k.dictFix.cram:0+50619
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 129, Read name 809R9ABXX101220:5:6:17918:145992, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 129, Read name 809R9ABXX101220:5:6:17918:145992, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 129, Read name 809R9ABXX101220:5:6:17918:145992, The unaligned mate start position is 69400, should be 0
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 274, Read name 809R9ABXX101220:5:8:7119:101555, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 274, Read name 809R9ABXX101220:5:8:7119:101555, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 274, Read name 809R9ABXX101220:5:8:7119:101555, The unaligned mate start position is 69471, should be 0
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 418, Read name 809R9ABXX101220:5:48:20204:50350, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 418, Read name 809R9ABXX101220:5:48:20204:50350, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 418, Read name 809R9ABXX101220:5:48:20204:50350, The unaligned mate start position is 69569, should be 0
Ignoring SAM validation error: ERROR::INVALID_ALIGNMENT_START:Record 439, Read name 809R9ABXX101220:5:44:13776:49360, Mate Alignment start should be 0 because reference name = *.
Ignoring SAM validation error: ERROR::INVALID_FLAG_MATE_UNMAPPED:Record 439, Read name 809R9ABXX101220:5:44:13776:49360, Mapped mate should have mate reference name
Ignoring SAM validation error: ERROR::INVALID_UNALIGNED_MATE_START:Record 439, Read name 809R9ABXX101220:5:44:13776:49360, The unaligned mate start position is 69592, should be 0
17:38:27.206 INFO  Executor - Finished task 0.0 in stage 278.0 (TID 355). 154058 bytes result sent to driver
17:38:27.207 INFO  TaskSetManager - Finished task 0.0 in stage 278.0 (TID 355) in 31 ms on localhost (executor driver) (1/1)
17:38:27.207 INFO  TaskSchedulerImpl - Removed TaskSet 278.0, whose tasks have all completed, from pool 
17:38:27.207 INFO  DAGScheduler - ResultStage 278 (collect at ReadsSparkSourceUnitTest.java:112) finished in 0.046 s
17:38:27.207 INFO  DAGScheduler - Job 214 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:27.207 INFO  TaskSchedulerImpl - Killing all running tasks in stage 278: Stage finished
17:38:27.207 INFO  DAGScheduler - Job 214 finished: collect at ReadsSparkSourceUnitTest.java:112, took 0.046511 s
17:38:27.209 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.210 INFO  MemoryStore - Block broadcast_570 stored as values in memory (estimated size 297.9 KiB, free 1919.0 MiB)
17:38:27.216 INFO  MemoryStore - Block broadcast_570_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1918.9 MiB)
17:38:27.216 INFO  BlockManagerInfo - Added broadcast_570_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.8 MiB)
17:38:27.216 INFO  SparkContext - Created broadcast 570 from newAPIHadoopFile at PathSplitSource.java:96
17:38:27.234 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.234 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.236 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.237 INFO  MemoryStore - Block broadcast_571 stored as values in memory (estimated size 297.9 KiB, free 1918.6 MiB)
17:38:27.243 INFO  MemoryStore - Block broadcast_571_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1918.6 MiB)
17:38:27.243 INFO  BlockManagerInfo - Added broadcast_571_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.8 MiB)
17:38:27.243 INFO  SparkContext - Created broadcast 571 from newAPIHadoopFile at PathSplitSource.java:96
17:38:27.264 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:111
17:38:27.265 INFO  DAGScheduler - Got job 215 (collect at ReadsSparkSourceUnitTest.java:111) with 4 output partitions
17:38:27.265 INFO  DAGScheduler - Final stage: ResultStage 279 (collect at ReadsSparkSourceUnitTest.java:111)
17:38:27.265 INFO  DAGScheduler - Parents of final stage: List()
17:38:27.265 INFO  DAGScheduler - Missing parents: List()
17:38:27.265 INFO  DAGScheduler - Submitting ResultStage 279 (ParallelCollectionRDD[1355] at parallelize at ReadsSparkSourceUnitTest.java:310), which has no missing parents
17:38:27.265 INFO  MemoryStore - Block broadcast_572 stored as values in memory (estimated size 3.0 KiB, free 1918.6 MiB)
17:38:27.266 INFO  MemoryStore - Block broadcast_572_piece0 stored as bytes in memory (estimated size 1778.0 B, free 1918.6 MiB)
17:38:27.266 INFO  BlockManagerInfo - Added broadcast_572_piece0 in memory on localhost:37953 (size: 1778.0 B, free: 1919.7 MiB)
17:38:27.266 INFO  SparkContext - Created broadcast 572 from broadcast at DAGScheduler.scala:1580
17:38:27.266 INFO  DAGScheduler - Submitting 4 missing tasks from ResultStage 279 (ParallelCollectionRDD[1355] at parallelize at ReadsSparkSourceUnitTest.java:310) (first 15 tasks are for partitions Vector(0, 1, 2, 3))
17:38:27.266 INFO  TaskSchedulerImpl - Adding task set 279.0 with 4 tasks resource profile 0
17:38:27.267 INFO  TaskSetManager - Starting task 0.0 in stage 279.0 (TID 356) (localhost, executor driver, partition 0, PROCESS_LOCAL, 47080 bytes) 
17:38:27.267 INFO  TaskSetManager - Starting task 1.0 in stage 279.0 (TID 357) (localhost, executor driver, partition 1, PROCESS_LOCAL, 47194 bytes) 
17:38:27.267 INFO  TaskSetManager - Starting task 2.0 in stage 279.0 (TID 358) (localhost, executor driver, partition 2, PROCESS_LOCAL, 47105 bytes) 
17:38:27.267 INFO  TaskSetManager - Starting task 3.0 in stage 279.0 (TID 359) (localhost, executor driver, partition 3, PROCESS_LOCAL, 47530 bytes) 
17:38:27.268 INFO  Executor - Running task 0.0 in stage 279.0 (TID 356)
17:38:27.268 INFO  Executor - Running task 1.0 in stage 279.0 (TID 357)
17:38:27.268 INFO  Executor - Running task 2.0 in stage 279.0 (TID 358)
17:38:27.268 INFO  Executor - Running task 3.0 in stage 279.0 (TID 359)
17:38:27.269 INFO  Executor - Finished task 1.0 in stage 279.0 (TID 357). 40426 bytes result sent to driver
17:38:27.269 INFO  Executor - Finished task 0.0 in stage 279.0 (TID 356). 40312 bytes result sent to driver
17:38:27.269 INFO  Executor - Finished task 3.0 in stage 279.0 (TID 359). 40762 bytes result sent to driver
17:38:27.270 INFO  Executor - Finished task 2.0 in stage 279.0 (TID 358). 40380 bytes result sent to driver
17:38:27.270 INFO  TaskSetManager - Finished task 3.0 in stage 279.0 (TID 359) in 3 ms on localhost (executor driver) (1/4)
17:38:27.270 INFO  TaskSetManager - Finished task 0.0 in stage 279.0 (TID 356) in 3 ms on localhost (executor driver) (2/4)
17:38:27.270 INFO  TaskSetManager - Finished task 2.0 in stage 279.0 (TID 358) in 3 ms on localhost (executor driver) (3/4)
17:38:27.270 INFO  TaskSetManager - Finished task 1.0 in stage 279.0 (TID 357) in 3 ms on localhost (executor driver) (4/4)
17:38:27.270 INFO  TaskSchedulerImpl - Removed TaskSet 279.0, whose tasks have all completed, from pool 
17:38:27.270 INFO  DAGScheduler - ResultStage 279 (collect at ReadsSparkSourceUnitTest.java:111) finished in 0.005 s
17:38:27.270 INFO  DAGScheduler - Job 215 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:27.270 INFO  TaskSchedulerImpl - Killing all running tasks in stage 279: Stage finished
17:38:27.270 INFO  DAGScheduler - Job 215 finished: collect at ReadsSparkSourceUnitTest.java:111, took 0.005989 s
17:38:27.271 INFO  FileInputFormat - Total input files to process : 1
17:38:27.303 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:112
17:38:27.303 INFO  DAGScheduler - Got job 216 (collect at ReadsSparkSourceUnitTest.java:112) with 1 output partitions
17:38:27.303 INFO  DAGScheduler - Final stage: ResultStage 280 (collect at ReadsSparkSourceUnitTest.java:112)
17:38:27.303 INFO  DAGScheduler - Parents of final stage: List()
17:38:27.303 INFO  DAGScheduler - Missing parents: List()
17:38:27.304 INFO  DAGScheduler - Submitting ResultStage 280 (MapPartitionsRDD[1362] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:27.319 INFO  MemoryStore - Block broadcast_573 stored as values in memory (estimated size 426.2 KiB, free 1918.2 MiB)
17:38:27.320 INFO  MemoryStore - Block broadcast_573_piece0 stored as bytes in memory (estimated size 153.7 KiB, free 1918.0 MiB)
17:38:27.320 INFO  BlockManagerInfo - Added broadcast_573_piece0 in memory on localhost:37953 (size: 153.7 KiB, free: 1919.6 MiB)
17:38:27.320 INFO  SparkContext - Created broadcast 573 from broadcast at DAGScheduler.scala:1580
17:38:27.320 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 280 (MapPartitionsRDD[1362] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:27.320 INFO  TaskSchedulerImpl - Adding task set 280.0 with 1 tasks resource profile 0
17:38:27.321 INFO  TaskSetManager - Starting task 0.0 in stage 280.0 (TID 360) (localhost, executor driver, partition 0, PROCESS_LOCAL, 7838 bytes) 
17:38:27.321 INFO  Executor - Running task 0.0 in stage 280.0 (TID 360)
17:38:27.353 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/NA12878.chr17_69k_70k.dictFix.bam:0+57538
17:38:27.354 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.354 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.355 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.359 INFO  BlockManagerInfo - Removed broadcast_566_piece0 on localhost:37953 in memory (size: 187.0 B, free: 1919.6 MiB)
17:38:27.359 INFO  Executor - Finished task 0.0 in stage 280.0 (TID 360). 159658 bytes result sent to driver
17:38:27.360 INFO  TaskSetManager - Finished task 0.0 in stage 280.0 (TID 360) in 39 ms on localhost (executor driver) (1/1)
17:38:27.360 INFO  BlockManagerInfo - Removed broadcast_569_piece0 on localhost:37953 in memory (size: 103.6 KiB, free: 1919.7 MiB)
17:38:27.360 INFO  TaskSchedulerImpl - Removed TaskSet 280.0, whose tasks have all completed, from pool 
17:38:27.360 INFO  DAGScheduler - ResultStage 280 (collect at ReadsSparkSourceUnitTest.java:112) finished in 0.056 s
17:38:27.360 INFO  DAGScheduler - Job 216 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:27.360 INFO  TaskSchedulerImpl - Killing all running tasks in stage 280: Stage finished
17:38:27.360 INFO  DAGScheduler - Job 216 finished: collect at ReadsSparkSourceUnitTest.java:112, took 0.057222 s
17:38:27.361 INFO  BlockManagerInfo - Removed broadcast_570_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.8 MiB)
17:38:27.361 INFO  BlockManagerInfo - Removed broadcast_567_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.8 MiB)
17:38:27.361 INFO  BlockManagerInfo - Removed broadcast_572_piece0 on localhost:37953 in memory (size: 1778.0 B, free: 1919.8 MiB)
17:38:27.363 INFO  MemoryStore - Block broadcast_574 stored as values in memory (estimated size 536.0 B, free 1919.1 MiB)
17:38:27.363 INFO  MemoryStore - Block broadcast_574_piece0 stored as bytes in memory (estimated size 187.0 B, free 1919.1 MiB)
17:38:27.363 INFO  BlockManagerInfo - Added broadcast_574_piece0 in memory on localhost:37953 (size: 187.0 B, free: 1919.8 MiB)
17:38:27.364 INFO  SparkContext - Created broadcast 574 from broadcast at CramSource.java:114
17:38:27.364 INFO  MemoryStore - Block broadcast_575 stored as values in memory (estimated size 297.9 KiB, free 1918.8 MiB)
17:38:27.370 INFO  MemoryStore - Block broadcast_575_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1918.8 MiB)
17:38:27.370 INFO  BlockManagerInfo - Added broadcast_575_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.8 MiB)
17:38:27.370 INFO  SparkContext - Created broadcast 575 from newAPIHadoopFile at PathSplitSource.java:96
17:38:27.389 INFO  MemoryStore - Block broadcast_576 stored as values in memory (estimated size 536.0 B, free 1918.8 MiB)
17:38:27.390 INFO  MemoryStore - Block broadcast_576_piece0 stored as bytes in memory (estimated size 187.0 B, free 1918.8 MiB)
17:38:27.390 INFO  BlockManagerInfo - Added broadcast_576_piece0 in memory on localhost:37953 (size: 187.0 B, free: 1919.8 MiB)
17:38:27.390 INFO  SparkContext - Created broadcast 576 from broadcast at CramSource.java:114
17:38:27.391 INFO  MemoryStore - Block broadcast_577 stored as values in memory (estimated size 297.9 KiB, free 1918.5 MiB)
17:38:27.396 INFO  MemoryStore - Block broadcast_577_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1918.4 MiB)
17:38:27.396 INFO  BlockManagerInfo - Added broadcast_577_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.7 MiB)
17:38:27.397 INFO  SparkContext - Created broadcast 577 from newAPIHadoopFile at PathSplitSource.java:96
17:38:27.412 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:111
17:38:27.413 INFO  DAGScheduler - Got job 217 (collect at ReadsSparkSourceUnitTest.java:111) with 4 output partitions
17:38:27.413 INFO  DAGScheduler - Final stage: ResultStage 281 (collect at ReadsSparkSourceUnitTest.java:111)
17:38:27.413 INFO  DAGScheduler - Parents of final stage: List()
17:38:27.413 INFO  DAGScheduler - Missing parents: List()
17:38:27.413 INFO  DAGScheduler - Submitting ResultStage 281 (ParallelCollectionRDD[1367] at parallelize at ReadsSparkSourceUnitTest.java:310), which has no missing parents
17:38:27.413 INFO  MemoryStore - Block broadcast_578 stored as values in memory (estimated size 3.0 KiB, free 1918.4 MiB)
17:38:27.414 INFO  MemoryStore - Block broadcast_578_piece0 stored as bytes in memory (estimated size 1778.0 B, free 1918.4 MiB)
17:38:27.414 INFO  BlockManagerInfo - Added broadcast_578_piece0 in memory on localhost:37953 (size: 1778.0 B, free: 1919.7 MiB)
17:38:27.414 INFO  SparkContext - Created broadcast 578 from broadcast at DAGScheduler.scala:1580
17:38:27.414 INFO  DAGScheduler - Submitting 4 missing tasks from ResultStage 281 (ParallelCollectionRDD[1367] at parallelize at ReadsSparkSourceUnitTest.java:310) (first 15 tasks are for partitions Vector(0, 1, 2, 3))
17:38:27.414 INFO  TaskSchedulerImpl - Adding task set 281.0 with 4 tasks resource profile 0
17:38:27.415 INFO  TaskSetManager - Starting task 0.0 in stage 281.0 (TID 361) (localhost, executor driver, partition 0, PROCESS_LOCAL, 45675 bytes) 
17:38:27.415 INFO  TaskSetManager - Starting task 1.0 in stage 281.0 (TID 362) (localhost, executor driver, partition 1, PROCESS_LOCAL, 45855 bytes) 
17:38:27.416 INFO  TaskSetManager - Starting task 2.0 in stage 281.0 (TID 363) (localhost, executor driver, partition 2, PROCESS_LOCAL, 45795 bytes) 
17:38:27.416 INFO  TaskSetManager - Starting task 3.0 in stage 281.0 (TID 364) (localhost, executor driver, partition 3, PROCESS_LOCAL, 46068 bytes) 
17:38:27.416 INFO  Executor - Running task 1.0 in stage 281.0 (TID 362)
17:38:27.416 INFO  Executor - Running task 3.0 in stage 281.0 (TID 364)
17:38:27.416 INFO  Executor - Running task 2.0 in stage 281.0 (TID 363)
17:38:27.416 INFO  Executor - Running task 0.0 in stage 281.0 (TID 361)
17:38:27.417 INFO  Executor - Finished task 0.0 in stage 281.0 (TID 361). 38907 bytes result sent to driver
17:38:27.417 INFO  Executor - Finished task 1.0 in stage 281.0 (TID 362). 39087 bytes result sent to driver
17:38:27.417 INFO  Executor - Finished task 3.0 in stage 281.0 (TID 364). 39300 bytes result sent to driver
17:38:27.418 INFO  Executor - Finished task 2.0 in stage 281.0 (TID 363). 39027 bytes result sent to driver
17:38:27.418 INFO  TaskSetManager - Finished task 0.0 in stage 281.0 (TID 361) in 3 ms on localhost (executor driver) (1/4)
17:38:27.418 INFO  TaskSetManager - Finished task 3.0 in stage 281.0 (TID 364) in 2 ms on localhost (executor driver) (2/4)
17:38:27.418 INFO  TaskSetManager - Finished task 2.0 in stage 281.0 (TID 363) in 3 ms on localhost (executor driver) (3/4)
17:38:27.418 INFO  TaskSetManager - Finished task 1.0 in stage 281.0 (TID 362) in 3 ms on localhost (executor driver) (4/4)
17:38:27.418 INFO  TaskSchedulerImpl - Removed TaskSet 281.0, whose tasks have all completed, from pool 
17:38:27.418 INFO  DAGScheduler - ResultStage 281 (collect at ReadsSparkSourceUnitTest.java:111) finished in 0.005 s
17:38:27.418 INFO  DAGScheduler - Job 217 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:27.419 INFO  TaskSchedulerImpl - Killing all running tasks in stage 281: Stage finished
17:38:27.419 INFO  DAGScheduler - Job 217 finished: collect at ReadsSparkSourceUnitTest.java:111, took 0.006077 s
17:38:27.419 INFO  FileInputFormat - Total input files to process : 1
17:38:27.441 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:112
17:38:27.442 INFO  DAGScheduler - Got job 218 (collect at ReadsSparkSourceUnitTest.java:112) with 1 output partitions
17:38:27.442 INFO  DAGScheduler - Final stage: ResultStage 282 (collect at ReadsSparkSourceUnitTest.java:112)
17:38:27.442 INFO  DAGScheduler - Parents of final stage: List()
17:38:27.442 INFO  DAGScheduler - Missing parents: List()
17:38:27.442 INFO  DAGScheduler - Submitting ResultStage 282 (MapPartitionsRDD[1373] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:27.452 INFO  MemoryStore - Block broadcast_579 stored as values in memory (estimated size 286.8 KiB, free 1918.1 MiB)
17:38:27.456 INFO  BlockManagerInfo - Removed broadcast_578_piece0 on localhost:37953 in memory (size: 1778.0 B, free: 1919.7 MiB)
17:38:27.456 INFO  MemoryStore - Block broadcast_579_piece0 stored as bytes in memory (estimated size 103.6 KiB, free 1918.0 MiB)
17:38:27.456 INFO  BlockManagerInfo - Added broadcast_579_piece0 in memory on localhost:37953 (size: 103.6 KiB, free: 1919.6 MiB)
17:38:27.456 INFO  BlockManagerInfo - Removed broadcast_573_piece0 on localhost:37953 in memory (size: 153.7 KiB, free: 1919.8 MiB)
17:38:27.457 INFO  SparkContext - Created broadcast 579 from broadcast at DAGScheduler.scala:1580
17:38:27.457 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 282 (MapPartitionsRDD[1373] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:27.457 INFO  TaskSchedulerImpl - Adding task set 282.0 with 1 tasks resource profile 0
17:38:27.457 INFO  BlockManagerInfo - Removed broadcast_574_piece0 on localhost:37953 in memory (size: 187.0 B, free: 1919.8 MiB)
17:38:27.457 INFO  TaskSetManager - Starting task 0.0 in stage 282.0 (TID 365) (localhost, executor driver, partition 0, PROCESS_LOCAL, 7839 bytes) 
17:38:27.457 INFO  BlockManagerInfo - Removed broadcast_571_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.8 MiB)
17:38:27.458 INFO  Executor - Running task 0.0 in stage 282.0 (TID 365)
17:38:27.459 INFO  BlockManagerInfo - Removed broadcast_575_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.8 MiB)
17:38:27.480 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/NA12878.chr17_69k_70k.dictFix.cram:0+50619
17:38:27.487 INFO  Executor - Finished task 0.0 in stage 282.0 (TID 365). 154058 bytes result sent to driver
17:38:27.488 INFO  TaskSetManager - Finished task 0.0 in stage 282.0 (TID 365) in 31 ms on localhost (executor driver) (1/1)
17:38:27.488 INFO  TaskSchedulerImpl - Removed TaskSet 282.0, whose tasks have all completed, from pool 
17:38:27.488 INFO  DAGScheduler - ResultStage 282 (collect at ReadsSparkSourceUnitTest.java:112) finished in 0.046 s
17:38:27.488 INFO  DAGScheduler - Job 218 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:27.488 INFO  TaskSchedulerImpl - Killing all running tasks in stage 282: Stage finished
17:38:27.488 INFO  DAGScheduler - Job 218 finished: collect at ReadsSparkSourceUnitTest.java:112, took 0.046736 s
17:38:27.490 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.491 INFO  MemoryStore - Block broadcast_580 stored as values in memory (estimated size 297.9 KiB, free 1919.0 MiB)
17:38:27.497 INFO  MemoryStore - Block broadcast_580_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1918.9 MiB)
17:38:27.497 INFO  BlockManagerInfo - Added broadcast_580_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.8 MiB)
17:38:27.497 INFO  SparkContext - Created broadcast 580 from newAPIHadoopFile at PathSplitSource.java:96
17:38:27.515 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.515 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.518 INFO  MemoryStore - Block broadcast_581 stored as values in memory (estimated size 536.0 B, free 1918.9 MiB)
17:38:27.518 INFO  MemoryStore - Block broadcast_581_piece0 stored as bytes in memory (estimated size 187.0 B, free 1918.9 MiB)
17:38:27.518 INFO  BlockManagerInfo - Added broadcast_581_piece0 in memory on localhost:37953 (size: 187.0 B, free: 1919.8 MiB)
17:38:27.519 INFO  SparkContext - Created broadcast 581 from broadcast at CramSource.java:114
17:38:27.520 INFO  MemoryStore - Block broadcast_582 stored as values in memory (estimated size 297.9 KiB, free 1918.6 MiB)
17:38:27.525 INFO  MemoryStore - Block broadcast_582_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1918.6 MiB)
17:38:27.525 INFO  BlockManagerInfo - Added broadcast_582_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.8 MiB)
17:38:27.526 INFO  SparkContext - Created broadcast 582 from newAPIHadoopFile at PathSplitSource.java:96
17:38:27.550 WARN  FileSystem - Failed to initialize filesystem hdfs://bogus/path.bam: java.lang.IllegalArgumentException: java.net.UnknownHostException: bogus
17:38:27.552 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.553 INFO  MemoryStore - Block broadcast_583 stored as values in memory (estimated size 298.0 KiB, free 1918.3 MiB)
17:38:27.559 INFO  MemoryStore - Block broadcast_583_piece0 stored as bytes in memory (estimated size 50.3 KiB, free 1918.3 MiB)
17:38:27.559 INFO  BlockManagerInfo - Added broadcast_583_piece0 in memory on localhost:37953 (size: 50.3 KiB, free: 1919.7 MiB)
17:38:27.559 INFO  SparkContext - Created broadcast 583 from newAPIHadoopFile at PathSplitSource.java:96
17:38:27.577 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.577 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.581 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.583 INFO  MemoryStore - Block broadcast_584 stored as values in memory (estimated size 298.0 KiB, free 1918.0 MiB)
17:38:27.588 INFO  MemoryStore - Block broadcast_584_piece0 stored as bytes in memory (estimated size 50.3 KiB, free 1917.9 MiB)
17:38:27.588 INFO  BlockManagerInfo - Added broadcast_584_piece0 in memory on localhost:37953 (size: 50.3 KiB, free: 1919.7 MiB)
17:38:27.589 INFO  SparkContext - Created broadcast 584 from newAPIHadoopFile at PathSplitSource.java:96
17:38:27.610 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:154
17:38:27.610 INFO  DAGScheduler - Got job 219 (collect at ReadsSparkSourceUnitTest.java:154) with 4 output partitions
17:38:27.610 INFO  DAGScheduler - Final stage: ResultStage 283 (collect at ReadsSparkSourceUnitTest.java:154)
17:38:27.610 INFO  DAGScheduler - Parents of final stage: List()
17:38:27.610 INFO  DAGScheduler - Missing parents: List()
17:38:27.610 INFO  DAGScheduler - Submitting ResultStage 283 (ParallelCollectionRDD[1388] at parallelize at ReadsSparkSourceUnitTest.java:310), which has no missing parents
17:38:27.611 INFO  MemoryStore - Block broadcast_585 stored as values in memory (estimated size 3.0 KiB, free 1917.9 MiB)
17:38:27.614 INFO  MemoryStore - Block broadcast_585_piece0 stored as bytes in memory (estimated size 1778.0 B, free 1917.9 MiB)
17:38:27.614 INFO  BlockManagerInfo - Added broadcast_585_piece0 in memory on localhost:37953 (size: 1778.0 B, free: 1919.7 MiB)
17:38:27.614 INFO  BlockManagerInfo - Removed broadcast_583_piece0 on localhost:37953 in memory (size: 50.3 KiB, free: 1919.7 MiB)
17:38:27.614 INFO  SparkContext - Created broadcast 585 from broadcast at DAGScheduler.scala:1580
17:38:27.614 INFO  DAGScheduler - Submitting 4 missing tasks from ResultStage 283 (ParallelCollectionRDD[1388] at parallelize at ReadsSparkSourceUnitTest.java:310) (first 15 tasks are for partitions Vector(0, 1, 2, 3))
17:38:27.614 INFO  TaskSchedulerImpl - Adding task set 283.0 with 4 tasks resource profile 0
17:38:27.614 INFO  BlockManagerInfo - Removed broadcast_580_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.7 MiB)
17:38:27.615 INFO  BlockManagerInfo - Removed broadcast_581_piece0 on localhost:37953 in memory (size: 187.0 B, free: 1919.7 MiB)
17:38:27.615 INFO  TaskSetManager - Starting task 0.0 in stage 283.0 (TID 366) (localhost, executor driver, partition 0, PROCESS_LOCAL, 169886 bytes) 
17:38:27.615 INFO  BlockManagerInfo - Removed broadcast_579_piece0 on localhost:37953 in memory (size: 103.6 KiB, free: 1919.9 MiB)
17:38:27.615 INFO  TaskSetManager - Starting task 1.0 in stage 283.0 (TID 367) (localhost, executor driver, partition 1, PROCESS_LOCAL, 170093 bytes) 
17:38:27.616 INFO  TaskSetManager - Starting task 2.0 in stage 283.0 (TID 368) (localhost, executor driver, partition 2, PROCESS_LOCAL, 170081 bytes) 
17:38:27.616 INFO  BlockManagerInfo - Removed broadcast_577_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.9 MiB)
17:38:27.616 INFO  TaskSetManager - Starting task 3.0 in stage 283.0 (TID 369) (localhost, executor driver, partition 3, PROCESS_LOCAL, 169419 bytes) 
17:38:27.616 INFO  Executor - Running task 1.0 in stage 283.0 (TID 367)
17:38:27.616 INFO  Executor - Running task 0.0 in stage 283.0 (TID 366)
17:38:27.616 INFO  Executor - Running task 3.0 in stage 283.0 (TID 369)
17:38:27.616 INFO  BlockManagerInfo - Removed broadcast_576_piece0 on localhost:37953 in memory (size: 187.0 B, free: 1919.9 MiB)
17:38:27.617 INFO  Executor - Running task 2.0 in stage 283.0 (TID 368)
17:38:27.617 INFO  BlockManagerInfo - Removed broadcast_582_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.9 MiB)
17:38:27.618 INFO  Executor - Finished task 0.0 in stage 283.0 (TID 366). 163161 bytes result sent to driver
17:38:27.618 INFO  Executor - Finished task 2.0 in stage 283.0 (TID 368). 163313 bytes result sent to driver
17:38:27.619 INFO  Executor - Finished task 3.0 in stage 283.0 (TID 369). 162694 bytes result sent to driver
17:38:27.619 INFO  Executor - Finished task 1.0 in stage 283.0 (TID 367). 163368 bytes result sent to driver
17:38:27.620 INFO  TaskSetManager - Finished task 0.0 in stage 283.0 (TID 366) in 4 ms on localhost (executor driver) (1/4)
17:38:27.620 INFO  TaskSetManager - Finished task 2.0 in stage 283.0 (TID 368) in 5 ms on localhost (executor driver) (2/4)
17:38:27.620 INFO  TaskSetManager - Finished task 3.0 in stage 283.0 (TID 369) in 4 ms on localhost (executor driver) (3/4)
17:38:27.620 INFO  TaskSetManager - Finished task 1.0 in stage 283.0 (TID 367) in 5 ms on localhost (executor driver) (4/4)
17:38:27.620 INFO  TaskSchedulerImpl - Removed TaskSet 283.0, whose tasks have all completed, from pool 
17:38:27.620 INFO  DAGScheduler - ResultStage 283 (collect at ReadsSparkSourceUnitTest.java:154) finished in 0.010 s
17:38:27.620 INFO  DAGScheduler - Job 219 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:27.620 INFO  TaskSchedulerImpl - Killing all running tasks in stage 283: Stage finished
17:38:27.620 INFO  DAGScheduler - Job 219 finished: collect at ReadsSparkSourceUnitTest.java:154, took 0.010386 s
17:38:27.627 INFO  FileInputFormat - Total input files to process : 2
17:38:27.659 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:155
17:38:27.659 INFO  DAGScheduler - Got job 220 (collect at ReadsSparkSourceUnitTest.java:155) with 2 output partitions
17:38:27.659 INFO  DAGScheduler - Final stage: ResultStage 284 (collect at ReadsSparkSourceUnitTest.java:155)
17:38:27.659 INFO  DAGScheduler - Parents of final stage: List()
17:38:27.659 INFO  DAGScheduler - Missing parents: List()
17:38:27.659 INFO  DAGScheduler - Submitting ResultStage 284 (MapPartitionsRDD[1395] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:27.674 INFO  MemoryStore - Block broadcast_586 stored as values in memory (estimated size 426.2 KiB, free 1919.2 MiB)
17:38:27.676 INFO  MemoryStore - Block broadcast_586_piece0 stored as bytes in memory (estimated size 153.7 KiB, free 1919.1 MiB)
17:38:27.676 INFO  BlockManagerInfo - Added broadcast_586_piece0 in memory on localhost:37953 (size: 153.7 KiB, free: 1919.8 MiB)
17:38:27.676 INFO  SparkContext - Created broadcast 586 from broadcast at DAGScheduler.scala:1580
17:38:27.676 INFO  DAGScheduler - Submitting 2 missing tasks from ResultStage 284 (MapPartitionsRDD[1395] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0, 1))
17:38:27.676 INFO  TaskSchedulerImpl - Adding task set 284.0 with 2 tasks resource profile 0
17:38:27.677 INFO  TaskSetManager - Starting task 0.0 in stage 284.0 (TID 370) (localhost, executor driver, partition 0, PROCESS_LOCAL, 7928 bytes) 
17:38:27.677 INFO  TaskSetManager - Starting task 1.0 in stage 284.0 (TID 371) (localhost, executor driver, partition 1, PROCESS_LOCAL, 7928 bytes) 
17:38:27.677 INFO  Executor - Running task 1.0 in stage 284.0 (TID 371)
17:38:27.677 INFO  Executor - Running task 0.0 in stage 284.0 (TID 370)
17:38:27.712 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/tools/BQSR/HiSeq.1mb.1RG.2k_lines.alternate.recalibrated.DIQ.sharded.bam/part-r-00001.bam:0+131967
17:38:27.712 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/tools/BQSR/HiSeq.1mb.1RG.2k_lines.alternate.recalibrated.DIQ.sharded.bam/part-r-00000.bam:0+131967
17:38:27.713 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.714 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.714 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.714 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.721 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.722 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:27.724 INFO  Executor - Finished task 0.0 in stage 284.0 (TID 370). 325590 bytes result sent to driver
17:38:27.724 INFO  Executor - Finished task 1.0 in stage 284.0 (TID 371). 325590 bytes result sent to driver
17:38:27.725 INFO  TaskSetManager - Finished task 0.0 in stage 284.0 (TID 370) in 49 ms on localhost (executor driver) (1/2)
17:38:27.725 INFO  TaskSetManager - Finished task 1.0 in stage 284.0 (TID 371) in 48 ms on localhost (executor driver) (2/2)
17:38:27.725 INFO  TaskSchedulerImpl - Removed TaskSet 284.0, whose tasks have all completed, from pool 
17:38:27.725 INFO  DAGScheduler - ResultStage 284 (collect at ReadsSparkSourceUnitTest.java:155) finished in 0.065 s
17:38:27.725 INFO  DAGScheduler - Job 220 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:27.725 INFO  TaskSchedulerImpl - Killing all running tasks in stage 284: Stage finished
17:38:27.725 INFO  DAGScheduler - Job 220 finished: collect at ReadsSparkSourceUnitTest.java:155, took 0.066522 s
17:38:27.735 INFO  MiniDFSCluster - starting cluster: numNameNodes=1, numDataNodes=1
17:38:27.736 INFO  NameNode - Formatting using clusterid: testClusterID
17:38:27.736 INFO  FSEditLog - Edit logging is async:true
17:38:27.743 INFO  FSNamesystem - KeyProvider: null
17:38:27.743 INFO  FSNamesystem - fsLock is fair: true
17:38:27.743 INFO  FSNamesystem - Detailed lock hold time metrics enabled: false
17:38:27.743 INFO  FSNamesystem - fsOwner                = runner (auth:SIMPLE)
17:38:27.743 INFO  FSNamesystem - supergroup             = supergroup
17:38:27.743 INFO  FSNamesystem - isPermissionEnabled    = true
17:38:27.743 INFO  FSNamesystem - isStoragePolicyEnabled = true
17:38:27.743 INFO  FSNamesystem - HA Enabled: false
17:38:27.743 INFO  Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
17:38:27.743 INFO  DatanodeManager - dfs.block.invalidate.limit : configured=1000, counted=60, effected=1000
17:38:27.743 INFO  DatanodeManager - dfs.namenode.datanode.registration.ip-hostname-check=true
17:38:27.743 INFO  BlockManager - dfs.namenode.startup.delay.block.deletion.sec is set to 000:00:00:00.000
17:38:27.744 INFO  BlockManager - The block deletion will start around 2025 Oct 27 17:38:27
17:38:27.744 INFO  GSet - Computing capacity for map BlocksMap
17:38:27.744 INFO  GSet - VM type       = 64-bit
17:38:27.744 INFO  GSet - 2.0% max memory 3.4 GB = 70 MB
17:38:27.744 INFO  GSet - capacity      = 2^23 = 8388608 entries
17:38:27.749 INFO  BlockManager - Storage policy satisfier is disabled
17:38:27.749 INFO  BlockManager - dfs.block.access.token.enable = false
17:38:27.749 INFO  BlockManagerInfo - Removed broadcast_586_piece0 on localhost:37953 in memory (size: 153.7 KiB, free: 1919.9 MiB)
17:38:27.749 INFO  BlockManagerSafeMode - dfs.namenode.safemode.threshold-pct = 0.999
17:38:27.749 INFO  BlockManagerSafeMode - dfs.namenode.safemode.min.datanodes = 0
17:38:27.749 INFO  BlockManagerSafeMode - dfs.namenode.safemode.extension = 0
17:38:27.749 INFO  BlockManager - defaultReplication         = 1
17:38:27.749 INFO  BlockManager - maxReplication             = 512
17:38:27.749 INFO  BlockManager - minReplication             = 1
17:38:27.749 INFO  BlockManager - maxReplicationStreams      = 2
17:38:27.749 INFO  BlockManager - redundancyRecheckInterval  = 3000ms
17:38:27.749 INFO  BlockManager - encryptDataTransfer        = false
17:38:27.749 INFO  BlockManager - maxNumBlocksToLog          = 1000
17:38:27.749 INFO  GSet - Computing capacity for map INodeMap
17:38:27.749 INFO  GSet - VM type       = 64-bit
17:38:27.749 INFO  GSet - 1.0% max memory 3.4 GB = 35 MB
17:38:27.749 INFO  GSet - capacity      = 2^22 = 4194304 entries
17:38:27.753 INFO  BlockManagerInfo - Removed broadcast_584_piece0 on localhost:37953 in memory (size: 50.3 KiB, free: 1920.0 MiB)
17:38:27.753 INFO  FSDirectory - ACLs enabled? true
17:38:27.753 INFO  FSDirectory - POSIX ACL inheritance enabled? true
17:38:27.753 INFO  FSDirectory - XAttrs enabled? true
17:38:27.753 INFO  NameNode - Caching file names occurring more than 10 times
17:38:27.753 INFO  SnapshotManager - Loaded config captureOpenFiles: false, skipCaptureAccessTimeOnlyChange: false, snapshotDiffAllowSnapRootDescendant: true, maxSnapshotLimit: 65536
17:38:27.753 INFO  SnapshotManager - SkipList is disabled
17:38:27.753 INFO  GSet - Computing capacity for map cachedBlocks
17:38:27.753 INFO  GSet - VM type       = 64-bit
17:38:27.753 INFO  GSet - 0.25% max memory 3.4 GB = 8.8 MB
17:38:27.753 INFO  GSet - capacity      = 2^20 = 1048576 entries
17:38:27.753 INFO  TopMetrics - NNTop conf: dfs.namenode.top.window.num.buckets = 10
17:38:27.753 INFO  TopMetrics - NNTop conf: dfs.namenode.top.num.users = 10
17:38:27.753 INFO  TopMetrics - NNTop conf: dfs.namenode.top.windows.minutes = 1,5,25
17:38:27.754 INFO  FSNamesystem - Retry cache on namenode is enabled
17:38:27.754 INFO  FSNamesystem - Retry cache will use 0.03 of total heap and retry cache entry expiry time is 600000 millis
17:38:27.754 INFO  GSet - Computing capacity for map NameNodeRetryCache
17:38:27.754 INFO  GSet - VM type       = 64-bit
17:38:27.754 INFO  GSet - 0.029999999329447746% max memory 3.4 GB = 1.0 MB
17:38:27.754 INFO  GSet - capacity      = 2^17 = 131072 entries
17:38:27.754 INFO  FSImage - Allocated new BlockPoolId: BP-1987156128-10.1.0.252-1761586707754
17:38:27.755 INFO  BlockManagerInfo - Removed broadcast_585_piece0 on localhost:37953 in memory (size: 1778.0 B, free: 1920.0 MiB)
17:38:27.763 INFO  Storage - Storage directory /tmp/minicluster_storage17032969745032485617/name-0-1 has been successfully formatted.
17:38:27.770 INFO  Storage - Storage directory /tmp/minicluster_storage17032969745032485617/name-0-2 has been successfully formatted.
17:38:27.780 INFO  FSImageFormatProtobuf - Saving image file /tmp/minicluster_storage17032969745032485617/name-0-2/current/fsimage.ckpt_0000000000000000000 using no compression
17:38:27.780 INFO  FSImageFormatProtobuf - Saving image file /tmp/minicluster_storage17032969745032485617/name-0-1/current/fsimage.ckpt_0000000000000000000 using no compression
17:38:27.783 INFO  FSImageFormatProtobuf - Image file /tmp/minicluster_storage17032969745032485617/name-0-2/current/fsimage.ckpt_0000000000000000000 of size 419 bytes saved in 0 seconds .
17:38:27.783 INFO  FSImageFormatProtobuf - Image file /tmp/minicluster_storage17032969745032485617/name-0-1/current/fsimage.ckpt_0000000000000000000 of size 419 bytes saved in 0 seconds .
17:38:27.787 INFO  NNStorageRetentionManager - Going to retain 1 images with txid >= 0
17:38:27.790 INFO  FSNamesystem - Stopping services started for active state
17:38:27.790 INFO  FSNamesystem - Stopping services started for standby state
17:38:27.790 INFO  NameNode - createNameNode []
17:38:27.791 WARN  MetricsConfig - Cannot locate configuration: tried hadoop-metrics2-namenode.properties,hadoop-metrics2.properties
17:38:27.792 INFO  MetricsSystemImpl - Scheduled Metric snapshot period at 10 second(s).
17:38:27.792 INFO  MetricsSystemImpl - NameNode metrics system started
17:38:27.793 INFO  NameNodeUtils - fs.defaultFS is hdfs://127.0.0.1:0
17:38:27.803 INFO  JvmPauseMonitor - Starting JVM pause monitor
17:38:27.803 INFO  DFSUtil - Filter initializers set : org.apache.hadoop.http.lib.StaticUserWebFilter,org.apache.hadoop.hdfs.web.AuthFilterInitializer
17:38:27.803 INFO  DFSUtil - Starting Web-server for hdfs at: http://localhost:0
17:38:27.804 WARN  AuthenticationFilter - Unable to initialize FileSignerSecretProvider, falling back to use random secrets. Reason: Could not read signature secret file: /home/runner/hadoop-http-auth-signature-secret
17:38:27.805 WARN  HttpRequestLog - Jetty request log can only be enabled using Log4j
17:38:27.806 INFO  HttpServer2 - Added global filter 'safety' (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter)
17:38:27.806 INFO  HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context hdfs
17:38:27.806 INFO  HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context static
17:38:27.807 INFO  HttpServer2 - Added filter AuthFilter (class=org.apache.hadoop.hdfs.web.AuthFilter) to context hdfs
17:38:27.807 INFO  HttpServer2 - Added filter AuthFilter (class=org.apache.hadoop.hdfs.web.AuthFilter) to context static
17:38:27.807 INFO  HttpServer2 - addJerseyResourcePackage: packageName=org.apache.hadoop.hdfs.server.namenode.web.resources;org.apache.hadoop.hdfs.web.resources, pathSpec=/webhdfs/v1/*
17:38:27.808 INFO  HttpServer2 - Jetty bound to port 35797
17:38:27.808 INFO  Server - jetty-9.4.56.v20240826; built: 2024-08-26T17:15:05.868Z; git: ec6782ff5ead824dabdcf47fa98f90a4aedff401; jvm 17.0.6+10
17:38:27.809 INFO  session - DefaultSessionIdManager workerName=node0
17:38:27.809 INFO  session - No SessionScavenger set, using defaults
17:38:27.809 INFO  session - node0 Scavenging every 600000ms
17:38:27.810 WARN  AuthenticationFilter - Unable to initialize FileSignerSecretProvider, falling back to use random secrets. Reason: Could not read signature secret file: /home/runner/hadoop-http-auth-signature-secret
17:38:27.810 INFO  ContextHandler - Started o.e.j.s.ServletContextHandler@592470f8{static,/static,jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/static,AVAILABLE}
17:38:27.881 INFO  ContextHandler - Started o.e.j.w.WebAppContext@5a5d74b2{hdfs,/,file:///tmp/jetty-localhost-35797-hadoop-hdfs-3_3_6-tests_jar-_-any-5457084659302820021/webapp/,AVAILABLE}{jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/hdfs}
17:38:27.882 INFO  AbstractConnector - Started ServerConnector@2bdd285b{HTTP/1.1, (http/1.1)}{localhost:35797}
17:38:27.882 INFO  Server - Started @69993ms
17:38:27.882 INFO  FSEditLog - Edit logging is async:true
17:38:27.891 INFO  FSNamesystem - KeyProvider: null
17:38:27.891 INFO  FSNamesystem - fsLock is fair: true
17:38:27.891 INFO  FSNamesystem - Detailed lock hold time metrics enabled: false
17:38:27.891 INFO  FSNamesystem - fsOwner                = runner (auth:SIMPLE)
17:38:27.891 INFO  FSNamesystem - supergroup             = supergroup
17:38:27.891 INFO  FSNamesystem - isPermissionEnabled    = true
17:38:27.891 INFO  FSNamesystem - isStoragePolicyEnabled = true
17:38:27.891 INFO  FSNamesystem - HA Enabled: false
17:38:27.891 INFO  Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
17:38:27.891 INFO  DatanodeManager - dfs.block.invalidate.limit : configured=1000, counted=60, effected=1000
17:38:27.891 INFO  DatanodeManager - dfs.namenode.datanode.registration.ip-hostname-check=true
17:38:27.892 INFO  BlockManager - dfs.namenode.startup.delay.block.deletion.sec is set to 000:00:00:00.000
17:38:27.892 INFO  BlockManager - The block deletion will start around 2025 Oct 27 17:38:27
17:38:27.892 INFO  GSet - Computing capacity for map BlocksMap
17:38:27.892 INFO  GSet - VM type       = 64-bit
17:38:27.892 INFO  GSet - 2.0% max memory 3.4 GB = 70 MB
17:38:27.892 INFO  GSet - capacity      = 2^23 = 8388608 entries
17:38:27.896 INFO  BlockManager - Storage policy satisfier is disabled
17:38:27.896 INFO  BlockManager - dfs.block.access.token.enable = false
17:38:27.896 INFO  BlockManagerSafeMode - dfs.namenode.safemode.threshold-pct = 0.999
17:38:27.896 INFO  BlockManagerSafeMode - dfs.namenode.safemode.min.datanodes = 0
17:38:27.896 INFO  BlockManagerSafeMode - dfs.namenode.safemode.extension = 0
17:38:27.896 INFO  BlockManager - defaultReplication         = 1
17:38:27.896 INFO  BlockManager - maxReplication             = 512
17:38:27.896 INFO  BlockManager - minReplication             = 1
17:38:27.896 INFO  BlockManager - maxReplicationStreams      = 2
17:38:27.896 INFO  BlockManager - redundancyRecheckInterval  = 3000ms
17:38:27.896 INFO  BlockManager - encryptDataTransfer        = false
17:38:27.896 INFO  BlockManager - maxNumBlocksToLog          = 1000
17:38:27.896 INFO  GSet - Computing capacity for map INodeMap
17:38:27.896 INFO  GSet - VM type       = 64-bit
17:38:27.896 INFO  GSet - 1.0% max memory 3.4 GB = 35 MB
17:38:27.896 INFO  GSet - capacity      = 2^22 = 4194304 entries
17:38:27.900 INFO  FSDirectory - ACLs enabled? true
17:38:27.900 INFO  FSDirectory - POSIX ACL inheritance enabled? true
17:38:27.900 INFO  FSDirectory - XAttrs enabled? true
17:38:27.900 INFO  NameNode - Caching file names occurring more than 10 times
17:38:27.900 INFO  SnapshotManager - Loaded config captureOpenFiles: false, skipCaptureAccessTimeOnlyChange: false, snapshotDiffAllowSnapRootDescendant: true, maxSnapshotLimit: 65536
17:38:27.900 INFO  SnapshotManager - SkipList is disabled
17:38:27.900 INFO  GSet - Computing capacity for map cachedBlocks
17:38:27.900 INFO  GSet - VM type       = 64-bit
17:38:27.900 INFO  GSet - 0.25% max memory 3.4 GB = 8.8 MB
17:38:27.900 INFO  GSet - capacity      = 2^20 = 1048576 entries
17:38:27.900 INFO  TopMetrics - NNTop conf: dfs.namenode.top.window.num.buckets = 10
17:38:27.900 INFO  TopMetrics - NNTop conf: dfs.namenode.top.num.users = 10
17:38:27.900 INFO  TopMetrics - NNTop conf: dfs.namenode.top.windows.minutes = 1,5,25
17:38:27.900 INFO  FSNamesystem - Retry cache on namenode is enabled
17:38:27.900 INFO  FSNamesystem - Retry cache will use 0.03 of total heap and retry cache entry expiry time is 600000 millis
17:38:27.900 INFO  GSet - Computing capacity for map NameNodeRetryCache
17:38:27.900 INFO  GSet - VM type       = 64-bit
17:38:27.900 INFO  GSet - 0.029999999329447746% max memory 3.4 GB = 1.0 MB
17:38:27.900 INFO  GSet - capacity      = 2^17 = 131072 entries
17:38:27.906 INFO  Storage - Lock on /tmp/minicluster_storage17032969745032485617/name-0-1/in_use.lock acquired by nodename 2975@runnervmrcw8b
17:38:27.911 INFO  Storage - Lock on /tmp/minicluster_storage17032969745032485617/name-0-2/in_use.lock acquired by nodename 2975@runnervmrcw8b
17:38:27.911 INFO  FileJournalManager - Recovering unfinalized segments in /tmp/minicluster_storage17032969745032485617/name-0-1/current
17:38:27.911 INFO  FileJournalManager - Recovering unfinalized segments in /tmp/minicluster_storage17032969745032485617/name-0-2/current
17:38:27.911 INFO  FSImage - No edit log streams selected.
17:38:27.911 INFO  FSImage - Planning to load image: FSImageFile(file=/tmp/minicluster_storage17032969745032485617/name-0-1/current/fsimage_0000000000000000000, cpktTxId=0000000000000000000)
17:38:27.912 INFO  FSImageFormatPBINode - Loading 1 INodes.
17:38:27.912 INFO  FSImageFormatPBINode - Successfully loaded 1 inodes
17:38:27.912 INFO  FSImageFormatPBINode - Completed update blocks map and name cache, total waiting duration 0ms.
17:38:27.913 INFO  FSImageFormatProtobuf - Loaded FSImage in 0 seconds.
17:38:27.913 INFO  FSImage - Loaded image for txid 0 from /tmp/minicluster_storage17032969745032485617/name-0-1/current/fsimage_0000000000000000000
17:38:27.913 INFO  FSNamesystem - Need to save fs image? false (staleImage=false, haEnabled=false, isRollingUpgrade=false)
17:38:27.913 INFO  FSEditLog - Starting log segment at 1
17:38:27.925 INFO  NameCache - initialized with 0 entries 0 lookups
17:38:27.925 INFO  FSNamesystem - Finished loading FSImage in 25 msecs
17:38:27.925 INFO  NameNode - RPC server is binding to localhost:0
17:38:27.925 INFO  NameNode - Enable NameNode state context:false
17:38:27.925 INFO  CallQueueManager - Using callQueue: class java.util.concurrent.LinkedBlockingQueue, queueCapacity: 1000, scheduler: class org.apache.hadoop.ipc.DefaultRpcScheduler, ipcBackoff: false.
17:38:27.925 INFO  Server - Listener at localhost:35551
17:38:27.926 INFO  Server - Starting Socket Reader #1 for port 0
17:38:27.928 INFO  NameNode - Clients are to use localhost:35551 to access this namenode/service.
17:38:27.928 INFO  FSNamesystem - Registered FSNamesystemState, ReplicatedBlocksState and ECBlockGroupsState MBeans.
17:38:27.935 INFO  LeaseManager - Number of blocks under construction: 0
17:38:27.935 INFO  DatanodeAdminDefaultMonitor - Initialized the Default Decommission and Maintenance monitor
17:38:27.936 INFO  BlockManager - Start MarkedDeleteBlockScrubber thread
17:38:27.936 INFO  BlockManager - initializing replication queues
17:38:27.936 INFO  StateChange - STATE* Leaving safe mode after 0 secs
17:38:27.936 INFO  StateChange - STATE* Network topology has 0 racks and 0 datanodes
17:38:27.936 INFO  StateChange - STATE* UnderReplicatedBlocks has 0 blocks
17:38:27.938 INFO  Server - IPC Server Responder: starting
17:38:27.938 INFO  Server - IPC Server listener on 0: starting
17:38:27.939 INFO  BlockManager - Total number of blocks            = 0
17:38:27.939 INFO  BlockManager - Number of invalid blocks          = 0
17:38:27.939 INFO  BlockManager - Number of under-replicated blocks = 0
17:38:27.939 INFO  BlockManager - Number of  over-replicated blocks = 0
17:38:27.939 INFO  BlockManager - Number of blocks being written    = 0
17:38:27.939 INFO  StateChange - STATE* Replication Queue initialization scan for invalid, over- and under-replicated blocks completed in 3 msec
17:38:27.940 INFO  NameNode - NameNode RPC up at: localhost/127.0.0.1:35551
17:38:27.940 WARN  MetricsLoggerTask - Metrics logging will not be async since the logger is not log4j
17:38:27.940 INFO  FSNamesystem - Starting services required for active state
17:38:27.940 INFO  FSDirectory - Initializing quota with 12 thread(s)
17:38:27.941 INFO  FSDirectory - Quota initialization completed in 1 milliseconds
name space=1
storage space=0
storage types=RAM_DISK=0, SSD=0, DISK=0, ARCHIVE=0, PROVIDED=0
17:38:27.941 INFO  CacheReplicationMonitor - Starting CacheReplicationMonitor with interval 30000 milliseconds
17:38:27.942 INFO  MiniDFSCluster - Starting DataNode 0 with dfs.datanode.data.dir: [DISK]file:/tmp/minicluster_storage17032969745032485617/data/data1,[DISK]file:/tmp/minicluster_storage17032969745032485617/data/data2
17:38:27.942 INFO  ThrottledAsyncChecker - Scheduling a check for [DISK]file:/tmp/minicluster_storage17032969745032485617/data/data1
17:38:27.943 INFO  ThrottledAsyncChecker - Scheduling a check for [DISK]file:/tmp/minicluster_storage17032969745032485617/data/data2
17:38:27.952 INFO  MetricsSystemImpl - DataNode metrics system started (again)
17:38:27.952 INFO  Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
17:38:27.952 INFO  BlockScanner - Initialized block scanner with targetBytesPerSec 1048576
17:38:27.953 INFO  DataNode - Configured hostname is 127.0.0.1
17:38:27.953 INFO  Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
17:38:27.953 INFO  DataNode - Starting DataNode with maxLockedMemory = 0
17:38:27.953 INFO  DataNode - Opened streaming server at /127.0.0.1:35631
17:38:27.953 INFO  DataNode - Balancing bandwidth is 104857600 bytes/s
17:38:27.953 INFO  DataNode - Number threads for balancing is 100
17:38:27.954 WARN  AuthenticationFilter - Unable to initialize FileSignerSecretProvider, falling back to use random secrets. Reason: Could not read signature secret file: /home/runner/hadoop-http-auth-signature-secret
17:38:27.955 WARN  HttpRequestLog - Jetty request log can only be enabled using Log4j
17:38:27.956 INFO  HttpServer2 - Added global filter 'safety' (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter)
17:38:27.957 INFO  HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context datanode
17:38:27.957 INFO  HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context static
17:38:27.957 INFO  HttpServer2 - Jetty bound to port 38585
17:38:27.957 INFO  Server - jetty-9.4.56.v20240826; built: 2024-08-26T17:15:05.868Z; git: ec6782ff5ead824dabdcf47fa98f90a4aedff401; jvm 17.0.6+10
17:38:27.958 INFO  session - DefaultSessionIdManager workerName=node0
17:38:27.958 INFO  session - No SessionScavenger set, using defaults
17:38:27.958 INFO  session - node0 Scavenging every 660000ms
17:38:27.959 INFO  ContextHandler - Started o.e.j.s.ServletContextHandler@4030a8ad{static,/static,jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/static,AVAILABLE}
17:38:28.034 INFO  ContextHandler - Started o.e.j.w.WebAppContext@1d776a9b{datanode,/,file:///tmp/jetty-localhost-38585-hadoop-hdfs-3_3_6-tests_jar-_-any-13846963181430503563/webapp/,AVAILABLE}{jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/datanode}
17:38:28.035 INFO  AbstractConnector - Started ServerConnector@5ae59cc9{HTTP/1.1, (http/1.1)}{localhost:38585}
17:38:28.035 INFO  Server - Started @70147ms
17:38:28.036 WARN  DatanodeHttpServer - Got null for restCsrfPreventionFilter - will not do any filtering.
17:38:28.037 INFO  DatanodeHttpServer - Listening HTTP traffic on /127.0.0.1:46717
17:38:28.037 INFO  DataNode - dnUserName = runner
17:38:28.037 INFO  DataNode - supergroup = supergroup
17:38:28.037 INFO  JvmPauseMonitor - Starting JVM pause monitor
17:38:28.037 INFO  CallQueueManager - Using callQueue: class java.util.concurrent.LinkedBlockingQueue, queueCapacity: 1000, scheduler: class org.apache.hadoop.ipc.DefaultRpcScheduler, ipcBackoff: false.
17:38:28.037 INFO  Server - Listener at localhost:38653
17:38:28.037 INFO  Server - Starting Socket Reader #1 for port 0
17:38:28.039 INFO  DataNode - Opened IPC server at /127.0.0.1:38653
17:38:28.050 INFO  DataNode - Refresh request received for nameservices: null
17:38:28.050 INFO  DataNode - Starting BPOfferServices for nameservices: <default>
17:38:28.050 WARN  MetricsLoggerTask - Metrics logging will not be async since the logger is not log4j
17:38:28.050 INFO  DataNode - Block pool <registering> (Datanode Uuid unassigned) service to localhost/127.0.0.1:35551 starting to offer service
17:38:28.051 INFO  Server - IPC Server Responder: starting
17:38:28.051 INFO  Server - IPC Server listener on 0: starting
17:38:28.052 INFO  DataNode - Acknowledging ACTIVE Namenode during handshakeBlock pool <registering> (Datanode Uuid unassigned) service to localhost/127.0.0.1:35551
17:38:28.052 INFO  Storage - Using 2 threads to upgrade data directories (dfs.datanode.parallel.volumes.load.threads.num=2, dataDirs=2)
17:38:28.054 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=datanodeReport	src=null	dst=null	perm=null	proto=rpc
17:38:28.054 INFO  MiniDFSCluster - dnInfo.length != numDataNodes
17:38:28.054 INFO  MiniDFSCluster - Waiting for cluster to become active
17:38:28.059 INFO  Storage - Lock on /tmp/minicluster_storage17032969745032485617/data/data1/in_use.lock acquired by nodename 2975@runnervmrcw8b
17:38:28.059 INFO  Storage - Storage directory with location [DISK]file:/tmp/minicluster_storage17032969745032485617/data/data1 is not formatted for namespace 1756611818. Formatting...
17:38:28.059 INFO  Storage - Generated new storageID DS-aaeb5fee-79fb-4dd3-b08e-5e6b7ed5c4b1 for directory /tmp/minicluster_storage17032969745032485617/data/data1 
17:38:28.074 INFO  Storage - Lock on /tmp/minicluster_storage17032969745032485617/data/data2/in_use.lock acquired by nodename 2975@runnervmrcw8b
17:38:28.074 INFO  Storage - Storage directory with location [DISK]file:/tmp/minicluster_storage17032969745032485617/data/data2 is not formatted for namespace 1756611818. Formatting...
17:38:28.074 INFO  Storage - Generated new storageID DS-32b3a99b-f50c-48bf-8125-1dc609cc5178 for directory /tmp/minicluster_storage17032969745032485617/data/data2 
17:38:28.093 INFO  Storage - Analyzing storage directories for bpid BP-1987156128-10.1.0.252-1761586707754
17:38:28.093 INFO  Storage - Locking is disabled for /tmp/minicluster_storage17032969745032485617/data/data1/current/BP-1987156128-10.1.0.252-1761586707754
17:38:28.093 INFO  Storage - Block pool storage directory for location [DISK]file:/tmp/minicluster_storage17032969745032485617/data/data1 and block pool id BP-1987156128-10.1.0.252-1761586707754 is not formatted. Formatting ...
17:38:28.093 INFO  Storage - Formatting block pool BP-1987156128-10.1.0.252-1761586707754 directory /tmp/minicluster_storage17032969745032485617/data/data1/current/BP-1987156128-10.1.0.252-1761586707754/current
17:38:28.111 INFO  Storage - Analyzing storage directories for bpid BP-1987156128-10.1.0.252-1761586707754
17:38:28.112 INFO  Storage - Locking is disabled for /tmp/minicluster_storage17032969745032485617/data/data2/current/BP-1987156128-10.1.0.252-1761586707754
17:38:28.112 INFO  Storage - Block pool storage directory for location [DISK]file:/tmp/minicluster_storage17032969745032485617/data/data2 and block pool id BP-1987156128-10.1.0.252-1761586707754 is not formatted. Formatting ...
17:38:28.112 INFO  Storage - Formatting block pool BP-1987156128-10.1.0.252-1761586707754 directory /tmp/minicluster_storage17032969745032485617/data/data2/current/BP-1987156128-10.1.0.252-1761586707754/current
17:38:28.118 INFO  DataNode - Setting up storage: nsid=1756611818;bpid=BP-1987156128-10.1.0.252-1761586707754;lv=-57;nsInfo=lv=-66;cid=testClusterID;nsid=1756611818;c=1761586707754;bpid=BP-1987156128-10.1.0.252-1761586707754;dnuuid=null
17:38:28.125 INFO  DataNode - Generated and persisted new Datanode UUID 40dea655-a5f9-4cdd-bea0-cdd35b1d8d69
17:38:28.125 INFO  FsDatasetImpl - The datanode lock is a read write lock
17:38:28.126 INFO  FsDatasetImpl - Added new volume: DS-aaeb5fee-79fb-4dd3-b08e-5e6b7ed5c4b1
17:38:28.126 INFO  FsDatasetImpl - Added volume - [DISK]file:/tmp/minicluster_storage17032969745032485617/data/data1, StorageType: DISK
17:38:28.127 INFO  FsDatasetImpl - Added new volume: DS-32b3a99b-f50c-48bf-8125-1dc609cc5178
17:38:28.127 INFO  FsDatasetImpl - Added volume - [DISK]file:/tmp/minicluster_storage17032969745032485617/data/data2, StorageType: DISK
17:38:28.127 INFO  MemoryMappableBlockLoader - Initializing cache loader: MemoryMappableBlockLoader.
17:38:28.127 INFO  FsDatasetImpl - Registered FSDatasetState MBean
17:38:28.128 INFO  FsDatasetImpl - Adding block pool BP-1987156128-10.1.0.252-1761586707754
17:38:28.128 INFO  FsDatasetImpl - Scanning block pool BP-1987156128-10.1.0.252-1761586707754 on volume /tmp/minicluster_storage17032969745032485617/data/data1...
17:38:28.128 INFO  FsDatasetImpl - Scanning block pool BP-1987156128-10.1.0.252-1761586707754 on volume /tmp/minicluster_storage17032969745032485617/data/data2...
17:38:28.128 WARN  FsDatasetImpl - dfsUsed file missing in /tmp/minicluster_storage17032969745032485617/data/data1/current/BP-1987156128-10.1.0.252-1761586707754/current, will proceed with Du for space computation calculation, 
17:38:28.128 WARN  FsDatasetImpl - dfsUsed file missing in /tmp/minicluster_storage17032969745032485617/data/data2/current/BP-1987156128-10.1.0.252-1761586707754/current, will proceed with Du for space computation calculation, 
17:38:28.139 INFO  FsDatasetImpl - Time taken to scan block pool BP-1987156128-10.1.0.252-1761586707754 on /tmp/minicluster_storage17032969745032485617/data/data1: 11ms
17:38:28.139 INFO  FsDatasetImpl - Time taken to scan block pool BP-1987156128-10.1.0.252-1761586707754 on /tmp/minicluster_storage17032969745032485617/data/data2: 11ms
17:38:28.139 INFO  FsDatasetImpl - Total time to scan all replicas for block pool BP-1987156128-10.1.0.252-1761586707754: 11ms
17:38:28.139 INFO  FsDatasetImpl - Adding replicas to map for block pool BP-1987156128-10.1.0.252-1761586707754 on volume /tmp/minicluster_storage17032969745032485617/data/data1...
17:38:28.139 INFO  BlockPoolSlice - Replica Cache file: /tmp/minicluster_storage17032969745032485617/data/data1/current/BP-1987156128-10.1.0.252-1761586707754/current/replicas doesn't exist 
17:38:28.139 INFO  FsDatasetImpl - Adding replicas to map for block pool BP-1987156128-10.1.0.252-1761586707754 on volume /tmp/minicluster_storage17032969745032485617/data/data2...
17:38:28.140 INFO  BlockPoolSlice - Replica Cache file: /tmp/minicluster_storage17032969745032485617/data/data2/current/BP-1987156128-10.1.0.252-1761586707754/current/replicas doesn't exist 
17:38:28.140 INFO  FsDatasetImpl - Time to add replicas to map for block pool BP-1987156128-10.1.0.252-1761586707754 on volume /tmp/minicluster_storage17032969745032485617/data/data1: 1ms
17:38:28.140 INFO  FsDatasetImpl - Time to add replicas to map for block pool BP-1987156128-10.1.0.252-1761586707754 on volume /tmp/minicluster_storage17032969745032485617/data/data2: 0ms
17:38:28.140 INFO  FsDatasetImpl - Total time to add all replicas to map for block pool BP-1987156128-10.1.0.252-1761586707754: 1ms
17:38:28.140 INFO  ThrottledAsyncChecker - Scheduling a check for /tmp/minicluster_storage17032969745032485617/data/data1
17:38:28.140 INFO  DatasetVolumeChecker - Scheduled health check for volume /tmp/minicluster_storage17032969745032485617/data/data1
17:38:28.140 INFO  ThrottledAsyncChecker - Scheduling a check for /tmp/minicluster_storage17032969745032485617/data/data2
17:38:28.140 INFO  DatasetVolumeChecker - Scheduled health check for volume /tmp/minicluster_storage17032969745032485617/data/data2
17:38:28.141 INFO  VolumeScanner - Now scanning bpid BP-1987156128-10.1.0.252-1761586707754 on volume /tmp/minicluster_storage17032969745032485617/data/data2
17:38:28.141 INFO  VolumeScanner - Now scanning bpid BP-1987156128-10.1.0.252-1761586707754 on volume /tmp/minicluster_storage17032969745032485617/data/data1
17:38:28.141 WARN  DirectoryScanner - dfs.datanode.directoryscan.throttle.limit.ms.per.sec set to value above 1000 ms/sec. Assuming default value of -1
17:38:28.141 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage17032969745032485617/data/data2, DS-32b3a99b-f50c-48bf-8125-1dc609cc5178): finished scanning block pool BP-1987156128-10.1.0.252-1761586707754
17:38:28.141 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage17032969745032485617/data/data1, DS-aaeb5fee-79fb-4dd3-b08e-5e6b7ed5c4b1): finished scanning block pool BP-1987156128-10.1.0.252-1761586707754
17:38:28.141 INFO  DirectoryScanner - Periodic Directory Tree Verification scan starting in 13323597ms with interval of 21600000ms and throttle limit of -1ms/s
17:38:28.141 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage17032969745032485617/data/data2, DS-32b3a99b-f50c-48bf-8125-1dc609cc5178): no suitable block pools found to scan.  Waiting 1814399999 ms.
17:38:28.141 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage17032969745032485617/data/data1, DS-aaeb5fee-79fb-4dd3-b08e-5e6b7ed5c4b1): no suitable block pools found to scan.  Waiting 1814399999 ms.
17:38:28.141 INFO  DataNode - Block pool BP-1987156128-10.1.0.252-1761586707754 (Datanode Uuid 40dea655-a5f9-4cdd-bea0-cdd35b1d8d69) service to localhost/127.0.0.1:35551 beginning handshake with NN
17:38:28.142 INFO  StateChange - BLOCK* registerDatanode: from DatanodeRegistration(127.0.0.1:35631, datanodeUuid=40dea655-a5f9-4cdd-bea0-cdd35b1d8d69, infoPort=46717, infoSecurePort=0, ipcPort=38653, storageInfo=lv=-57;cid=testClusterID;nsid=1756611818;c=1761586707754) storage 40dea655-a5f9-4cdd-bea0-cdd35b1d8d69
17:38:28.142 INFO  NetworkTopology - Adding a new node: /default-rack/127.0.0.1:35631
17:38:28.142 INFO  BlockReportLeaseManager - Registered DN 40dea655-a5f9-4cdd-bea0-cdd35b1d8d69 (127.0.0.1:35631).
17:38:28.142 INFO  DataNode - Block pool BP-1987156128-10.1.0.252-1761586707754 (Datanode Uuid 40dea655-a5f9-4cdd-bea0-cdd35b1d8d69) service to localhost/127.0.0.1:35551 successfully registered with NN
17:38:28.142 INFO  DataNode - For namenode localhost/127.0.0.1:35551 using BLOCKREPORT_INTERVAL of 21600000msecs CACHEREPORT_INTERVAL of 10000msecs Initial delay: 0msecs; heartBeatInterval=3000
17:38:28.142 INFO  DataNode - Starting IBR Task Handler.
17:38:28.143 INFO  DatanodeDescriptor - Adding new storage ID DS-aaeb5fee-79fb-4dd3-b08e-5e6b7ed5c4b1 for DN 127.0.0.1:35631
17:38:28.143 INFO  DatanodeDescriptor - Adding new storage ID DS-32b3a99b-f50c-48bf-8125-1dc609cc5178 for DN 127.0.0.1:35631
17:38:28.143 INFO  DataNode - After receiving heartbeat response, updating state of namenode localhost:35551 to active
17:38:28.144 INFO  BlockStateChange - BLOCK* processReport 0x91624da43ba6be3 with lease ID 0x348c1ae4dd2a1151: Processing first storage report for DS-aaeb5fee-79fb-4dd3-b08e-5e6b7ed5c4b1 from datanode DatanodeRegistration(127.0.0.1:35631, datanodeUuid=40dea655-a5f9-4cdd-bea0-cdd35b1d8d69, infoPort=46717, infoSecurePort=0, ipcPort=38653, storageInfo=lv=-57;cid=testClusterID;nsid=1756611818;c=1761586707754)
17:38:28.144 INFO  BlockStateChange - BLOCK* processReport 0x91624da43ba6be3 with lease ID 0x348c1ae4dd2a1151: from storage DS-aaeb5fee-79fb-4dd3-b08e-5e6b7ed5c4b1 node DatanodeRegistration(127.0.0.1:35631, datanodeUuid=40dea655-a5f9-4cdd-bea0-cdd35b1d8d69, infoPort=46717, infoSecurePort=0, ipcPort=38653, storageInfo=lv=-57;cid=testClusterID;nsid=1756611818;c=1761586707754), blocks: 0, hasStaleStorage: true, processing time: 0 msecs, invalidatedBlocks: 0
17:38:28.144 INFO  BlockStateChange - BLOCK* processReport 0x91624da43ba6be3 with lease ID 0x348c1ae4dd2a1151: Processing first storage report for DS-32b3a99b-f50c-48bf-8125-1dc609cc5178 from datanode DatanodeRegistration(127.0.0.1:35631, datanodeUuid=40dea655-a5f9-4cdd-bea0-cdd35b1d8d69, infoPort=46717, infoSecurePort=0, ipcPort=38653, storageInfo=lv=-57;cid=testClusterID;nsid=1756611818;c=1761586707754)
17:38:28.144 INFO  BlockStateChange - BLOCK* processReport 0x91624da43ba6be3 with lease ID 0x348c1ae4dd2a1151: from storage DS-32b3a99b-f50c-48bf-8125-1dc609cc5178 node DatanodeRegistration(127.0.0.1:35631, datanodeUuid=40dea655-a5f9-4cdd-bea0-cdd35b1d8d69, infoPort=46717, infoSecurePort=0, ipcPort=38653, storageInfo=lv=-57;cid=testClusterID;nsid=1756611818;c=1761586707754), blocks: 0, hasStaleStorage: false, processing time: 0 msecs, invalidatedBlocks: 0
17:38:28.144 INFO  DataNode - Successfully sent block report 0x91624da43ba6be3 with lease ID 0x348c1ae4dd2a1151 to namenode: localhost/127.0.0.1:35551,  containing 2 storage report(s), of which we sent 2. The reports had 0 total blocks and used 1 RPC(s). This took 0 msecs to generate and 1 msecs for RPC and NN processing. Got back one command: FinalizeCommand/5.
17:38:28.144 INFO  DataNode - Got finalize command for block pool BP-1987156128-10.1.0.252-1761586707754
17:38:28.155 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=datanodeReport	src=null	dst=null	perm=null	proto=rpc
17:38:28.155 INFO  MiniDFSCluster - Cluster is active
17:38:28.157 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.159 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=create	src=/user/runner/hdfs.cram	dst=null	perm=runner:supergroup:rw-r--r--	proto=rpc
17:38:28.161 INFO  StateChange - BLOCK* allocate blk_1073741825_1001, replicas=127.0.0.1:35631 for /user/runner/hdfs.cram
17:38:28.162 INFO  DataNode - Receiving BP-1987156128-10.1.0.252-1761586707754:blk_1073741825_1001 src: /127.0.0.1:53210 dest: /127.0.0.1:35631
17:38:28.164 INFO  clienttrace - src: /127.0.0.1:53210, dest: /127.0.0.1:35631, bytes: 50619, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_1168220604_1, offset: 0, srvID: 40dea655-a5f9-4cdd-bea0-cdd35b1d8d69, blockid: BP-1987156128-10.1.0.252-1761586707754:blk_1073741825_1001, duration(ns): 650107
17:38:28.164 INFO  DataNode - PacketResponder: BP-1987156128-10.1.0.252-1761586707754:blk_1073741825_1001, type=LAST_IN_PIPELINE terminating
17:38:28.164 INFO  StateChange - DIR* completeFile: /user/runner/hdfs.cram is closed by DFSClient_NONMAPREDUCE_1168220604_1
17:38:28.165 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.fasta	dst=null	perm=null	proto=rpc
17:38:28.166 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=create	src=/user/runner/hdfs.fasta	dst=null	perm=runner:supergroup:rw-r--r--	proto=rpc
17:38:28.167 INFO  StateChange - BLOCK* allocate blk_1073741826_1002, replicas=127.0.0.1:35631 for /user/runner/hdfs.fasta
17:38:28.169 INFO  DataNode - Receiving BP-1987156128-10.1.0.252-1761586707754:blk_1073741826_1002 src: /127.0.0.1:53224 dest: /127.0.0.1:35631
17:38:28.172 INFO  clienttrace - src: /127.0.0.1:53224, dest: /127.0.0.1:35631, bytes: 1016671, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_1168220604_1, offset: 0, srvID: 40dea655-a5f9-4cdd-bea0-cdd35b1d8d69, blockid: BP-1987156128-10.1.0.252-1761586707754:blk_1073741826_1002, duration(ns): 2477832
17:38:28.172 INFO  DataNode - PacketResponder: BP-1987156128-10.1.0.252-1761586707754:blk_1073741826_1002, type=LAST_IN_PIPELINE terminating
17:38:28.173 INFO  FSNamesystem - BLOCK* blk_1073741826_1002 is COMMITTED but not COMPLETE(numNodes= 0 <  minimum = 1) in file /user/runner/hdfs.fasta
17:38:28.574 INFO  StateChange - DIR* completeFile: /user/runner/hdfs.fasta is closed by DFSClient_NONMAPREDUCE_1168220604_1
17:38:28.575 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.fasta.fai	dst=null	perm=null	proto=rpc
17:38:28.576 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=create	src=/user/runner/hdfs.fasta.fai	dst=null	perm=runner:supergroup:rw-r--r--	proto=rpc
17:38:28.577 INFO  StateChange - BLOCK* allocate blk_1073741827_1003, replicas=127.0.0.1:35631 for /user/runner/hdfs.fasta.fai
17:38:28.578 INFO  DataNode - Receiving BP-1987156128-10.1.0.252-1761586707754:blk_1073741827_1003 src: /127.0.0.1:53236 dest: /127.0.0.1:35631
17:38:28.579 INFO  clienttrace - src: /127.0.0.1:53236, dest: /127.0.0.1:35631, bytes: 19, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_1168220604_1, offset: 0, srvID: 40dea655-a5f9-4cdd-bea0-cdd35b1d8d69, blockid: BP-1987156128-10.1.0.252-1761586707754:blk_1073741827_1003, duration(ns): 698980
17:38:28.580 INFO  DataNode - PacketResponder: BP-1987156128-10.1.0.252-1761586707754:blk_1073741827_1003, type=LAST_IN_PIPELINE terminating
17:38:28.580 INFO  StateChange - DIR* completeFile: /user/runner/hdfs.fasta.fai is closed by DFSClient_NONMAPREDUCE_1168220604_1
17:38:28.581 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.fasta	dst=null	perm=null	proto=rpc
17:38:28.581 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.582 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.582 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.582 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.583 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram.crai	dst=null	perm=null	proto=rpc
17:38:28.584 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.crai	dst=null	perm=null	proto=rpc
17:38:28.584 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.fasta	dst=null	perm=null	proto=rpc
17:38:28.584 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.fasta	dst=null	perm=null	proto=rpc
17:38:28.585 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.fasta.fai	dst=null	perm=null	proto=rpc
17:38:28.586 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.fasta.fai	dst=null	perm=null	proto=rpc
17:38:28.587 WARN  DFSUtil - Unexpected value for data transfer bytes=23 duration=0
17:38:28.589 WARN  DFSUtil - Unexpected value for data transfer bytes=51015 duration=0
17:38:28.589 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.590 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.590 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram.crai	dst=null	perm=null	proto=rpc
17:38:28.591 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.crai	dst=null	perm=null	proto=rpc
17:38:28.591 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.591 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.593 INFO  MemoryStore - Block broadcast_587 stored as values in memory (estimated size 472.0 B, free 1920.0 MiB)
17:38:28.593 INFO  MemoryStore - Block broadcast_587_piece0 stored as bytes in memory (estimated size 129.0 B, free 1920.0 MiB)
17:38:28.594 INFO  BlockManagerInfo - Added broadcast_587_piece0 in memory on localhost:37953 (size: 129.0 B, free: 1920.0 MiB)
17:38:28.594 INFO  SparkContext - Created broadcast 587 from broadcast at CramSource.java:114
17:38:28.595 INFO  MemoryStore - Block broadcast_588 stored as values in memory (estimated size 297.9 KiB, free 1919.7 MiB)
17:38:28.602 INFO  MemoryStore - Block broadcast_588_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1919.7 MiB)
17:38:28.602 INFO  BlockManagerInfo - Added broadcast_588_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1920.0 MiB)
17:38:28.602 INFO  SparkContext - Created broadcast 588 from newAPIHadoopFile at PathSplitSource.java:96
17:38:28.620 INFO  MemoryStore - Block broadcast_589 stored as values in memory (estimated size 536.0 B, free 1919.7 MiB)
17:38:28.621 INFO  MemoryStore - Block broadcast_589_piece0 stored as bytes in memory (estimated size 187.0 B, free 1919.7 MiB)
17:38:28.621 INFO  BlockManagerInfo - Added broadcast_589_piece0 in memory on localhost:37953 (size: 187.0 B, free: 1920.0 MiB)
17:38:28.621 INFO  SparkContext - Created broadcast 589 from broadcast at CramSource.java:114
17:38:28.622 INFO  MemoryStore - Block broadcast_590 stored as values in memory (estimated size 297.9 KiB, free 1919.4 MiB)
17:38:28.629 INFO  MemoryStore - Block broadcast_590_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1919.3 MiB)
17:38:28.629 INFO  BlockManagerInfo - Added broadcast_590_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.9 MiB)
17:38:28.629 INFO  SparkContext - Created broadcast 590 from newAPIHadoopFile at PathSplitSource.java:96
17:38:28.646 INFO  FileInputFormat - Total input files to process : 1
17:38:28.673 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:244
17:38:28.674 INFO  DAGScheduler - Got job 221 (collect at ReadsSparkSourceUnitTest.java:244) with 1 output partitions
17:38:28.674 INFO  DAGScheduler - Final stage: ResultStage 285 (collect at ReadsSparkSourceUnitTest.java:244)
17:38:28.674 INFO  DAGScheduler - Parents of final stage: List()
17:38:28.674 INFO  DAGScheduler - Missing parents: List()
17:38:28.674 INFO  DAGScheduler - Submitting ResultStage 285 (MapPartitionsRDD[1405] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:28.687 INFO  MemoryStore - Block broadcast_591 stored as values in memory (estimated size 286.8 KiB, free 1919.0 MiB)
17:38:28.688 INFO  MemoryStore - Block broadcast_591_piece0 stored as bytes in memory (estimated size 103.6 KiB, free 1918.9 MiB)
17:38:28.688 INFO  BlockManagerInfo - Added broadcast_591_piece0 in memory on localhost:37953 (size: 103.6 KiB, free: 1919.8 MiB)
17:38:28.688 INFO  SparkContext - Created broadcast 591 from broadcast at DAGScheduler.scala:1580
17:38:28.688 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 285 (MapPartitionsRDD[1405] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:28.688 INFO  TaskSchedulerImpl - Adding task set 285.0 with 1 tasks resource profile 0
17:38:28.689 INFO  TaskSetManager - Starting task 0.0 in stage 285.0 (TID 372) (localhost, executor driver, partition 0, PROCESS_LOCAL, 7839 bytes) 
17:38:28.689 INFO  Executor - Running task 0.0 in stage 285.0 (TID 372)
17:38:28.718 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/NA12878.chr17_69k_70k.dictFix.cram:0+50619
17:38:28.728 INFO  Executor - Finished task 0.0 in stage 285.0 (TID 372). 154058 bytes result sent to driver
17:38:28.729 INFO  TaskSetManager - Finished task 0.0 in stage 285.0 (TID 372) in 40 ms on localhost (executor driver) (1/1)
17:38:28.729 INFO  TaskSchedulerImpl - Removed TaskSet 285.0, whose tasks have all completed, from pool 
17:38:28.729 INFO  DAGScheduler - ResultStage 285 (collect at ReadsSparkSourceUnitTest.java:244) finished in 0.055 s
17:38:28.729 INFO  DAGScheduler - Job 221 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:28.729 INFO  TaskSchedulerImpl - Killing all running tasks in stage 285: Stage finished
17:38:28.729 INFO  DAGScheduler - Job 221 finished: collect at ReadsSparkSourceUnitTest.java:244, took 0.055557 s
17:38:28.730 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.fasta	dst=null	perm=null	proto=rpc
17:38:28.730 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.731 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.731 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.732 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.733 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram.crai	dst=null	perm=null	proto=rpc
17:38:28.733 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.crai	dst=null	perm=null	proto=rpc
17:38:28.734 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.fasta	dst=null	perm=null	proto=rpc
17:38:28.734 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.fasta	dst=null	perm=null	proto=rpc
17:38:28.735 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.fasta.fai	dst=null	perm=null	proto=rpc
17:38:28.735 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.fasta.fai	dst=null	perm=null	proto=rpc
17:38:28.736 WARN  DFSUtil - Unexpected value for data transfer bytes=23 duration=0
17:38:28.738 WARN  DFSUtil - Unexpected value for data transfer bytes=51015 duration=0
17:38:28.738 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.739 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.739 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram.crai	dst=null	perm=null	proto=rpc
17:38:28.739 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.crai	dst=null	perm=null	proto=rpc
17:38:28.740 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.740 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.741 WARN  DFSUtil - Unexpected value for data transfer bytes=51015 duration=0
17:38:28.741 INFO  MemoryStore - Block broadcast_592 stored as values in memory (estimated size 472.0 B, free 1918.9 MiB)
17:38:28.742 INFO  MemoryStore - Block broadcast_592_piece0 stored as bytes in memory (estimated size 129.0 B, free 1918.9 MiB)
17:38:28.742 INFO  BlockManagerInfo - Added broadcast_592_piece0 in memory on localhost:37953 (size: 129.0 B, free: 1919.8 MiB)
17:38:28.742 INFO  SparkContext - Created broadcast 592 from broadcast at CramSource.java:114
17:38:28.743 INFO  MemoryStore - Block broadcast_593 stored as values in memory (estimated size 297.9 KiB, free 1918.6 MiB)
17:38:28.749 INFO  MemoryStore - Block broadcast_593_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1918.6 MiB)
17:38:28.749 INFO  BlockManagerInfo - Added broadcast_593_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.8 MiB)
17:38:28.749 INFO  SparkContext - Created broadcast 593 from newAPIHadoopFile at PathSplitSource.java:96
17:38:28.763 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.763 INFO  FileInputFormat - Total input files to process : 1
17:38:28.763 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.786 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:245
17:38:28.786 INFO  DAGScheduler - Got job 222 (collect at ReadsSparkSourceUnitTest.java:245) with 1 output partitions
17:38:28.786 INFO  DAGScheduler - Final stage: ResultStage 286 (collect at ReadsSparkSourceUnitTest.java:245)
17:38:28.786 INFO  DAGScheduler - Parents of final stage: List()
17:38:28.786 INFO  DAGScheduler - Missing parents: List()
17:38:28.787 INFO  DAGScheduler - Submitting ResultStage 286 (MapPartitionsRDD[1411] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:28.797 INFO  MemoryStore - Block broadcast_594 stored as values in memory (estimated size 286.8 KiB, free 1918.3 MiB)
17:38:28.798 INFO  MemoryStore - Block broadcast_594_piece0 stored as bytes in memory (estimated size 103.6 KiB, free 1918.2 MiB)
17:38:28.798 INFO  BlockManagerInfo - Added broadcast_594_piece0 in memory on localhost:37953 (size: 103.6 KiB, free: 1919.7 MiB)
17:38:28.798 INFO  SparkContext - Created broadcast 594 from broadcast at DAGScheduler.scala:1580
17:38:28.798 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 286 (MapPartitionsRDD[1411] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:28.798 INFO  TaskSchedulerImpl - Adding task set 286.0 with 1 tasks resource profile 0
17:38:28.799 INFO  TaskSetManager - Starting task 0.0 in stage 286.0 (TID 373) (localhost, executor driver, partition 0, ANY, 7797 bytes) 
17:38:28.799 INFO  Executor - Running task 0.0 in stage 286.0 (TID 373)
17:38:28.821 INFO  NewHadoopRDD - Input split: hdfs://localhost:35551/user/runner/hdfs.cram:0+50619
17:38:28.822 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.823 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.cram	dst=null	perm=null	proto=rpc
17:38:28.823 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.cram.crai	dst=null	perm=null	proto=rpc
17:38:28.824 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.crai	dst=null	perm=null	proto=rpc
17:38:28.824 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.fasta	dst=null	perm=null	proto=rpc
17:38:28.825 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.fasta	dst=null	perm=null	proto=rpc
17:38:28.825 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.fasta.fai	dst=null	perm=null	proto=rpc
17:38:28.826 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.fasta.fai	dst=null	perm=null	proto=rpc
17:38:28.827 WARN  DFSUtil - Unexpected value for data transfer bytes=23 duration=0
17:38:28.828 WARN  DFSUtil - Unexpected value for data transfer bytes=51015 duration=0
17:38:28.838 WARN  DFSUtil - Unexpected value for data transfer bytes=232039 duration=0
17:38:28.839 WARN  DFSUtil - Unexpected value for data transfer bytes=99943 duration=0
17:38:28.841 INFO  Executor - Finished task 0.0 in stage 286.0 (TID 373). 154058 bytes result sent to driver
17:38:28.842 INFO  TaskSetManager - Finished task 0.0 in stage 286.0 (TID 373) in 43 ms on localhost (executor driver) (1/1)
17:38:28.842 INFO  TaskSchedulerImpl - Removed TaskSet 286.0, whose tasks have all completed, from pool 
17:38:28.842 INFO  DAGScheduler - ResultStage 286 (collect at ReadsSparkSourceUnitTest.java:245) finished in 0.055 s
17:38:28.842 INFO  DAGScheduler - Job 222 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:28.842 INFO  TaskSchedulerImpl - Killing all running tasks in stage 286: Stage finished
17:38:28.842 INFO  DAGScheduler - Job 222 finished: collect at ReadsSparkSourceUnitTest.java:245, took 0.055895 s
17:38:28.844 INFO  MiniDFSCluster - Shutting down the Mini HDFS Cluster
17:38:28.844 INFO  MiniDFSCluster - Shutting down DataNode 0
17:38:28.844 INFO  DirectoryScanner - Shutdown has been called
17:38:28.844 INFO  DataNode - Closing all peers.
17:38:28.844 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage17032969745032485617/data/data2, DS-32b3a99b-f50c-48bf-8125-1dc609cc5178) exiting.
17:38:28.845 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage17032969745032485617/data/data1, DS-aaeb5fee-79fb-4dd3-b08e-5e6b7ed5c4b1) exiting.
17:38:28.851 INFO  BlockManagerInfo - Removed broadcast_587_piece0 on localhost:37953 in memory (size: 129.0 B, free: 1919.7 MiB)
17:38:28.851 INFO  ContextHandler - Stopped o.e.j.w.WebAppContext@1d776a9b{datanode,/,null,STOPPED}{jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/datanode}
17:38:28.851 INFO  BlockManagerInfo - Removed broadcast_588_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.7 MiB)
17:38:28.851 INFO  AbstractConnector - Stopped ServerConnector@5ae59cc9{HTTP/1.1, (http/1.1)}{localhost:0}
17:38:28.851 INFO  session - node0 Stopped scavenging
17:38:28.851 INFO  ContextHandler - Stopped o.e.j.s.ServletContextHandler@4030a8ad{static,/static,jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/static,STOPPED}
17:38:28.851 INFO  BlockManagerInfo - Removed broadcast_590_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.7 MiB)
17:38:28.852 INFO  BlockManagerInfo - Removed broadcast_592_piece0 on localhost:37953 in memory (size: 129.0 B, free: 1919.7 MiB)
17:38:28.853 INFO  BlockManagerInfo - Removed broadcast_591_piece0 on localhost:37953 in memory (size: 103.6 KiB, free: 1919.8 MiB)
17:38:28.853 INFO  DataNode - Waiting up to 30 seconds for transfer threads to complete
17:38:28.853 INFO  Server - Stopping server on 38653
17:38:28.854 INFO  Server - Stopping IPC Server listener on 0
17:38:28.854 INFO  Server - Stopping IPC Server Responder
17:38:28.854 INFO  BlockManagerInfo - Removed broadcast_589_piece0 on localhost:37953 in memory (size: 187.0 B, free: 1919.8 MiB)
17:38:28.855 ERROR DataNode - Command processor encountered interrupt and exit.
17:38:28.855 WARN  IncrementalBlockReportManager - IncrementalBlockReportManager interrupted
17:38:28.855 WARN  DataNode - Ending command processor service for: Thread[Command processor,5,main]
17:38:28.855 WARN  DataNode - Ending block pool service for: Block pool BP-1987156128-10.1.0.252-1761586707754 (Datanode Uuid 40dea655-a5f9-4cdd-bea0-cdd35b1d8d69) service to localhost/127.0.0.1:35551
17:38:28.855 INFO  DataNode - Removed Block pool BP-1987156128-10.1.0.252-1761586707754 (Datanode Uuid 40dea655-a5f9-4cdd-bea0-cdd35b1d8d69)
17:38:28.855 INFO  FsDatasetImpl - Removing block pool BP-1987156128-10.1.0.252-1761586707754
17:38:28.855 WARN  IncrementalBlockReportManager - IncrementalBlockReportManager interrupted
17:38:28.855 INFO  BlockManagerInfo - Removed broadcast_593_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.9 MiB)
17:38:28.855 WARN  CachingGetSpaceUsed - Thread Interrupted waiting to refresh disk information: sleep interrupted
17:38:28.855 WARN  CachingGetSpaceUsed - Thread Interrupted waiting to refresh disk information: sleep interrupted
17:38:28.855 INFO  FsDatasetAsyncDiskService - Shutting down all async disk service threads
17:38:28.855 INFO  FsDatasetAsyncDiskService - All async disk service threads have been shut down
17:38:28.855 INFO  RamDiskAsyncLazyPersistService - Shutting down all async lazy persist service threads
17:38:28.855 INFO  RamDiskAsyncLazyPersistService - All async lazy persist service threads have been shut down
17:38:28.855 INFO  DataNode - Shutdown complete.
17:38:28.855 INFO  MiniDFSCluster - Shutting down the namenode
17:38:28.855 INFO  FSNamesystem - Stopping services started for active state
17:38:28.856 INFO  FSEditLog - Ending log segment 1, 18
17:38:28.856 INFO  FSNamesystem - LazyPersistFileScrubber was interrupted, exiting
17:38:28.856 INFO  FSEditLog - Number of transactions: 19 Total time for transactions(ms): 0 Number of transactions batched in Syncs: 4 Number of syncs: 16 SyncTimes(ms): 1 0 
17:38:28.856 INFO  BlockManagerInfo - Removed broadcast_594_piece0 on localhost:37953 in memory (size: 103.6 KiB, free: 1920.0 MiB)
17:38:28.856 INFO  FileJournalManager - Finalizing edits file /tmp/minicluster_storage17032969745032485617/name-0-1/current/edits_inprogress_0000000000000000001 -> /tmp/minicluster_storage17032969745032485617/name-0-1/current/edits_0000000000000000001-0000000000000000019
17:38:28.856 INFO  FSNamesystem - NameNodeEditLogRoller was interrupted, exiting
17:38:28.856 INFO  FileJournalManager - Finalizing edits file /tmp/minicluster_storage17032969745032485617/name-0-2/current/edits_inprogress_0000000000000000001 -> /tmp/minicluster_storage17032969745032485617/name-0-2/current/edits_0000000000000000001-0000000000000000019
17:38:28.856 INFO  FSEditLog - FSEditLogAsync was interrupted, exiting
17:38:28.857 INFO  Server - Stopping server on 35551
17:38:28.857 INFO  CacheReplicationMonitor - Shutting down CacheReplicationMonitor
17:38:28.857 INFO  Server - Stopping IPC Server listener on 0
17:38:28.857 INFO  Server - Stopping IPC Server Responder
17:38:28.858 INFO  BlockManager - Stopping MarkedDeleteBlockScrubber.
17:38:28.858 INFO  BlockManager - Stopping RedundancyMonitor.
17:38:28.860 INFO  FSNamesystem - Stopping services started for active state
17:38:28.860 INFO  FSNamesystem - Stopping services started for standby state
17:38:28.861 INFO  ContextHandler - Stopped o.e.j.w.WebAppContext@5a5d74b2{hdfs,/,null,STOPPED}{jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/hdfs}
17:38:28.862 INFO  AbstractConnector - Stopped ServerConnector@2bdd285b{HTTP/1.1, (http/1.1)}{localhost:0}
17:38:28.862 INFO  session - node0 Stopped scavenging
17:38:28.862 INFO  ContextHandler - Stopped o.e.j.s.ServletContextHandler@592470f8{static,/static,jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/static,STOPPED}
17:38:28.863 INFO  MetricsSystemImpl - Stopping DataNode metrics system...
17:38:28.863 INFO  MetricsSystemImpl - DataNode metrics system stopped.
17:38:28.863 INFO  MetricsSystemImpl - DataNode metrics system shutdown complete.
17:38:28.867 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:28.869 INFO  MemoryStore - Block broadcast_595 stored as values in memory (estimated size 297.9 KiB, free 1919.7 MiB)
17:38:28.875 INFO  MemoryStore - Block broadcast_595_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1919.7 MiB)
17:38:28.875 INFO  BlockManagerInfo - Added broadcast_595_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1920.0 MiB)
17:38:28.875 INFO  SparkContext - Created broadcast 595 from newAPIHadoopFile at PathSplitSource.java:96
17:38:28.897 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:28.898 INFO  BlockManagerInfo - Removed broadcast_595_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1920.0 MiB)
17:38:28.899 INFO  MemoryStore - Block broadcast_596 stored as values in memory (estimated size 298.0 KiB, free 1919.7 MiB)
17:38:28.905 INFO  MemoryStore - Block broadcast_596_piece0 stored as bytes in memory (estimated size 50.3 KiB, free 1919.7 MiB)
17:38:28.905 INFO  BlockManagerInfo - Added broadcast_596_piece0 in memory on localhost:37953 (size: 50.3 KiB, free: 1920.0 MiB)
17:38:28.905 INFO  SparkContext - Created broadcast 596 from newAPIHadoopFile at PathSplitSource.java:96
17:38:28.923 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:28.925 INFO  MemoryStore - Block broadcast_597 stored as values in memory (estimated size 298.0 KiB, free 1919.4 MiB)
17:38:28.930 INFO  MemoryStore - Block broadcast_597_piece0 stored as bytes in memory (estimated size 50.3 KiB, free 1919.3 MiB)
17:38:28.931 INFO  BlockManagerInfo - Added broadcast_597_piece0 in memory on localhost:37953 (size: 50.3 KiB, free: 1919.9 MiB)
17:38:28.931 INFO  SparkContext - Created broadcast 597 from newAPIHadoopFile at PathSplitSource.java:96
17:38:28.951 INFO  MemoryStore - Block broadcast_598 stored as values in memory (estimated size 536.0 B, free 1919.3 MiB)
17:38:28.952 INFO  MemoryStore - Block broadcast_598_piece0 stored as bytes in memory (estimated size 187.0 B, free 1919.3 MiB)
17:38:28.952 INFO  BlockManagerInfo - Added broadcast_598_piece0 in memory on localhost:37953 (size: 187.0 B, free: 1919.9 MiB)
17:38:28.952 INFO  SparkContext - Created broadcast 598 from broadcast at CramSource.java:114
17:38:28.953 INFO  MemoryStore - Block broadcast_599 stored as values in memory (estimated size 297.9 KiB, free 1919.0 MiB)
17:38:28.958 INFO  MemoryStore - Block broadcast_599_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1919.0 MiB)
17:38:28.958 INFO  BlockManagerInfo - Added broadcast_599_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.9 MiB)
17:38:28.959 INFO  SparkContext - Created broadcast 599 from newAPIHadoopFile at PathSplitSource.java:96
17:38:28.973 INFO  MemoryStore - Block broadcast_600 stored as values in memory (estimated size 608.0 B, free 1919.0 MiB)
17:38:28.973 INFO  MemoryStore - Block broadcast_600_piece0 stored as bytes in memory (estimated size 206.0 B, free 1919.0 MiB)
17:38:28.973 INFO  BlockManagerInfo - Added broadcast_600_piece0 in memory on localhost:37953 (size: 206.0 B, free: 1919.9 MiB)
17:38:28.973 INFO  SparkContext - Created broadcast 600 from broadcast at CramSource.java:114
17:38:28.974 INFO  MemoryStore - Block broadcast_601 stored as values in memory (estimated size 297.9 KiB, free 1918.7 MiB)
17:38:28.980 INFO  MemoryStore - Block broadcast_601_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1918.6 MiB)
17:38:28.980 INFO  BlockManagerInfo - Added broadcast_601_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.8 MiB)
17:38:28.980 INFO  SparkContext - Created broadcast 601 from newAPIHadoopFile at PathSplitSource.java:96
17:38:28.993 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:28.994 INFO  MemoryStore - Block broadcast_602 stored as values in memory (estimated size 298.0 KiB, free 1918.3 MiB)
17:38:29.000 INFO  MemoryStore - Block broadcast_602_piece0 stored as bytes in memory (estimated size 50.3 KiB, free 1918.3 MiB)
17:38:29.000 INFO  BlockManagerInfo - Added broadcast_602_piece0 in memory on localhost:37953 (size: 50.3 KiB, free: 1919.8 MiB)
17:38:29.000 INFO  SparkContext - Created broadcast 602 from newAPIHadoopFile at PathSplitSource.java:96
17:38:29.019 INFO  FileInputFormat - Total input files to process : 1
17:38:29.050 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:163
17:38:29.051 INFO  DAGScheduler - Got job 223 (collect at ReadsSparkSourceUnitTest.java:163) with 1 output partitions
17:38:29.051 INFO  DAGScheduler - Final stage: ResultStage 287 (collect at ReadsSparkSourceUnitTest.java:163)
17:38:29.051 INFO  DAGScheduler - Parents of final stage: List()
17:38:29.051 INFO  DAGScheduler - Missing parents: List()
17:38:29.051 INFO  DAGScheduler - Submitting ResultStage 287 (MapPartitionsRDD[1441] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:29.066 INFO  MemoryStore - Block broadcast_603 stored as values in memory (estimated size 426.2 KiB, free 1917.9 MiB)
17:38:29.067 INFO  MemoryStore - Block broadcast_603_piece0 stored as bytes in memory (estimated size 153.6 KiB, free 1917.7 MiB)
17:38:29.067 INFO  BlockManagerInfo - Added broadcast_603_piece0 in memory on localhost:37953 (size: 153.6 KiB, free: 1919.6 MiB)
17:38:29.068 INFO  SparkContext - Created broadcast 603 from broadcast at DAGScheduler.scala:1580
17:38:29.068 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 287 (MapPartitionsRDD[1441] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:29.068 INFO  TaskSchedulerImpl - Adding task set 287.0 with 1 tasks resource profile 0
17:38:29.068 INFO  TaskSetManager - Starting task 0.0 in stage 287.0 (TID 374) (localhost, executor driver, partition 0, PROCESS_LOCAL, 7883 bytes) 
17:38:29.069 INFO  Executor - Running task 0.0 in stage 287.0 (TID 374)
17:38:29.101 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/tools/BQSR/HiSeq.1mb.1RG.2k_lines.alternate.bam:0+221635
17:38:29.101 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.102 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.109 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.113 INFO  Executor - Finished task 0.0 in stage 287.0 (TID 374). 650141 bytes result sent to driver
17:38:29.115 INFO  TaskSetManager - Finished task 0.0 in stage 287.0 (TID 374) in 47 ms on localhost (executor driver) (1/1)
17:38:29.115 INFO  TaskSchedulerImpl - Removed TaskSet 287.0, whose tasks have all completed, from pool 
17:38:29.115 INFO  DAGScheduler - ResultStage 287 (collect at ReadsSparkSourceUnitTest.java:163) finished in 0.064 s
17:38:29.115 INFO  DAGScheduler - Job 223 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:29.115 INFO  TaskSchedulerImpl - Killing all running tasks in stage 287: Stage finished
17:38:29.115 INFO  DAGScheduler - Job 223 finished: collect at ReadsSparkSourceUnitTest.java:163, took 0.064816 s
17:38:29.117 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.118 INFO  MemoryStore - Block broadcast_604 stored as values in memory (estimated size 208.0 B, free 1917.7 MiB)
17:38:29.120 INFO  MemoryStore - Block broadcast_604_piece0 stored as bytes in memory (estimated size 222.0 B, free 1917.7 MiB)
17:38:29.120 INFO  BlockManagerInfo - Added broadcast_604_piece0 in memory on localhost:37953 (size: 222.0 B, free: 1919.6 MiB)
17:38:29.121 INFO  SparkContext - Created broadcast 604 from broadcast at AbstractBinarySamSource.java:82
17:38:29.122 INFO  MemoryStore - Block broadcast_605 stored as values in memory (estimated size 297.9 KiB, free 1917.4 MiB)
17:38:29.127 INFO  MemoryStore - Block broadcast_605_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1917.4 MiB)
17:38:29.127 INFO  BlockManagerInfo - Added broadcast_605_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.6 MiB)
17:38:29.127 INFO  SparkContext - Created broadcast 605 from newAPIHadoopFile at PathSplitSource.java:96
17:38:29.146 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.146 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.148 INFO  FileInputFormat - Total input files to process : 1
17:38:29.150 INFO  SparkContext - Starting job: count at ReadsSparkSourceUnitTest.java:265
17:38:29.151 INFO  DAGScheduler - Got job 224 (count at ReadsSparkSourceUnitTest.java:265) with 1 output partitions
17:38:29.151 INFO  DAGScheduler - Final stage: ResultStage 288 (count at ReadsSparkSourceUnitTest.java:265)
17:38:29.151 INFO  DAGScheduler - Parents of final stage: List()
17:38:29.151 INFO  DAGScheduler - Missing parents: List()
17:38:29.151 INFO  DAGScheduler - Submitting ResultStage 288 (MapPartitionsRDD[1448] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:29.166 INFO  MemoryStore - Block broadcast_606 stored as values in memory (estimated size 426.2 KiB, free 1917.0 MiB)
17:38:29.170 INFO  MemoryStore - Block broadcast_606_piece0 stored as bytes in memory (estimated size 153.7 KiB, free 1916.8 MiB)
17:38:29.170 INFO  BlockManagerInfo - Added broadcast_606_piece0 in memory on localhost:37953 (size: 153.7 KiB, free: 1919.4 MiB)
17:38:29.170 INFO  SparkContext - Created broadcast 606 from broadcast at DAGScheduler.scala:1580
17:38:29.170 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 288 (MapPartitionsRDD[1448] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:29.170 INFO  TaskSchedulerImpl - Adding task set 288.0 with 1 tasks resource profile 0
17:38:29.171 INFO  BlockManagerInfo - Removed broadcast_603_piece0 on localhost:37953 in memory (size: 153.6 KiB, free: 1919.6 MiB)
17:38:29.171 INFO  TaskSetManager - Starting task 0.0 in stage 288.0 (TID 375) (localhost, executor driver, partition 0, PROCESS_LOCAL, 7838 bytes) 
17:38:29.171 INFO  BlockManagerInfo - Removed broadcast_601_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.6 MiB)
17:38:29.171 INFO  Executor - Running task 0.0 in stage 288.0 (TID 375)
17:38:29.171 INFO  BlockManagerInfo - Removed broadcast_599_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.7 MiB)
17:38:29.172 INFO  BlockManagerInfo - Removed broadcast_596_piece0 on localhost:37953 in memory (size: 50.3 KiB, free: 1919.7 MiB)
17:38:29.172 INFO  BlockManagerInfo - Removed broadcast_597_piece0 on localhost:37953 in memory (size: 50.3 KiB, free: 1919.8 MiB)
17:38:29.173 INFO  BlockManagerInfo - Removed broadcast_602_piece0 on localhost:37953 in memory (size: 50.3 KiB, free: 1919.8 MiB)
17:38:29.173 INFO  BlockManagerInfo - Removed broadcast_600_piece0 on localhost:37953 in memory (size: 206.0 B, free: 1919.8 MiB)
17:38:29.173 INFO  BlockManagerInfo - Removed broadcast_598_piece0 on localhost:37953 in memory (size: 187.0 B, free: 1919.8 MiB)
17:38:29.202 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/NA12878.chr17_69k_70k.dictFix.bam:0+57538
17:38:29.203 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.204 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.205 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.207 INFO  Executor - Finished task 0.0 in stage 288.0 (TID 375). 989 bytes result sent to driver
17:38:29.208 INFO  TaskSetManager - Finished task 0.0 in stage 288.0 (TID 375) in 37 ms on localhost (executor driver) (1/1)
17:38:29.208 INFO  TaskSchedulerImpl - Removed TaskSet 288.0, whose tasks have all completed, from pool 
17:38:29.208 INFO  DAGScheduler - ResultStage 288 (count at ReadsSparkSourceUnitTest.java:265) finished in 0.057 s
17:38:29.208 INFO  DAGScheduler - Job 224 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:29.208 INFO  TaskSchedulerImpl - Killing all running tasks in stage 288: Stage finished
17:38:29.208 INFO  DAGScheduler - Job 224 finished: count at ReadsSparkSourceUnitTest.java:265, took 0.057479 s
17:38:29.210 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.210 INFO  MemoryStore - Block broadcast_607 stored as values in memory (estimated size 160.0 B, free 1919.1 MiB)
17:38:29.211 INFO  MemoryStore - Block broadcast_607_piece0 stored as bytes in memory (estimated size 212.0 B, free 1919.1 MiB)
17:38:29.211 INFO  BlockManagerInfo - Added broadcast_607_piece0 in memory on localhost:37953 (size: 212.0 B, free: 1919.8 MiB)
17:38:29.211 INFO  SparkContext - Created broadcast 607 from broadcast at AbstractBinarySamSource.java:82
17:38:29.212 INFO  MemoryStore - Block broadcast_608 stored as values in memory (estimated size 298.0 KiB, free 1918.8 MiB)
17:38:29.218 INFO  MemoryStore - Block broadcast_608_piece0 stored as bytes in memory (estimated size 50.3 KiB, free 1918.8 MiB)
17:38:29.218 INFO  BlockManagerInfo - Added broadcast_608_piece0 in memory on localhost:37953 (size: 50.3 KiB, free: 1919.8 MiB)
17:38:29.218 INFO  SparkContext - Created broadcast 608 from newAPIHadoopFile at PathSplitSource.java:96
17:38:29.237 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.237 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.238 INFO  FileInputFormat - Total input files to process : 1
17:38:29.240 INFO  SparkContext - Starting job: count at ReadsSparkSourceUnitTest.java:286
17:38:29.241 INFO  DAGScheduler - Got job 225 (count at ReadsSparkSourceUnitTest.java:286) with 1 output partitions
17:38:29.241 INFO  DAGScheduler - Final stage: ResultStage 289 (count at ReadsSparkSourceUnitTest.java:286)
17:38:29.241 INFO  DAGScheduler - Parents of final stage: List()
17:38:29.241 INFO  DAGScheduler - Missing parents: List()
17:38:29.241 INFO  DAGScheduler - Submitting ResultStage 289 (MapPartitionsRDD[1455] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:29.256 INFO  MemoryStore - Block broadcast_609 stored as values in memory (estimated size 426.2 KiB, free 1918.3 MiB)
17:38:29.257 INFO  MemoryStore - Block broadcast_609_piece0 stored as bytes in memory (estimated size 153.7 KiB, free 1918.2 MiB)
17:38:29.257 INFO  BlockManagerInfo - Added broadcast_609_piece0 in memory on localhost:37953 (size: 153.7 KiB, free: 1919.6 MiB)
17:38:29.257 INFO  SparkContext - Created broadcast 609 from broadcast at DAGScheduler.scala:1580
17:38:29.258 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 289 (MapPartitionsRDD[1455] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:29.258 INFO  TaskSchedulerImpl - Adding task set 289.0 with 1 tasks resource profile 0
17:38:29.258 INFO  TaskSetManager - Starting task 0.0 in stage 289.0 (TID 376) (localhost, executor driver, partition 0, PROCESS_LOCAL, 7901 bytes) 
17:38:29.258 INFO  Executor - Running task 0.0 in stage 289.0 (TID 376)
17:38:29.289 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/engine/CEUTrio.HiSeq.WGS.b37.NA12878.snippet_with_unmapped.bam:0+2184
17:38:29.290 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.291 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.292 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.293 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.294 INFO  Executor - Finished task 0.0 in stage 289.0 (TID 376). 989 bytes result sent to driver
17:38:29.294 INFO  TaskSetManager - Finished task 0.0 in stage 289.0 (TID 376) in 36 ms on localhost (executor driver) (1/1)
17:38:29.294 INFO  TaskSchedulerImpl - Removed TaskSet 289.0, whose tasks have all completed, from pool 
17:38:29.294 INFO  DAGScheduler - ResultStage 289 (count at ReadsSparkSourceUnitTest.java:286) finished in 0.053 s
17:38:29.294 INFO  DAGScheduler - Job 225 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:29.294 INFO  TaskSchedulerImpl - Killing all running tasks in stage 289: Stage finished
17:38:29.294 INFO  DAGScheduler - Job 225 finished: count at ReadsSparkSourceUnitTest.java:286, took 0.053905 s
17:38:29.296 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.297 INFO  MemoryStore - Block broadcast_610 stored as values in memory (estimated size 298.0 KiB, free 1917.9 MiB)
17:38:29.303 INFO  MemoryStore - Block broadcast_610_piece0 stored as bytes in memory (estimated size 50.3 KiB, free 1917.8 MiB)
17:38:29.303 INFO  BlockManagerInfo - Added broadcast_610_piece0 in memory on localhost:37953 (size: 50.3 KiB, free: 1919.6 MiB)
17:38:29.303 INFO  SparkContext - Created broadcast 610 from newAPIHadoopFile at PathSplitSource.java:96
17:38:29.322 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:29.324 INFO  MemoryStore - Block broadcast_611 stored as values in memory (estimated size 298.2 KiB, free 1917.6 MiB)
17:38:29.329 INFO  MemoryStore - Block broadcast_611_piece0 stored as bytes in memory (estimated size 50.3 KiB, free 1917.5 MiB)
17:38:29.330 INFO  BlockManagerInfo - Added broadcast_611_piece0 in memory on localhost:37953 (size: 50.3 KiB, free: 1919.5 MiB)
17:38:29.330 INFO  SparkContext - Created broadcast 611 from newAPIHadoopFile at PathSplitSource.java:96
17:38:29.349 INFO  FileInputFormat - Total input files to process : 1
17:38:29.349 INFO  FileInputFormat - Total input files to process : 1
17:38:29.358 INFO  MiniDFSCluster - starting cluster: numNameNodes=1, numDataNodes=1
17:38:29.358 INFO  NameNode - Formatting using clusterid: testClusterID
17:38:29.358 INFO  FSEditLog - Edit logging is async:true
17:38:29.365 INFO  FSNamesystem - KeyProvider: null
17:38:29.365 INFO  FSNamesystem - fsLock is fair: true
17:38:29.365 INFO  FSNamesystem - Detailed lock hold time metrics enabled: false
17:38:29.365 INFO  FSNamesystem - fsOwner                = runner (auth:SIMPLE)
17:38:29.365 INFO  FSNamesystem - supergroup             = supergroup
17:38:29.365 INFO  FSNamesystem - isPermissionEnabled    = true
17:38:29.365 INFO  FSNamesystem - isStoragePolicyEnabled = true
17:38:29.365 INFO  FSNamesystem - HA Enabled: false
17:38:29.365 INFO  Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
17:38:29.365 INFO  DatanodeManager - dfs.block.invalidate.limit : configured=1000, counted=60, effected=1000
17:38:29.366 INFO  DatanodeManager - dfs.namenode.datanode.registration.ip-hostname-check=true
17:38:29.366 INFO  BlockManager - dfs.namenode.startup.delay.block.deletion.sec is set to 000:00:00:00.000
17:38:29.366 INFO  BlockManager - The block deletion will start around 2025 Oct 27 17:38:29
17:38:29.366 INFO  GSet - Computing capacity for map BlocksMap
17:38:29.366 INFO  GSet - VM type       = 64-bit
17:38:29.366 INFO  GSet - 2.0% max memory 3.4 GB = 70 MB
17:38:29.366 INFO  GSet - capacity      = 2^23 = 8388608 entries
17:38:29.369 INFO  BlockManagerInfo - Removed broadcast_605_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.6 MiB)
17:38:29.369 INFO  BlockManager - Storage policy satisfier is disabled
17:38:29.369 INFO  BlockManager - dfs.block.access.token.enable = false
17:38:29.369 INFO  BlockManagerSafeMode - dfs.namenode.safemode.threshold-pct = 0.999
17:38:29.369 INFO  BlockManagerSafeMode - dfs.namenode.safemode.min.datanodes = 0
17:38:29.369 INFO  BlockManagerSafeMode - dfs.namenode.safemode.extension = 0
17:38:29.369 INFO  BlockManager - defaultReplication         = 1
17:38:29.369 INFO  BlockManager - maxReplication             = 512
17:38:29.369 INFO  BlockManager - minReplication             = 1
17:38:29.369 INFO  BlockManager - maxReplicationStreams      = 2
17:38:29.369 INFO  BlockManager - redundancyRecheckInterval  = 3000ms
17:38:29.369 INFO  BlockManager - encryptDataTransfer        = false
17:38:29.369 INFO  BlockManager - maxNumBlocksToLog          = 1000
17:38:29.369 INFO  BlockManagerInfo - Removed broadcast_610_piece0 on localhost:37953 in memory (size: 50.3 KiB, free: 1919.6 MiB)
17:38:29.369 INFO  GSet - Computing capacity for map INodeMap
17:38:29.369 INFO  GSet - VM type       = 64-bit
17:38:29.369 INFO  GSet - 1.0% max memory 3.4 GB = 35 MB
17:38:29.369 INFO  GSet - capacity      = 2^22 = 4194304 entries
17:38:29.370 INFO  BlockManagerInfo - Removed broadcast_606_piece0 on localhost:37953 in memory (size: 153.7 KiB, free: 1919.8 MiB)
17:38:29.370 INFO  FSDirectory - ACLs enabled? true
17:38:29.370 INFO  FSDirectory - POSIX ACL inheritance enabled? true
17:38:29.370 INFO  FSDirectory - XAttrs enabled? true
17:38:29.370 INFO  NameNode - Caching file names occurring more than 10 times
17:38:29.370 INFO  SnapshotManager - Loaded config captureOpenFiles: false, skipCaptureAccessTimeOnlyChange: false, snapshotDiffAllowSnapRootDescendant: true, maxSnapshotLimit: 65536
17:38:29.370 INFO  SnapshotManager - SkipList is disabled
17:38:29.370 INFO  GSet - Computing capacity for map cachedBlocks
17:38:29.370 INFO  GSet - VM type       = 64-bit
17:38:29.370 INFO  GSet - 0.25% max memory 3.4 GB = 8.8 MB
17:38:29.370 INFO  GSet - capacity      = 2^20 = 1048576 entries
17:38:29.370 INFO  TopMetrics - NNTop conf: dfs.namenode.top.window.num.buckets = 10
17:38:29.370 INFO  TopMetrics - NNTop conf: dfs.namenode.top.num.users = 10
17:38:29.370 INFO  TopMetrics - NNTop conf: dfs.namenode.top.windows.minutes = 1,5,25
17:38:29.370 INFO  FSNamesystem - Retry cache on namenode is enabled
17:38:29.370 INFO  FSNamesystem - Retry cache will use 0.03 of total heap and retry cache entry expiry time is 600000 millis
17:38:29.370 INFO  GSet - Computing capacity for map NameNodeRetryCache
17:38:29.370 INFO  GSet - VM type       = 64-bit
17:38:29.370 INFO  GSet - 0.029999999329447746% max memory 3.4 GB = 1.0 MB
17:38:29.370 INFO  GSet - capacity      = 2^17 = 131072 entries
17:38:29.371 INFO  BlockManagerInfo - Removed broadcast_608_piece0 on localhost:37953 in memory (size: 50.3 KiB, free: 1919.8 MiB)
17:38:29.371 INFO  FSImage - Allocated new BlockPoolId: BP-829943571-10.1.0.252-1761586709371
17:38:29.371 INFO  BlockManagerInfo - Removed broadcast_609_piece0 on localhost:37953 in memory (size: 153.7 KiB, free: 1920.0 MiB)
17:38:29.371 INFO  BlockManagerInfo - Removed broadcast_611_piece0 on localhost:37953 in memory (size: 50.3 KiB, free: 1920.0 MiB)
17:38:29.372 INFO  BlockManagerInfo - Removed broadcast_607_piece0 on localhost:37953 in memory (size: 212.0 B, free: 1920.0 MiB)
17:38:29.372 INFO  BlockManagerInfo - Removed broadcast_604_piece0 on localhost:37953 in memory (size: 222.0 B, free: 1920.0 MiB)
17:38:29.380 INFO  Storage - Storage directory /tmp/minicluster_storage18063395967434311937/name-0-1 has been successfully formatted.
17:38:29.388 INFO  Storage - Storage directory /tmp/minicluster_storage18063395967434311937/name-0-2 has been successfully formatted.
17:38:29.396 INFO  FSImageFormatProtobuf - Saving image file /tmp/minicluster_storage18063395967434311937/name-0-2/current/fsimage.ckpt_0000000000000000000 using no compression
17:38:29.396 INFO  FSImageFormatProtobuf - Saving image file /tmp/minicluster_storage18063395967434311937/name-0-1/current/fsimage.ckpt_0000000000000000000 using no compression
17:38:29.399 INFO  FSImageFormatProtobuf - Image file /tmp/minicluster_storage18063395967434311937/name-0-2/current/fsimage.ckpt_0000000000000000000 of size 419 bytes saved in 0 seconds .
17:38:29.399 INFO  FSImageFormatProtobuf - Image file /tmp/minicluster_storage18063395967434311937/name-0-1/current/fsimage.ckpt_0000000000000000000 of size 419 bytes saved in 0 seconds .
17:38:29.403 INFO  NNStorageRetentionManager - Going to retain 1 images with txid >= 0
17:38:29.406 INFO  FSNamesystem - Stopping services started for active state
17:38:29.406 INFO  FSNamesystem - Stopping services started for standby state
17:38:29.406 INFO  NameNode - createNameNode []
17:38:29.407 WARN  MetricsConfig - Cannot locate configuration: tried hadoop-metrics2-namenode.properties,hadoop-metrics2.properties
17:38:29.408 INFO  MetricsSystemImpl - Scheduled Metric snapshot period at 10 second(s).
17:38:29.408 INFO  MetricsSystemImpl - NameNode metrics system started
17:38:29.408 INFO  NameNodeUtils - fs.defaultFS is hdfs://127.0.0.1:0
17:38:29.417 INFO  JvmPauseMonitor - Starting JVM pause monitor
17:38:29.418 INFO  DFSUtil - Filter initializers set : org.apache.hadoop.http.lib.StaticUserWebFilter,org.apache.hadoop.hdfs.web.AuthFilterInitializer
17:38:29.418 INFO  DFSUtil - Starting Web-server for hdfs at: http://localhost:0
17:38:29.418 WARN  AuthenticationFilter - Unable to initialize FileSignerSecretProvider, falling back to use random secrets. Reason: Could not read signature secret file: /home/runner/hadoop-http-auth-signature-secret
17:38:29.419 WARN  HttpRequestLog - Jetty request log can only be enabled using Log4j
17:38:29.419 INFO  HttpServer2 - Added global filter 'safety' (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter)
17:38:29.420 INFO  HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context hdfs
17:38:29.420 INFO  HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context static
17:38:29.420 INFO  HttpServer2 - Added filter AuthFilter (class=org.apache.hadoop.hdfs.web.AuthFilter) to context hdfs
17:38:29.420 INFO  HttpServer2 - Added filter AuthFilter (class=org.apache.hadoop.hdfs.web.AuthFilter) to context static
17:38:29.421 INFO  HttpServer2 - addJerseyResourcePackage: packageName=org.apache.hadoop.hdfs.server.namenode.web.resources;org.apache.hadoop.hdfs.web.resources, pathSpec=/webhdfs/v1/*
17:38:29.421 INFO  HttpServer2 - Jetty bound to port 39051
17:38:29.421 INFO  Server - jetty-9.4.56.v20240826; built: 2024-08-26T17:15:05.868Z; git: ec6782ff5ead824dabdcf47fa98f90a4aedff401; jvm 17.0.6+10
17:38:29.422 INFO  session - DefaultSessionIdManager workerName=node0
17:38:29.422 INFO  session - No SessionScavenger set, using defaults
17:38:29.422 INFO  session - node0 Scavenging every 660000ms
17:38:29.422 WARN  AuthenticationFilter - Unable to initialize FileSignerSecretProvider, falling back to use random secrets. Reason: Could not read signature secret file: /home/runner/hadoop-http-auth-signature-secret
17:38:29.423 INFO  ContextHandler - Started o.e.j.s.ServletContextHandler@2aa023bc{static,/static,jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/static,AVAILABLE}
17:38:29.491 INFO  ContextHandler - Started o.e.j.w.WebAppContext@444454ac{hdfs,/,file:///tmp/jetty-localhost-39051-hadoop-hdfs-3_3_6-tests_jar-_-any-7132641173539545930/webapp/,AVAILABLE}{jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/hdfs}
17:38:29.492 INFO  AbstractConnector - Started ServerConnector@7b51743b{HTTP/1.1, (http/1.1)}{localhost:39051}
17:38:29.492 INFO  Server - Started @71604ms
17:38:29.492 INFO  FSEditLog - Edit logging is async:true
17:38:29.500 INFO  FSNamesystem - KeyProvider: null
17:38:29.500 INFO  FSNamesystem - fsLock is fair: true
17:38:29.500 INFO  FSNamesystem - Detailed lock hold time metrics enabled: false
17:38:29.500 INFO  FSNamesystem - fsOwner                = runner (auth:SIMPLE)
17:38:29.500 INFO  FSNamesystem - supergroup             = supergroup
17:38:29.500 INFO  FSNamesystem - isPermissionEnabled    = true
17:38:29.500 INFO  FSNamesystem - isStoragePolicyEnabled = true
17:38:29.500 INFO  FSNamesystem - HA Enabled: false
17:38:29.501 INFO  Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
17:38:29.501 INFO  DatanodeManager - dfs.block.invalidate.limit : configured=1000, counted=60, effected=1000
17:38:29.501 INFO  DatanodeManager - dfs.namenode.datanode.registration.ip-hostname-check=true
17:38:29.501 INFO  BlockManager - dfs.namenode.startup.delay.block.deletion.sec is set to 000:00:00:00.000
17:38:29.501 INFO  BlockManager - The block deletion will start around 2025 Oct 27 17:38:29
17:38:29.501 INFO  GSet - Computing capacity for map BlocksMap
17:38:29.501 INFO  GSet - VM type       = 64-bit
17:38:29.501 INFO  GSet - 2.0% max memory 3.4 GB = 70 MB
17:38:29.501 INFO  GSet - capacity      = 2^23 = 8388608 entries
17:38:29.505 INFO  BlockManager - Storage policy satisfier is disabled
17:38:29.505 INFO  BlockManager - dfs.block.access.token.enable = false
17:38:29.505 INFO  BlockManagerSafeMode - dfs.namenode.safemode.threshold-pct = 0.999
17:38:29.505 INFO  BlockManagerSafeMode - dfs.namenode.safemode.min.datanodes = 0
17:38:29.505 INFO  BlockManagerSafeMode - dfs.namenode.safemode.extension = 0
17:38:29.505 INFO  BlockManager - defaultReplication         = 1
17:38:29.505 INFO  BlockManager - maxReplication             = 512
17:38:29.505 INFO  BlockManager - minReplication             = 1
17:38:29.505 INFO  BlockManager - maxReplicationStreams      = 2
17:38:29.505 INFO  BlockManager - redundancyRecheckInterval  = 3000ms
17:38:29.505 INFO  BlockManager - encryptDataTransfer        = false
17:38:29.505 INFO  BlockManager - maxNumBlocksToLog          = 1000
17:38:29.505 INFO  GSet - Computing capacity for map INodeMap
17:38:29.505 INFO  GSet - VM type       = 64-bit
17:38:29.505 INFO  GSet - 1.0% max memory 3.4 GB = 35 MB
17:38:29.505 INFO  GSet - capacity      = 2^22 = 4194304 entries
17:38:29.508 INFO  FSDirectory - ACLs enabled? true
17:38:29.508 INFO  FSDirectory - POSIX ACL inheritance enabled? true
17:38:29.508 INFO  FSDirectory - XAttrs enabled? true
17:38:29.508 INFO  NameNode - Caching file names occurring more than 10 times
17:38:29.508 INFO  SnapshotManager - Loaded config captureOpenFiles: false, skipCaptureAccessTimeOnlyChange: false, snapshotDiffAllowSnapRootDescendant: true, maxSnapshotLimit: 65536
17:38:29.508 INFO  SnapshotManager - SkipList is disabled
17:38:29.508 INFO  GSet - Computing capacity for map cachedBlocks
17:38:29.508 INFO  GSet - VM type       = 64-bit
17:38:29.508 INFO  GSet - 0.25% max memory 3.4 GB = 8.8 MB
17:38:29.508 INFO  GSet - capacity      = 2^20 = 1048576 entries
17:38:29.508 INFO  TopMetrics - NNTop conf: dfs.namenode.top.window.num.buckets = 10
17:38:29.508 INFO  TopMetrics - NNTop conf: dfs.namenode.top.num.users = 10
17:38:29.508 INFO  TopMetrics - NNTop conf: dfs.namenode.top.windows.minutes = 1,5,25
17:38:29.508 INFO  FSNamesystem - Retry cache on namenode is enabled
17:38:29.508 INFO  FSNamesystem - Retry cache will use 0.03 of total heap and retry cache entry expiry time is 600000 millis
17:38:29.508 INFO  GSet - Computing capacity for map NameNodeRetryCache
17:38:29.508 INFO  GSet - VM type       = 64-bit
17:38:29.508 INFO  GSet - 0.029999999329447746% max memory 3.4 GB = 1.0 MB
17:38:29.508 INFO  GSet - capacity      = 2^17 = 131072 entries
17:38:29.513 INFO  Storage - Lock on /tmp/minicluster_storage18063395967434311937/name-0-1/in_use.lock acquired by nodename 2975@runnervmrcw8b
17:38:29.516 INFO  Storage - Lock on /tmp/minicluster_storage18063395967434311937/name-0-2/in_use.lock acquired by nodename 2975@runnervmrcw8b
17:38:29.517 INFO  FileJournalManager - Recovering unfinalized segments in /tmp/minicluster_storage18063395967434311937/name-0-1/current
17:38:29.517 INFO  FileJournalManager - Recovering unfinalized segments in /tmp/minicluster_storage18063395967434311937/name-0-2/current
17:38:29.517 INFO  FSImage - No edit log streams selected.
17:38:29.517 INFO  FSImage - Planning to load image: FSImageFile(file=/tmp/minicluster_storage18063395967434311937/name-0-1/current/fsimage_0000000000000000000, cpktTxId=0000000000000000000)
17:38:29.517 INFO  FSImageFormatPBINode - Loading 1 INodes.
17:38:29.518 INFO  FSImageFormatPBINode - Successfully loaded 1 inodes
17:38:29.518 INFO  FSImageFormatPBINode - Completed update blocks map and name cache, total waiting duration 0ms.
17:38:29.518 INFO  FSImageFormatProtobuf - Loaded FSImage in 0 seconds.
17:38:29.518 INFO  FSImage - Loaded image for txid 0 from /tmp/minicluster_storage18063395967434311937/name-0-1/current/fsimage_0000000000000000000
17:38:29.518 INFO  FSNamesystem - Need to save fs image? false (staleImage=false, haEnabled=false, isRollingUpgrade=false)
17:38:29.518 INFO  FSEditLog - Starting log segment at 1
17:38:29.526 INFO  NameCache - initialized with 0 entries 0 lookups
17:38:29.526 INFO  FSNamesystem - Finished loading FSImage in 17 msecs
17:38:29.526 INFO  NameNode - RPC server is binding to localhost:0
17:38:29.526 INFO  NameNode - Enable NameNode state context:false
17:38:29.526 INFO  CallQueueManager - Using callQueue: class java.util.concurrent.LinkedBlockingQueue, queueCapacity: 1000, scheduler: class org.apache.hadoop.ipc.DefaultRpcScheduler, ipcBackoff: false.
17:38:29.526 INFO  Server - Listener at localhost:44873
17:38:29.527 INFO  Server - Starting Socket Reader #1 for port 0
17:38:29.528 INFO  NameNode - Clients are to use localhost:44873 to access this namenode/service.
17:38:29.528 INFO  FSNamesystem - Registered FSNamesystemState, ReplicatedBlocksState and ECBlockGroupsState MBeans.
17:38:29.535 INFO  LeaseManager - Number of blocks under construction: 0
17:38:29.536 INFO  DatanodeAdminDefaultMonitor - Initialized the Default Decommission and Maintenance monitor
17:38:29.536 INFO  BlockManager - Start MarkedDeleteBlockScrubber thread
17:38:29.536 INFO  BlockManager - initializing replication queues
17:38:29.536 INFO  StateChange - STATE* Leaving safe mode after 0 secs
17:38:29.536 INFO  StateChange - STATE* Network topology has 0 racks and 0 datanodes
17:38:29.536 INFO  StateChange - STATE* UnderReplicatedBlocks has 0 blocks
17:38:29.538 INFO  Server - IPC Server Responder: starting
17:38:29.538 INFO  Server - IPC Server listener on 0: starting
17:38:29.540 INFO  BlockManager - Total number of blocks            = 0
17:38:29.540 INFO  BlockManager - Number of invalid blocks          = 0
17:38:29.540 INFO  BlockManager - Number of under-replicated blocks = 0
17:38:29.540 INFO  BlockManager - Number of  over-replicated blocks = 0
17:38:29.540 INFO  BlockManager - Number of blocks being written    = 0
17:38:29.540 INFO  StateChange - STATE* Replication Queue initialization scan for invalid, over- and under-replicated blocks completed in 3 msec
17:38:29.541 INFO  NameNode - NameNode RPC up at: localhost/127.0.0.1:44873
17:38:29.541 WARN  MetricsLoggerTask - Metrics logging will not be async since the logger is not log4j
17:38:29.541 INFO  FSNamesystem - Starting services required for active state
17:38:29.541 INFO  FSDirectory - Initializing quota with 12 thread(s)
17:38:29.541 INFO  FSDirectory - Quota initialization completed in 0 milliseconds
name space=1
storage space=0
storage types=RAM_DISK=0, SSD=0, DISK=0, ARCHIVE=0, PROVIDED=0
17:38:29.542 INFO  CacheReplicationMonitor - Starting CacheReplicationMonitor with interval 30000 milliseconds
17:38:29.542 INFO  MiniDFSCluster - Starting DataNode 0 with dfs.datanode.data.dir: [DISK]file:/tmp/minicluster_storage18063395967434311937/data/data1,[DISK]file:/tmp/minicluster_storage18063395967434311937/data/data2
17:38:29.543 INFO  ThrottledAsyncChecker - Scheduling a check for [DISK]file:/tmp/minicluster_storage18063395967434311937/data/data1
17:38:29.543 INFO  ThrottledAsyncChecker - Scheduling a check for [DISK]file:/tmp/minicluster_storage18063395967434311937/data/data2
17:38:29.549 INFO  MetricsSystemImpl - DataNode metrics system started (again)
17:38:29.549 INFO  Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
17:38:29.549 INFO  BlockScanner - Initialized block scanner with targetBytesPerSec 1048576
17:38:29.549 INFO  DataNode - Configured hostname is 127.0.0.1
17:38:29.549 INFO  Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
17:38:29.549 INFO  DataNode - Starting DataNode with maxLockedMemory = 0
17:38:29.549 INFO  DataNode - Opened streaming server at /127.0.0.1:44265
17:38:29.549 INFO  DataNode - Balancing bandwidth is 104857600 bytes/s
17:38:29.549 INFO  DataNode - Number threads for balancing is 100
17:38:29.551 WARN  AuthenticationFilter - Unable to initialize FileSignerSecretProvider, falling back to use random secrets. Reason: Could not read signature secret file: /home/runner/hadoop-http-auth-signature-secret
17:38:29.551 WARN  HttpRequestLog - Jetty request log can only be enabled using Log4j
17:38:29.552 INFO  HttpServer2 - Added global filter 'safety' (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter)
17:38:29.552 INFO  HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context datanode
17:38:29.552 INFO  HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context static
17:38:29.553 INFO  HttpServer2 - Jetty bound to port 42873
17:38:29.553 INFO  Server - jetty-9.4.56.v20240826; built: 2024-08-26T17:15:05.868Z; git: ec6782ff5ead824dabdcf47fa98f90a4aedff401; jvm 17.0.6+10
17:38:29.553 INFO  session - DefaultSessionIdManager workerName=node0
17:38:29.553 INFO  session - No SessionScavenger set, using defaults
17:38:29.553 INFO  session - node0 Scavenging every 600000ms
17:38:29.554 INFO  ContextHandler - Started o.e.j.s.ServletContextHandler@25615ffd{static,/static,jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/static,AVAILABLE}
17:38:29.629 INFO  ContextHandler - Started o.e.j.w.WebAppContext@64ee819{datanode,/,file:///tmp/jetty-localhost-42873-hadoop-hdfs-3_3_6-tests_jar-_-any-9348572429421616847/webapp/,AVAILABLE}{jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/datanode}
17:38:29.630 INFO  AbstractConnector - Started ServerConnector@10f9f71f{HTTP/1.1, (http/1.1)}{localhost:42873}
17:38:29.630 INFO  Server - Started @71741ms
17:38:29.630 WARN  DatanodeHttpServer - Got null for restCsrfPreventionFilter - will not do any filtering.
17:38:29.631 INFO  DatanodeHttpServer - Listening HTTP traffic on /127.0.0.1:33641
17:38:29.631 INFO  DataNode - dnUserName = runner
17:38:29.631 INFO  DataNode - supergroup = supergroup
17:38:29.632 INFO  JvmPauseMonitor - Starting JVM pause monitor
17:38:29.632 INFO  CallQueueManager - Using callQueue: class java.util.concurrent.LinkedBlockingQueue, queueCapacity: 1000, scheduler: class org.apache.hadoop.ipc.DefaultRpcScheduler, ipcBackoff: false.
17:38:29.632 INFO  Server - Listener at localhost:43615
17:38:29.632 INFO  Server - Starting Socket Reader #1 for port 0
17:38:29.634 INFO  DataNode - Opened IPC server at /127.0.0.1:43615
17:38:29.643 INFO  DataNode - Refresh request received for nameservices: null
17:38:29.643 INFO  DataNode - Starting BPOfferServices for nameservices: <default>
17:38:29.644 WARN  MetricsLoggerTask - Metrics logging will not be async since the logger is not log4j
17:38:29.644 INFO  DataNode - Block pool <registering> (Datanode Uuid unassigned) service to localhost/127.0.0.1:44873 starting to offer service
17:38:29.645 INFO  Server - IPC Server Responder: starting
17:38:29.646 INFO  Server - IPC Server listener on 0: starting
17:38:29.648 INFO  DataNode - Acknowledging ACTIVE Namenode during handshakeBlock pool <registering> (Datanode Uuid unassigned) service to localhost/127.0.0.1:44873
17:38:29.648 INFO  Storage - Using 2 threads to upgrade data directories (dfs.datanode.parallel.volumes.load.threads.num=2, dataDirs=2)
17:38:29.650 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=datanodeReport	src=null	dst=null	perm=null	proto=rpc
17:38:29.651 INFO  MiniDFSCluster - dnInfo.length != numDataNodes
17:38:29.651 INFO  MiniDFSCluster - Waiting for cluster to become active
17:38:29.652 INFO  Storage - Lock on /tmp/minicluster_storage18063395967434311937/data/data1/in_use.lock acquired by nodename 2975@runnervmrcw8b
17:38:29.652 INFO  Storage - Storage directory with location [DISK]file:/tmp/minicluster_storage18063395967434311937/data/data1 is not formatted for namespace 1369043031. Formatting...
17:38:29.653 INFO  Storage - Generated new storageID DS-aa63a8fd-4862-4366-bb39-9285b8093ae4 for directory /tmp/minicluster_storage18063395967434311937/data/data1 
17:38:29.663 INFO  Storage - Lock on /tmp/minicluster_storage18063395967434311937/data/data2/in_use.lock acquired by nodename 2975@runnervmrcw8b
17:38:29.663 INFO  Storage - Storage directory with location [DISK]file:/tmp/minicluster_storage18063395967434311937/data/data2 is not formatted for namespace 1369043031. Formatting...
17:38:29.663 INFO  Storage - Generated new storageID DS-721e23b4-dbc2-44ce-be69-fd77c1e17fc7 for directory /tmp/minicluster_storage18063395967434311937/data/data2 
17:38:29.679 INFO  Storage - Analyzing storage directories for bpid BP-829943571-10.1.0.252-1761586709371
17:38:29.679 INFO  Storage - Locking is disabled for /tmp/minicluster_storage18063395967434311937/data/data1/current/BP-829943571-10.1.0.252-1761586709371
17:38:29.679 INFO  Storage - Block pool storage directory for location [DISK]file:/tmp/minicluster_storage18063395967434311937/data/data1 and block pool id BP-829943571-10.1.0.252-1761586709371 is not formatted. Formatting ...
17:38:29.679 INFO  Storage - Formatting block pool BP-829943571-10.1.0.252-1761586709371 directory /tmp/minicluster_storage18063395967434311937/data/data1/current/BP-829943571-10.1.0.252-1761586709371/current
17:38:29.697 INFO  Storage - Analyzing storage directories for bpid BP-829943571-10.1.0.252-1761586709371
17:38:29.697 INFO  Storage - Locking is disabled for /tmp/minicluster_storage18063395967434311937/data/data2/current/BP-829943571-10.1.0.252-1761586709371
17:38:29.697 INFO  Storage - Block pool storage directory for location [DISK]file:/tmp/minicluster_storage18063395967434311937/data/data2 and block pool id BP-829943571-10.1.0.252-1761586709371 is not formatted. Formatting ...
17:38:29.697 INFO  Storage - Formatting block pool BP-829943571-10.1.0.252-1761586709371 directory /tmp/minicluster_storage18063395967434311937/data/data2/current/BP-829943571-10.1.0.252-1761586709371/current
17:38:29.704 INFO  DataNode - Setting up storage: nsid=1369043031;bpid=BP-829943571-10.1.0.252-1761586709371;lv=-57;nsInfo=lv=-66;cid=testClusterID;nsid=1369043031;c=1761586709371;bpid=BP-829943571-10.1.0.252-1761586709371;dnuuid=null
17:38:29.710 INFO  DataNode - Generated and persisted new Datanode UUID 7eeb06e8-b77b-461a-9674-2f1b537c18e3
17:38:29.710 INFO  FsDatasetImpl - The datanode lock is a read write lock
17:38:29.711 INFO  FsDatasetImpl - Added new volume: DS-aa63a8fd-4862-4366-bb39-9285b8093ae4
17:38:29.711 INFO  FsDatasetImpl - Added volume - [DISK]file:/tmp/minicluster_storage18063395967434311937/data/data1, StorageType: DISK
17:38:29.712 INFO  FsDatasetImpl - Added new volume: DS-721e23b4-dbc2-44ce-be69-fd77c1e17fc7
17:38:29.712 INFO  FsDatasetImpl - Added volume - [DISK]file:/tmp/minicluster_storage18063395967434311937/data/data2, StorageType: DISK
17:38:29.712 INFO  MemoryMappableBlockLoader - Initializing cache loader: MemoryMappableBlockLoader.
17:38:29.712 INFO  FsDatasetImpl - Registered FSDatasetState MBean
17:38:29.713 INFO  FsDatasetImpl - Adding block pool BP-829943571-10.1.0.252-1761586709371
17:38:29.713 INFO  FsDatasetImpl - Scanning block pool BP-829943571-10.1.0.252-1761586709371 on volume /tmp/minicluster_storage18063395967434311937/data/data1...
17:38:29.713 INFO  FsDatasetImpl - Scanning block pool BP-829943571-10.1.0.252-1761586709371 on volume /tmp/minicluster_storage18063395967434311937/data/data2...
17:38:29.713 WARN  FsDatasetImpl - dfsUsed file missing in /tmp/minicluster_storage18063395967434311937/data/data1/current/BP-829943571-10.1.0.252-1761586709371/current, will proceed with Du for space computation calculation, 
17:38:29.713 WARN  FsDatasetImpl - dfsUsed file missing in /tmp/minicluster_storage18063395967434311937/data/data2/current/BP-829943571-10.1.0.252-1761586709371/current, will proceed with Du for space computation calculation, 
17:38:29.724 INFO  FsDatasetImpl - Time taken to scan block pool BP-829943571-10.1.0.252-1761586709371 on /tmp/minicluster_storage18063395967434311937/data/data1: 11ms
17:38:29.724 INFO  FsDatasetImpl - Time taken to scan block pool BP-829943571-10.1.0.252-1761586709371 on /tmp/minicluster_storage18063395967434311937/data/data2: 11ms
17:38:29.724 INFO  FsDatasetImpl - Total time to scan all replicas for block pool BP-829943571-10.1.0.252-1761586709371: 11ms
17:38:29.724 INFO  FsDatasetImpl - Adding replicas to map for block pool BP-829943571-10.1.0.252-1761586709371 on volume /tmp/minicluster_storage18063395967434311937/data/data1...
17:38:29.724 INFO  BlockPoolSlice - Replica Cache file: /tmp/minicluster_storage18063395967434311937/data/data1/current/BP-829943571-10.1.0.252-1761586709371/current/replicas doesn't exist 
17:38:29.725 INFO  FsDatasetImpl - Time to add replicas to map for block pool BP-829943571-10.1.0.252-1761586709371 on volume /tmp/minicluster_storage18063395967434311937/data/data1: 0ms
17:38:29.725 INFO  FsDatasetImpl - Adding replicas to map for block pool BP-829943571-10.1.0.252-1761586709371 on volume /tmp/minicluster_storage18063395967434311937/data/data2...
17:38:29.725 INFO  BlockPoolSlice - Replica Cache file: /tmp/minicluster_storage18063395967434311937/data/data2/current/BP-829943571-10.1.0.252-1761586709371/current/replicas doesn't exist 
17:38:29.725 INFO  FsDatasetImpl - Time to add replicas to map for block pool BP-829943571-10.1.0.252-1761586709371 on volume /tmp/minicluster_storage18063395967434311937/data/data2: 0ms
17:38:29.725 INFO  FsDatasetImpl - Total time to add all replicas to map for block pool BP-829943571-10.1.0.252-1761586709371: 1ms
17:38:29.725 INFO  ThrottledAsyncChecker - Scheduling a check for /tmp/minicluster_storage18063395967434311937/data/data1
17:38:29.725 INFO  DatasetVolumeChecker - Scheduled health check for volume /tmp/minicluster_storage18063395967434311937/data/data1
17:38:29.725 INFO  ThrottledAsyncChecker - Scheduling a check for /tmp/minicluster_storage18063395967434311937/data/data2
17:38:29.725 INFO  DatasetVolumeChecker - Scheduled health check for volume /tmp/minicluster_storage18063395967434311937/data/data2
17:38:29.726 INFO  VolumeScanner - Now scanning bpid BP-829943571-10.1.0.252-1761586709371 on volume /tmp/minicluster_storage18063395967434311937/data/data2
17:38:29.726 WARN  DirectoryScanner - dfs.datanode.directoryscan.throttle.limit.ms.per.sec set to value above 1000 ms/sec. Assuming default value of -1
17:38:29.726 INFO  VolumeScanner - Now scanning bpid BP-829943571-10.1.0.252-1761586709371 on volume /tmp/minicluster_storage18063395967434311937/data/data1
17:38:29.726 INFO  DirectoryScanner - Periodic Directory Tree Verification scan starting in 2991783ms with interval of 21600000ms and throttle limit of -1ms/s
17:38:29.726 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage18063395967434311937/data/data2, DS-721e23b4-dbc2-44ce-be69-fd77c1e17fc7): finished scanning block pool BP-829943571-10.1.0.252-1761586709371
17:38:29.726 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage18063395967434311937/data/data1, DS-aa63a8fd-4862-4366-bb39-9285b8093ae4): finished scanning block pool BP-829943571-10.1.0.252-1761586709371
17:38:29.726 INFO  DataNode - Block pool BP-829943571-10.1.0.252-1761586709371 (Datanode Uuid 7eeb06e8-b77b-461a-9674-2f1b537c18e3) service to localhost/127.0.0.1:44873 beginning handshake with NN
17:38:29.726 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage18063395967434311937/data/data1, DS-aa63a8fd-4862-4366-bb39-9285b8093ae4): no suitable block pools found to scan.  Waiting 1814400000 ms.
17:38:29.726 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage18063395967434311937/data/data2, DS-721e23b4-dbc2-44ce-be69-fd77c1e17fc7): no suitable block pools found to scan.  Waiting 1814400000 ms.
17:38:29.727 INFO  StateChange - BLOCK* registerDatanode: from DatanodeRegistration(127.0.0.1:44265, datanodeUuid=7eeb06e8-b77b-461a-9674-2f1b537c18e3, infoPort=33641, infoSecurePort=0, ipcPort=43615, storageInfo=lv=-57;cid=testClusterID;nsid=1369043031;c=1761586709371) storage 7eeb06e8-b77b-461a-9674-2f1b537c18e3
17:38:29.727 INFO  NetworkTopology - Adding a new node: /default-rack/127.0.0.1:44265
17:38:29.727 INFO  BlockReportLeaseManager - Registered DN 7eeb06e8-b77b-461a-9674-2f1b537c18e3 (127.0.0.1:44265).
17:38:29.727 INFO  DataNode - Block pool BP-829943571-10.1.0.252-1761586709371 (Datanode Uuid 7eeb06e8-b77b-461a-9674-2f1b537c18e3) service to localhost/127.0.0.1:44873 successfully registered with NN
17:38:29.727 INFO  DataNode - For namenode localhost/127.0.0.1:44873 using BLOCKREPORT_INTERVAL of 21600000msecs CACHEREPORT_INTERVAL of 10000msecs Initial delay: 0msecs; heartBeatInterval=3000
17:38:29.727 INFO  DataNode - Starting IBR Task Handler.
17:38:29.728 INFO  DatanodeDescriptor - Adding new storage ID DS-aa63a8fd-4862-4366-bb39-9285b8093ae4 for DN 127.0.0.1:44265
17:38:29.728 INFO  DatanodeDescriptor - Adding new storage ID DS-721e23b4-dbc2-44ce-be69-fd77c1e17fc7 for DN 127.0.0.1:44265
17:38:29.728 INFO  DataNode - After receiving heartbeat response, updating state of namenode localhost:44873 to active
17:38:29.728 INFO  BlockStateChange - BLOCK* processReport 0xd7ddba8f1fdd346d with lease ID 0x717081cc8dc7eab4: Processing first storage report for DS-aa63a8fd-4862-4366-bb39-9285b8093ae4 from datanode DatanodeRegistration(127.0.0.1:44265, datanodeUuid=7eeb06e8-b77b-461a-9674-2f1b537c18e3, infoPort=33641, infoSecurePort=0, ipcPort=43615, storageInfo=lv=-57;cid=testClusterID;nsid=1369043031;c=1761586709371)
17:38:29.728 INFO  BlockStateChange - BLOCK* processReport 0xd7ddba8f1fdd346d with lease ID 0x717081cc8dc7eab4: from storage DS-aa63a8fd-4862-4366-bb39-9285b8093ae4 node DatanodeRegistration(127.0.0.1:44265, datanodeUuid=7eeb06e8-b77b-461a-9674-2f1b537c18e3, infoPort=33641, infoSecurePort=0, ipcPort=43615, storageInfo=lv=-57;cid=testClusterID;nsid=1369043031;c=1761586709371), blocks: 0, hasStaleStorage: true, processing time: 1 msecs, invalidatedBlocks: 0
17:38:29.729 INFO  BlockStateChange - BLOCK* processReport 0xd7ddba8f1fdd346d with lease ID 0x717081cc8dc7eab4: Processing first storage report for DS-721e23b4-dbc2-44ce-be69-fd77c1e17fc7 from datanode DatanodeRegistration(127.0.0.1:44265, datanodeUuid=7eeb06e8-b77b-461a-9674-2f1b537c18e3, infoPort=33641, infoSecurePort=0, ipcPort=43615, storageInfo=lv=-57;cid=testClusterID;nsid=1369043031;c=1761586709371)
17:38:29.729 INFO  BlockStateChange - BLOCK* processReport 0xd7ddba8f1fdd346d with lease ID 0x717081cc8dc7eab4: from storage DS-721e23b4-dbc2-44ce-be69-fd77c1e17fc7 node DatanodeRegistration(127.0.0.1:44265, datanodeUuid=7eeb06e8-b77b-461a-9674-2f1b537c18e3, infoPort=33641, infoSecurePort=0, ipcPort=43615, storageInfo=lv=-57;cid=testClusterID;nsid=1369043031;c=1761586709371), blocks: 0, hasStaleStorage: false, processing time: 0 msecs, invalidatedBlocks: 0
17:38:29.729 INFO  DataNode - Successfully sent block report 0xd7ddba8f1fdd346d with lease ID 0x717081cc8dc7eab4 to namenode: localhost/127.0.0.1:44873,  containing 2 storage report(s), of which we sent 2. The reports had 0 total blocks and used 1 RPC(s). This took 0 msecs to generate and 1 msecs for RPC and NN processing. Got back one command: FinalizeCommand/5.
17:38:29.729 INFO  DataNode - Got finalize command for block pool BP-829943571-10.1.0.252-1761586709371
17:38:29.751 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=datanodeReport	src=null	dst=null	perm=null	proto=rpc
17:38:29.751 INFO  MiniDFSCluster - Cluster is active
17:38:29.753 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bam	dst=null	perm=null	proto=rpc
17:38:29.754 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=create	src=/user/runner/hdfs.bam	dst=null	perm=runner:supergroup:rw-r--r--	proto=rpc
17:38:29.756 INFO  StateChange - BLOCK* allocate blk_1073741825_1001, replicas=127.0.0.1:44265 for /user/runner/hdfs.bam
17:38:29.757 INFO  DataNode - Receiving BP-829943571-10.1.0.252-1761586709371:blk_1073741825_1001 src: /127.0.0.1:34254 dest: /127.0.0.1:44265
17:38:29.758 INFO  clienttrace - src: /127.0.0.1:34254, dest: /127.0.0.1:44265, bytes: 2396, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_-1485765308_1, offset: 0, srvID: 7eeb06e8-b77b-461a-9674-2f1b537c18e3, blockid: BP-829943571-10.1.0.252-1761586709371:blk_1073741825_1001, duration(ns): 552264
17:38:29.759 INFO  DataNode - PacketResponder: BP-829943571-10.1.0.252-1761586709371:blk_1073741825_1001, type=LAST_IN_PIPELINE terminating
17:38:29.759 INFO  FSNamesystem - BLOCK* blk_1073741825_1001 is COMMITTED but not COMPLETE(numNodes= 0 <  minimum = 1) in file /user/runner/hdfs.bam
17:38:30.160 INFO  StateChange - DIR* completeFile: /user/runner/hdfs.bam is closed by DFSClient_NONMAPREDUCE_-1485765308_1
17:38:30.161 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bai	dst=null	perm=null	proto=rpc
17:38:30.162 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=create	src=/user/runner/hdfs.bai	dst=null	perm=runner:supergroup:rw-r--r--	proto=rpc
17:38:30.164 INFO  StateChange - BLOCK* allocate blk_1073741826_1002, replicas=127.0.0.1:44265 for /user/runner/hdfs.bai
17:38:30.165 INFO  DataNode - Receiving BP-829943571-10.1.0.252-1761586709371:blk_1073741826_1002 src: /127.0.0.1:34268 dest: /127.0.0.1:44265
17:38:30.166 INFO  clienttrace - src: /127.0.0.1:34268, dest: /127.0.0.1:44265, bytes: 656, op: HDFS_WRITE, cliID: DFSClient_NONMAPREDUCE_-1485765308_1, offset: 0, srvID: 7eeb06e8-b77b-461a-9674-2f1b537c18e3, blockid: BP-829943571-10.1.0.252-1761586709371:blk_1073741826_1002, duration(ns): 534304
17:38:30.166 INFO  DataNode - PacketResponder: BP-829943571-10.1.0.252-1761586709371:blk_1073741826_1002, type=LAST_IN_PIPELINE terminating
17:38:30.166 INFO  StateChange - DIR* completeFile: /user/runner/hdfs.bai is closed by DFSClient_NONMAPREDUCE_-1485765308_1
17:38:30.167 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:30.169 INFO  MemoryStore - Block broadcast_612 stored as values in memory (estimated size 298.3 KiB, free 1919.7 MiB)
17:38:30.175 INFO  MemoryStore - Block broadcast_612_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1919.7 MiB)
17:38:30.175 INFO  BlockManagerInfo - Added broadcast_612_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1920.0 MiB)
17:38:30.175 INFO  SparkContext - Created broadcast 612 from newAPIHadoopFile at PathSplitSource.java:96
17:38:30.194 INFO  FileInputFormat - Total input files to process : 1
17:38:30.226 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:212
17:38:30.227 INFO  DAGScheduler - Got job 226 (collect at ReadsSparkSourceUnitTest.java:212) with 1 output partitions
17:38:30.227 INFO  DAGScheduler - Final stage: ResultStage 290 (collect at ReadsSparkSourceUnitTest.java:212)
17:38:30.227 INFO  DAGScheduler - Parents of final stage: List()
17:38:30.227 INFO  DAGScheduler - Missing parents: List()
17:38:30.227 INFO  DAGScheduler - Submitting ResultStage 290 (MapPartitionsRDD[1476] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:30.242 INFO  MemoryStore - Block broadcast_613 stored as values in memory (estimated size 426.4 KiB, free 1919.2 MiB)
17:38:30.243 INFO  MemoryStore - Block broadcast_613_piece0 stored as bytes in memory (estimated size 154.0 KiB, free 1919.1 MiB)
17:38:30.243 INFO  BlockManagerInfo - Added broadcast_613_piece0 in memory on localhost:37953 (size: 154.0 KiB, free: 1919.8 MiB)
17:38:30.243 INFO  SparkContext - Created broadcast 613 from broadcast at DAGScheduler.scala:1580
17:38:30.244 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 290 (MapPartitionsRDD[1476] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:30.244 INFO  TaskSchedulerImpl - Adding task set 290.0 with 1 tasks resource profile 0
17:38:30.244 INFO  TaskSetManager - Starting task 0.0 in stage 290.0 (TID 377) (localhost, executor driver, partition 0, PROCESS_LOCAL, 7899 bytes) 
17:38:30.245 INFO  Executor - Running task 0.0 in stage 290.0 (TID 377)
17:38:30.276 INFO  NewHadoopRDD - Input split: file:/home/runner/work/gatk/gatk/src/test/resources/org/broadinstitute/hellbender/engine/spark/datasources/ReadsSparkSource/hdfs_file_test.bam:0+2396
17:38:30.277 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:30.278 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:30.278 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:30.279 INFO  Executor - Finished task 0.0 in stage 290.0 (TID 377). 5288 bytes result sent to driver
17:38:30.280 INFO  TaskSetManager - Finished task 0.0 in stage 290.0 (TID 377) in 36 ms on localhost (executor driver) (1/1)
17:38:30.280 INFO  TaskSchedulerImpl - Removed TaskSet 290.0, whose tasks have all completed, from pool 
17:38:30.280 INFO  DAGScheduler - ResultStage 290 (collect at ReadsSparkSourceUnitTest.java:212) finished in 0.053 s
17:38:30.280 INFO  DAGScheduler - Job 226 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:30.280 INFO  TaskSchedulerImpl - Killing all running tasks in stage 290: Stage finished
17:38:30.280 INFO  DAGScheduler - Job 226 finished: collect at ReadsSparkSourceUnitTest.java:212, took 0.053567 s
17:38:30.281 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bam	dst=null	perm=null	proto=rpc
17:38:30.281 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bam	dst=null	perm=null	proto=rpc
17:38:30.282 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bam	dst=null	perm=null	proto=rpc
17:38:30.282 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.bam	dst=null	perm=null	proto=rpc
17:38:30.283 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bam.bai	dst=null	perm=null	proto=rpc
17:38:30.283 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bai	dst=null	perm=null	proto=rpc
17:38:30.284 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bai	dst=null	perm=null	proto=rpc
17:38:30.284 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.bai	dst=null	perm=null	proto=rpc
17:38:30.285 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:30.286 WARN  DFSUtil - Unexpected value for data transfer bytes=2416 duration=0
17:38:30.287 WARN  DFSUtil - Unexpected value for data transfer bytes=664 duration=0
17:38:30.288 WARN  DFSUtil - Unexpected value for data transfer bytes=664 duration=0
17:38:30.288 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bam.sbi	dst=null	perm=null	proto=rpc
17:38:30.289 INFO  MemoryStore - Block broadcast_614 stored as values in memory (estimated size 298.2 KiB, free 1918.8 MiB)
17:38:30.295 INFO  MemoryStore - Block broadcast_614_piece0 stored as bytes in memory (estimated size 50.2 KiB, free 1918.8 MiB)
17:38:30.295 INFO  BlockManagerInfo - Added broadcast_614_piece0 in memory on localhost:37953 (size: 50.2 KiB, free: 1919.8 MiB)
17:38:30.295 INFO  SparkContext - Created broadcast 614 from newAPIHadoopFile at PathSplitSource.java:96
17:38:30.314 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bam	dst=null	perm=null	proto=rpc
17:38:30.314 INFO  FileInputFormat - Total input files to process : 1
17:38:30.315 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.bam	dst=null	perm=null	proto=rpc
17:38:30.347 INFO  SparkContext - Starting job: collect at ReadsSparkSourceUnitTest.java:213
17:38:30.348 INFO  DAGScheduler - Got job 227 (collect at ReadsSparkSourceUnitTest.java:213) with 1 output partitions
17:38:30.348 INFO  DAGScheduler - Final stage: ResultStage 291 (collect at ReadsSparkSourceUnitTest.java:213)
17:38:30.348 INFO  DAGScheduler - Parents of final stage: List()
17:38:30.348 INFO  DAGScheduler - Missing parents: List()
17:38:30.348 INFO  DAGScheduler - Submitting ResultStage 291 (MapPartitionsRDD[1483] at filter at ReadsSparkSource.java:96), which has no missing parents
17:38:30.363 INFO  MemoryStore - Block broadcast_615 stored as values in memory (estimated size 426.4 KiB, free 1918.3 MiB)
17:38:30.364 INFO  MemoryStore - Block broadcast_615_piece0 stored as bytes in memory (estimated size 154.0 KiB, free 1918.2 MiB)
17:38:30.364 INFO  BlockManagerInfo - Added broadcast_615_piece0 in memory on localhost:37953 (size: 154.0 KiB, free: 1919.6 MiB)
17:38:30.364 INFO  SparkContext - Created broadcast 615 from broadcast at DAGScheduler.scala:1580
17:38:30.365 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 291 (MapPartitionsRDD[1483] at filter at ReadsSparkSource.java:96) (first 15 tasks are for partitions Vector(0))
17:38:30.365 INFO  TaskSchedulerImpl - Adding task set 291.0 with 1 tasks resource profile 0
17:38:30.365 INFO  TaskSetManager - Starting task 0.0 in stage 291.0 (TID 378) (localhost, executor driver, partition 0, ANY, 7796 bytes) 
17:38:30.365 INFO  Executor - Running task 0.0 in stage 291.0 (TID 378)
17:38:30.401 INFO  BlockManagerInfo - Removed broadcast_613_piece0 on localhost:37953 in memory (size: 154.0 KiB, free: 1919.8 MiB)
17:38:30.401 INFO  NewHadoopRDD - Input split: hdfs://localhost:44873/user/runner/hdfs.bam:0+2396
17:38:30.401 INFO  BlockManagerInfo - Removed broadcast_612_piece0 on localhost:37953 in memory (size: 50.2 KiB, free: 1919.8 MiB)
17:38:30.401 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bam	dst=null	perm=null	proto=rpc
17:38:30.402 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.bam	dst=null	perm=null	proto=rpc
17:38:30.403 WARN  DFSUtil - Unexpected value for data transfer bytes=2416 duration=0
17:38:30.403 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bam	dst=null	perm=null	proto=rpc
17:38:30.404 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.bam	dst=null	perm=null	proto=rpc
17:38:30.404 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bam.bai	dst=null	perm=null	proto=rpc
17:38:30.405 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bai	dst=null	perm=null	proto=rpc
17:38:30.405 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bai	dst=null	perm=null	proto=rpc
17:38:30.405 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.bai	dst=null	perm=null	proto=rpc
17:38:30.406 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:30.407 WARN  DFSUtil - Unexpected value for data transfer bytes=2416 duration=0
17:38:30.408 WARN  DFSUtil - Unexpected value for data transfer bytes=664 duration=0
17:38:30.408 WARN  DFSUtil - Unexpected value for data transfer bytes=664 duration=0
17:38:30.408 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bam	dst=null	perm=null	proto=rpc
17:38:30.409 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.bam	dst=null	perm=null	proto=rpc
17:38:30.409 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:30.410 WARN  DFSUtil - Unexpected value for data transfer bytes=2416 duration=0
17:38:30.410 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bam	dst=null	perm=null	proto=rpc
17:38:30.410 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.bam	dst=null	perm=null	proto=rpc
17:38:30.411 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bam.bai	dst=null	perm=null	proto=rpc
17:38:30.411 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bai	dst=null	perm=null	proto=rpc
17:38:30.412 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=getfileinfo	src=/user/runner/hdfs.bai	dst=null	perm=null	proto=rpc
17:38:30.412 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=open	src=/user/runner/hdfs.bai	dst=null	perm=null	proto=rpc
17:38:30.413 WARN  IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:38:30.413 WARN  DFSUtil - Unexpected value for data transfer bytes=2416 duration=0
17:38:30.414 WARN  DFSUtil - Unexpected value for data transfer bytes=664 duration=0
17:38:30.414 WARN  DFSUtil - Unexpected value for data transfer bytes=664 duration=0
17:38:30.415 INFO  Executor - Finished task 0.0 in stage 291.0 (TID 378). 5331 bytes result sent to driver
17:38:30.415 INFO  TaskSetManager - Finished task 0.0 in stage 291.0 (TID 378) in 50 ms on localhost (executor driver) (1/1)
17:38:30.415 INFO  TaskSchedulerImpl - Removed TaskSet 291.0, whose tasks have all completed, from pool 
17:38:30.415 INFO  DAGScheduler - ResultStage 291 (collect at ReadsSparkSourceUnitTest.java:213) finished in 0.067 s
17:38:30.415 INFO  DAGScheduler - Job 227 is finished. Cancelling potential speculative or zombie tasks for this job
17:38:30.415 INFO  TaskSchedulerImpl - Killing all running tasks in stage 291: Stage finished
17:38:30.416 INFO  DAGScheduler - Job 227 finished: collect at ReadsSparkSourceUnitTest.java:213, took 0.068331 s
17:38:30.416 INFO  MiniDFSCluster - Shutting down the Mini HDFS Cluster
17:38:30.416 INFO  MiniDFSCluster - Shutting down DataNode 0
17:38:30.416 INFO  DirectoryScanner - Shutdown has been called
17:38:30.416 INFO  DataNode - Closing all peers.
17:38:30.416 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage18063395967434311937/data/data1, DS-aa63a8fd-4862-4366-bb39-9285b8093ae4) exiting.
17:38:30.417 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage18063395967434311937/data/data2, DS-721e23b4-dbc2-44ce-be69-fd77c1e17fc7) exiting.
17:38:30.419 INFO  ContextHandler - Stopped o.e.j.w.WebAppContext@64ee819{datanode,/,null,STOPPED}{jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/datanode}
17:38:30.420 INFO  AbstractConnector - Stopped ServerConnector@10f9f71f{HTTP/1.1, (http/1.1)}{localhost:0}
17:38:30.420 INFO  session - node0 Stopped scavenging
17:38:30.420 INFO  ContextHandler - Stopped o.e.j.s.ServletContextHandler@25615ffd{static,/static,jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/static,STOPPED}
17:38:30.421 INFO  DataNode - Waiting up to 30 seconds for transfer threads to complete
17:38:30.421 INFO  Server - Stopping server on 43615
17:38:30.421 INFO  Server - Stopping IPC Server listener on 0
17:38:30.421 INFO  Server - Stopping IPC Server Responder
17:38:30.422 ERROR DataNode - Command processor encountered interrupt and exit.
17:38:30.422 WARN  IncrementalBlockReportManager - IncrementalBlockReportManager interrupted
17:38:30.422 WARN  DataNode - Ending command processor service for: Thread[Command processor,5,main]
17:38:30.422 WARN  IncrementalBlockReportManager - IncrementalBlockReportManager interrupted
17:38:30.422 WARN  DataNode - Ending block pool service for: Block pool BP-829943571-10.1.0.252-1761586709371 (Datanode Uuid 7eeb06e8-b77b-461a-9674-2f1b537c18e3) service to localhost/127.0.0.1:44873
17:38:30.422 INFO  DataNode - Removed Block pool BP-829943571-10.1.0.252-1761586709371 (Datanode Uuid 7eeb06e8-b77b-461a-9674-2f1b537c18e3)
17:38:30.422 INFO  FsDatasetImpl - Removing block pool BP-829943571-10.1.0.252-1761586709371
17:38:30.422 WARN  CachingGetSpaceUsed - Thread Interrupted waiting to refresh disk information: sleep interrupted
17:38:30.422 WARN  CachingGetSpaceUsed - Thread Interrupted waiting to refresh disk information: sleep interrupted
17:38:30.423 INFO  FsDatasetAsyncDiskService - Shutting down all async disk service threads
17:38:30.423 INFO  FsDatasetAsyncDiskService - All async disk service threads have been shut down
17:38:30.423 INFO  RamDiskAsyncLazyPersistService - Shutting down all async lazy persist service threads
17:38:30.423 INFO  RamDiskAsyncLazyPersistService - All async lazy persist service threads have been shut down
17:38:30.423 INFO  DataNode - Shutdown complete.
17:38:30.423 INFO  MiniDFSCluster - Shutting down the namenode
17:38:30.423 INFO  FSNamesystem - Stopping services started for active state
17:38:30.423 INFO  FSNamesystem - NameNodeEditLogRoller was interrupted, exiting
17:38:30.423 INFO  FSEditLog - Ending log segment 1, 13
17:38:30.423 INFO  FSNamesystem - LazyPersistFileScrubber was interrupted, exiting
17:38:30.423 INFO  FSEditLog - Number of transactions: 14 Total time for transactions(ms): 0 Number of transactions batched in Syncs: 2 Number of syncs: 13 SyncTimes(ms): 1 0 
17:38:30.423 INFO  FileJournalManager - Finalizing edits file /tmp/minicluster_storage18063395967434311937/name-0-1/current/edits_inprogress_0000000000000000001 -> /tmp/minicluster_storage18063395967434311937/name-0-1/current/edits_0000000000000000001-0000000000000000014
17:38:30.424 INFO  FileJournalManager - Finalizing edits file /tmp/minicluster_storage18063395967434311937/name-0-2/current/edits_inprogress_0000000000000000001 -> /tmp/minicluster_storage18063395967434311937/name-0-2/current/edits_0000000000000000001-0000000000000000014
17:38:30.424 INFO  FSEditLog - FSEditLogAsync was interrupted, exiting
17:38:30.424 INFO  CacheReplicationMonitor - Shutting down CacheReplicationMonitor
17:38:30.424 INFO  Server - Stopping server on 44873
17:38:30.424 INFO  Server - Stopping IPC Server Responder
17:38:30.424 INFO  BlockManager - Stopping RedundancyMonitor.
17:38:30.425 INFO  Server - Stopping IPC Server listener on 0
17:38:30.425 INFO  BlockManager - Stopping MarkedDeleteBlockScrubber.
17:38:30.427 INFO  FSNamesystem - Stopping services started for active state
17:38:30.428 INFO  FSNamesystem - Stopping services started for standby state
17:38:30.428 INFO  ContextHandler - Stopped o.e.j.w.WebAppContext@444454ac{hdfs,/,null,STOPPED}{jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/hdfs}
17:38:30.429 INFO  AbstractConnector - Stopped ServerConnector@7b51743b{HTTP/1.1, (http/1.1)}{localhost:0}
17:38:30.429 INFO  session - node0 Stopped scavenging
17:38:30.429 INFO  ContextHandler - Stopped o.e.j.s.ServletContextHandler@2aa023bc{static,/static,jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/org.apache.hadoop/hadoop-hdfs/3.3.6/5058b645375c6a68f509e167ad6a6ada9642df09/hadoop-hdfs-3.3.6-tests.jar!/webapps/static,STOPPED}
17:38:30.429 INFO  MetricsSystemImpl - Stopping DataNode metrics system...
17:38:30.429 INFO  MetricsSystemImpl - DataNode metrics system stopped.
17:38:30.429 INFO  MetricsSystemImpl - DataNode metrics system shutdown complete.