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

32

tests

0

failures

0

ignored

22.197s

duration

100%

successful

Tests

Test Duration Result
testBrokenGVCFCasesAreDisallowed[0](false, .bcf) 0.001s passed
testBrokenGVCFCasesAreDisallowed[1](false, .bcf.gz) 0s passed
testBrokenGVCFCasesAreDisallowed[2](true, .g.bcf) 0s passed
testBrokenGVCFCasesAreDisallowed[3](true, .g.bcf.gz) 0s passed
testEnableDisableGVCFWriting[0](false, .vcf) 0.250s passed
testEnableDisableGVCFWriting[1](false, .vcf.gz) 0.177s passed
testEnableDisableGVCFWriting[2](true, .g.vcf) 0.168s passed
testEnableDisableGVCFWriting[3](true, .g.vcf.gz) 0.169s passed
testWritingToAnExistingFileHDFS[0](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf, true) 0.840s passed
testWritingToAnExistingFileHDFS[1](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.bgz, true) 1.921s passed
testWritingToAnExistingFileHDFS[2](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.bgz, false) 1.136s passed
testWritingToAnExistingFileHDFS[3](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.gz, true) 2.318s passed
testWritingToAnExistingFileHDFS[4](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.gz, false) 1.564s passed
testWritingToAnExistingFileHDFS[5](/home/runner/work/gatk/gatk/src/test/resources/HSA19.dbsnp135.chr1_1M.exome_intervals.modified.vcf, .vcf, true) 1.055s passed
testWritingToFileURL[0](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf, true) 0.334s passed
testWritingToFileURL[1](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.bgz, true) 0.259s passed
testWritingToFileURL[2](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.bgz, false) 0.391s passed
testWritingToFileURL[3](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.gz, true) 0.268s passed
testWritingToFileURL[4](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.gz, false) 0.293s passed
testWritingToFileURL[5](/home/runner/work/gatk/gatk/src/test/resources/HSA19.dbsnp135.chr1_1M.exome_intervals.modified.vcf, .vcf, true) 0.304s passed
variantsSinkHDFSTest[0](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf, true) 1.049s passed
variantsSinkHDFSTest[1](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.bgz, true) 2.291s passed
variantsSinkHDFSTest[2](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.bgz, false) 1.444s passed
variantsSinkHDFSTest[3](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.gz, true) 1.866s passed
variantsSinkHDFSTest[4](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.gz, false) 1.457s passed
variantsSinkHDFSTest[5](/home/runner/work/gatk/gatk/src/test/resources/HSA19.dbsnp135.chr1_1M.exome_intervals.modified.vcf, .vcf, true) 1.025s passed
variantsSinkTest[0](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf, true) 0.223s passed
variantsSinkTest[1](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.bgz, true) 0.277s passed
variantsSinkTest[2](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.bgz, false) 0.273s passed
variantsSinkTest[3](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.gz, true) 0.230s passed
variantsSinkTest[4](/home/runner/work/gatk/gatk/src/test/resources/Homo_sapiens_assembly19.dbsnp135.chr1_1M.exome_intervals.vcf, .vcf.gz, false) 0.331s passed
variantsSinkTest[5](/home/runner/work/gatk/gatk/src/test/resources/HSA19.dbsnp135.chr1_1M.exome_intervals.modified.vcf, .vcf, true) 0.283s passed

Standard error

20:34:00.296 INFO  MiniDFSCluster - starting cluster: numNameNodes=1, numDataNodes=1
20:34:00.296 INFO  NameNode - Formatting using clusterid: testClusterID
20:34:00.296 INFO  FSEditLog - Edit logging is async:true
20:34:00.304 INFO  FSNamesystem - KeyProvider: null
20:34:00.304 INFO  FSNamesystem - fsLock is fair: true
20:34:00.304 INFO  FSNamesystem - Detailed lock hold time metrics enabled: false
20:34:00.304 INFO  FSNamesystem - fsOwner                = runner (auth:SIMPLE)
20:34:00.304 INFO  FSNamesystem - supergroup             = supergroup
20:34:00.304 INFO  FSNamesystem - isPermissionEnabled    = true
20:34:00.304 INFO  FSNamesystem - isStoragePolicyEnabled = true
20:34:00.304 INFO  FSNamesystem - HA Enabled: false
20:34:00.305 INFO  Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
20:34:00.305 INFO  DatanodeManager - dfs.block.invalidate.limit : configured=1000, counted=60, effected=1000
20:34:00.305 INFO  DatanodeManager - dfs.namenode.datanode.registration.ip-hostname-check=true
20:34:00.305 INFO  BlockManager - dfs.namenode.startup.delay.block.deletion.sec is set to 000:00:00:00.000
20:34:00.305 INFO  BlockManager - The block deletion will start around 2025 Jul 15 20:34:00
20:34:00.305 INFO  GSet - Computing capacity for map BlocksMap
20:34:00.305 INFO  GSet - VM type       = 64-bit
20:34:00.305 INFO  GSet - 2.0% max memory 3.4 GB = 70 MB
20:34:00.305 INFO  GSet - capacity      = 2^23 = 8388608 entries
20:34:00.307 INFO  BlockManager - Storage policy satisfier is disabled
20:34:00.307 INFO  BlockManager - dfs.block.access.token.enable = false
20:34:00.307 INFO  BlockManagerSafeMode - dfs.namenode.safemode.threshold-pct = 0.999
20:34:00.307 INFO  BlockManagerSafeMode - dfs.namenode.safemode.min.datanodes = 0
20:34:00.307 INFO  BlockManagerSafeMode - dfs.namenode.safemode.extension = 0
20:34:00.307 INFO  BlockManager - defaultReplication         = 1
20:34:00.307 INFO  BlockManager - maxReplication             = 512
20:34:00.307 INFO  BlockManager - minReplication             = 1
20:34:00.307 INFO  BlockManager - maxReplicationStreams      = 2
20:34:00.307 INFO  BlockManager - redundancyRecheckInterval  = 3000ms
20:34:00.307 INFO  BlockManager - encryptDataTransfer        = false
20:34:00.307 INFO  BlockManager - maxNumBlocksToLog          = 1000
20:34:00.307 INFO  GSet - Computing capacity for map INodeMap
20:34:00.307 INFO  GSet - VM type       = 64-bit
20:34:00.307 INFO  GSet - 1.0% max memory 3.4 GB = 35 MB
20:34:00.307 INFO  GSet - capacity      = 2^22 = 4194304 entries
20:34:00.308 INFO  FSDirectory - ACLs enabled? true
20:34:00.308 INFO  FSDirectory - POSIX ACL inheritance enabled? true
20:34:00.308 INFO  FSDirectory - XAttrs enabled? true
20:34:00.308 INFO  NameNode - Caching file names occurring more than 10 times
20:34:00.308 INFO  SnapshotManager - Loaded config captureOpenFiles: false, skipCaptureAccessTimeOnlyChange: false, snapshotDiffAllowSnapRootDescendant: true, maxSnapshotLimit: 65536
20:34:00.308 INFO  SnapshotManager - SkipList is disabled
20:34:00.308 INFO  GSet - Computing capacity for map cachedBlocks
20:34:00.308 INFO  GSet - VM type       = 64-bit
20:34:00.308 INFO  GSet - 0.25% max memory 3.4 GB = 8.8 MB
20:34:00.308 INFO  GSet - capacity      = 2^20 = 1048576 entries
20:34:00.309 INFO  TopMetrics - NNTop conf: dfs.namenode.top.window.num.buckets = 10
20:34:00.309 INFO  TopMetrics - NNTop conf: dfs.namenode.top.num.users = 10
20:34:00.309 INFO  TopMetrics - NNTop conf: dfs.namenode.top.windows.minutes = 1,5,25
20:34:00.309 INFO  FSNamesystem - Retry cache on namenode is enabled
20:34:00.309 INFO  FSNamesystem - Retry cache will use 0.03 of total heap and retry cache entry expiry time is 600000 millis
20:34:00.309 INFO  GSet - Computing capacity for map NameNodeRetryCache
20:34:00.309 INFO  GSet - VM type       = 64-bit
20:34:00.309 INFO  GSet - 0.029999999329447746% max memory 3.4 GB = 1.0 MB
20:34:00.309 INFO  GSet - capacity      = 2^17 = 131072 entries
20:34:00.309 INFO  FSImage - Allocated new BlockPoolId: BP-1892518160-10.1.0.111-1752611640309
20:34:00.311 INFO  Storage - Storage directory /tmp/minicluster_storage7736891337661321902/name-0-1 has been successfully formatted.
20:34:00.312 INFO  Storage - Storage directory /tmp/minicluster_storage7736891337661321902/name-0-2 has been successfully formatted.
20:34:00.321 INFO  FSImageFormatProtobuf - Saving image file /tmp/minicluster_storage7736891337661321902/name-0-2/current/fsimage.ckpt_0000000000000000000 using no compression
20:34:00.321 INFO  FSImageFormatProtobuf - Saving image file /tmp/minicluster_storage7736891337661321902/name-0-1/current/fsimage.ckpt_0000000000000000000 using no compression
20:34:00.324 INFO  FSImageFormatProtobuf - Image file /tmp/minicluster_storage7736891337661321902/name-0-1/current/fsimage.ckpt_0000000000000000000 of size 419 bytes saved in 0 seconds .
20:34:00.324 INFO  FSImageFormatProtobuf - Image file /tmp/minicluster_storage7736891337661321902/name-0-2/current/fsimage.ckpt_0000000000000000000 of size 419 bytes saved in 0 seconds .
20:34:00.325 INFO  NNStorageRetentionManager - Going to retain 1 images with txid >= 0
20:34:00.328 INFO  FSNamesystem - Stopping services started for active state
20:34:00.328 INFO  FSNamesystem - Stopping services started for standby state
20:34:00.328 INFO  NameNode - createNameNode []
20:34:00.329 WARN  MetricsConfig - Cannot locate configuration: tried hadoop-metrics2-namenode.properties,hadoop-metrics2.properties
20:34:00.330 INFO  MetricsSystemImpl - Scheduled Metric snapshot period at 10 second(s).
20:34:00.330 INFO  MetricsSystemImpl - NameNode metrics system started
20:34:00.330 INFO  NameNodeUtils - fs.defaultFS is hdfs://127.0.0.1:0
20:34:00.340 INFO  JvmPauseMonitor - Starting JVM pause monitor
20:34:00.341 INFO  DFSUtil - Filter initializers set : org.apache.hadoop.http.lib.StaticUserWebFilter,org.apache.hadoop.hdfs.web.AuthFilterInitializer
20:34:00.341 INFO  DFSUtil - Starting Web-server for hdfs at: http://localhost:0
20:34:00.342 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
20:34:00.342 WARN  HttpRequestLog - Jetty request log can only be enabled using Log4j
20:34:00.343 INFO  HttpServer2 - Added global filter 'safety' (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter)
20:34:00.343 INFO  HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context hdfs
20:34:00.343 INFO  HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context static
20:34:00.344 INFO  HttpServer2 - Added filter AuthFilter (class=org.apache.hadoop.hdfs.web.AuthFilter) to context hdfs
20:34:00.344 INFO  HttpServer2 - Added filter AuthFilter (class=org.apache.hadoop.hdfs.web.AuthFilter) to context static
20:34:00.344 INFO  HttpServer2 - addJerseyResourcePackage: packageName=org.apache.hadoop.hdfs.server.namenode.web.resources;org.apache.hadoop.hdfs.web.resources, pathSpec=/webhdfs/v1/*
20:34:00.344 INFO  HttpServer2 - Jetty bound to port 36771
20:34:00.344 INFO  Server - jetty-9.4.56.v20240826; built: 2024-08-26T17:15:05.868Z; git: ec6782ff5ead824dabdcf47fa98f90a4aedff401; jvm 17.0.6+10
20:34:00.345 INFO  session - DefaultSessionIdManager workerName=node0
20:34:00.345 INFO  session - No SessionScavenger set, using defaults
20:34:00.345 INFO  session - node0 Scavenging every 600000ms
20:34:00.346 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
20:34:00.346 INFO  ContextHandler - Started o.e.j.s.ServletContextHandler@7e196405{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}
20:34:00.439 INFO  ContextHandler - Started o.e.j.w.WebAppContext@1cdc84a7{hdfs,/,file:///tmp/jetty-localhost-36771-hadoop-hdfs-3_3_6-tests_jar-_-any-9005250180736557336/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}
20:34:00.440 INFO  AbstractConnector - Started ServerConnector@2a11c3e4{HTTP/1.1, (http/1.1)}{localhost:36771}
20:34:00.440 INFO  Server - Started @76190ms
20:34:00.440 INFO  FSEditLog - Edit logging is async:true
20:34:00.449 INFO  FSNamesystem - KeyProvider: null
20:34:00.449 INFO  FSNamesystem - fsLock is fair: true
20:34:00.449 INFO  FSNamesystem - Detailed lock hold time metrics enabled: false
20:34:00.449 INFO  FSNamesystem - fsOwner                = runner (auth:SIMPLE)
20:34:00.449 INFO  FSNamesystem - supergroup             = supergroup
20:34:00.449 INFO  FSNamesystem - isPermissionEnabled    = true
20:34:00.449 INFO  FSNamesystem - isStoragePolicyEnabled = true
20:34:00.449 INFO  FSNamesystem - HA Enabled: false
20:34:00.449 INFO  Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
20:34:00.449 INFO  DatanodeManager - dfs.block.invalidate.limit : configured=1000, counted=60, effected=1000
20:34:00.449 INFO  DatanodeManager - dfs.namenode.datanode.registration.ip-hostname-check=true
20:34:00.449 INFO  BlockManager - dfs.namenode.startup.delay.block.deletion.sec is set to 000:00:00:00.000
20:34:00.449 INFO  BlockManager - The block deletion will start around 2025 Jul 15 20:34:00
20:34:00.449 INFO  GSet - Computing capacity for map BlocksMap
20:34:00.449 INFO  GSet - VM type       = 64-bit
20:34:00.449 INFO  GSet - 2.0% max memory 3.4 GB = 70 MB
20:34:00.449 INFO  GSet - capacity      = 2^23 = 8388608 entries
20:34:00.451 INFO  BlockManager - Storage policy satisfier is disabled
20:34:00.451 INFO  BlockManager - dfs.block.access.token.enable = false
20:34:00.451 INFO  BlockManagerSafeMode - dfs.namenode.safemode.threshold-pct = 0.999
20:34:00.451 INFO  BlockManagerSafeMode - dfs.namenode.safemode.min.datanodes = 0
20:34:00.451 INFO  BlockManagerSafeMode - dfs.namenode.safemode.extension = 0
20:34:00.451 INFO  BlockManager - defaultReplication         = 1
20:34:00.451 INFO  BlockManager - maxReplication             = 512
20:34:00.451 INFO  BlockManager - minReplication             = 1
20:34:00.451 INFO  BlockManager - maxReplicationStreams      = 2
20:34:00.451 INFO  BlockManager - redundancyRecheckInterval  = 3000ms
20:34:00.451 INFO  BlockManager - encryptDataTransfer        = false
20:34:00.451 INFO  BlockManager - maxNumBlocksToLog          = 1000
20:34:00.451 INFO  GSet - Computing capacity for map INodeMap
20:34:00.451 INFO  GSet - VM type       = 64-bit
20:34:00.451 INFO  GSet - 1.0% max memory 3.4 GB = 35 MB
20:34:00.452 INFO  GSet - capacity      = 2^22 = 4194304 entries
20:34:00.452 INFO  FSDirectory - ACLs enabled? true
20:34:00.452 INFO  FSDirectory - POSIX ACL inheritance enabled? true
20:34:00.452 INFO  FSDirectory - XAttrs enabled? true
20:34:00.452 INFO  NameNode - Caching file names occurring more than 10 times
20:34:00.452 INFO  SnapshotManager - Loaded config captureOpenFiles: false, skipCaptureAccessTimeOnlyChange: false, snapshotDiffAllowSnapRootDescendant: true, maxSnapshotLimit: 65536
20:34:00.452 INFO  SnapshotManager - SkipList is disabled
20:34:00.452 INFO  GSet - Computing capacity for map cachedBlocks
20:34:00.452 INFO  GSet - VM type       = 64-bit
20:34:00.453 INFO  GSet - 0.25% max memory 3.4 GB = 8.8 MB
20:34:00.453 INFO  GSet - capacity      = 2^20 = 1048576 entries
20:34:00.453 INFO  TopMetrics - NNTop conf: dfs.namenode.top.window.num.buckets = 10
20:34:00.453 INFO  TopMetrics - NNTop conf: dfs.namenode.top.num.users = 10
20:34:00.453 INFO  TopMetrics - NNTop conf: dfs.namenode.top.windows.minutes = 1,5,25
20:34:00.453 INFO  FSNamesystem - Retry cache on namenode is enabled
20:34:00.453 INFO  FSNamesystem - Retry cache will use 0.03 of total heap and retry cache entry expiry time is 600000 millis
20:34:00.453 INFO  GSet - Computing capacity for map NameNodeRetryCache
20:34:00.453 INFO  GSet - VM type       = 64-bit
20:34:00.453 INFO  GSet - 0.029999999329447746% max memory 3.4 GB = 1.0 MB
20:34:00.453 INFO  GSet - capacity      = 2^17 = 131072 entries
20:34:00.454 INFO  Storage - Lock on /tmp/minicluster_storage7736891337661321902/name-0-1/in_use.lock acquired by nodename 3077@pkrvmq0rgcvqdmg
20:34:00.455 INFO  Storage - Lock on /tmp/minicluster_storage7736891337661321902/name-0-2/in_use.lock acquired by nodename 3077@pkrvmq0rgcvqdmg
20:34:00.456 INFO  FileJournalManager - Recovering unfinalized segments in /tmp/minicluster_storage7736891337661321902/name-0-1/current
20:34:00.456 INFO  FileJournalManager - Recovering unfinalized segments in /tmp/minicluster_storage7736891337661321902/name-0-2/current
20:34:00.456 INFO  FSImage - No edit log streams selected.
20:34:00.456 INFO  FSImage - Planning to load image: FSImageFile(file=/tmp/minicluster_storage7736891337661321902/name-0-1/current/fsimage_0000000000000000000, cpktTxId=0000000000000000000)
20:34:00.457 INFO  FSImageFormatPBINode - Loading 1 INodes.
20:34:00.457 INFO  FSImageFormatPBINode - Successfully loaded 1 inodes
20:34:00.457 INFO  FSImageFormatPBINode - Completed update blocks map and name cache, total waiting duration 0ms.
20:34:00.457 INFO  FSImageFormatProtobuf - Loaded FSImage in 0 seconds.
20:34:00.457 INFO  FSImage - Loaded image for txid 0 from /tmp/minicluster_storage7736891337661321902/name-0-1/current/fsimage_0000000000000000000
20:34:00.457 INFO  FSNamesystem - Need to save fs image? false (staleImage=false, haEnabled=false, isRollingUpgrade=false)
20:34:00.457 INFO  FSEditLog - Starting log segment at 1
20:34:00.460 INFO  NameCache - initialized with 0 entries 0 lookups
20:34:00.460 INFO  FSNamesystem - Finished loading FSImage in 6 msecs
20:34:00.460 INFO  NameNode - RPC server is binding to localhost:0
20:34:00.460 INFO  NameNode - Enable NameNode state context:false
20:34:00.460 INFO  CallQueueManager - Using callQueue: class java.util.concurrent.LinkedBlockingQueue, queueCapacity: 1000, scheduler: class org.apache.hadoop.ipc.DefaultRpcScheduler, ipcBackoff: false.
20:34:00.461 INFO  Server - Listener at localhost:37855
20:34:00.461 INFO  Server - Starting Socket Reader #1 for port 0
20:34:00.462 INFO  NameNode - Clients are to use localhost:37855 to access this namenode/service.
20:34:00.463 INFO  FSNamesystem - Registered FSNamesystemState, ReplicatedBlocksState and ECBlockGroupsState MBeans.
20:34:00.473 INFO  LeaseManager - Number of blocks under construction: 0
20:34:00.473 INFO  DatanodeAdminDefaultMonitor - Initialized the Default Decommission and Maintenance monitor
20:34:00.474 INFO  BlockManager - Start MarkedDeleteBlockScrubber thread
20:34:00.474 INFO  BlockManager - initializing replication queues
20:34:00.474 INFO  StateChange - STATE* Leaving safe mode after 0 secs
20:34:00.474 INFO  StateChange - STATE* Network topology has 0 racks and 0 datanodes
20:34:00.474 INFO  StateChange - STATE* UnderReplicatedBlocks has 0 blocks
20:34:00.477 INFO  Server - IPC Server Responder: starting
20:34:00.477 INFO  Server - IPC Server listener on 0: starting
20:34:00.478 INFO  BlockManager - Total number of blocks            = 0
20:34:00.478 INFO  BlockManager - Number of invalid blocks          = 0
20:34:00.478 INFO  BlockManager - Number of under-replicated blocks = 0
20:34:00.478 INFO  BlockManager - Number of  over-replicated blocks = 0
20:34:00.478 INFO  BlockManager - Number of blocks being written    = 0
20:34:00.478 INFO  StateChange - STATE* Replication Queue initialization scan for invalid, over- and under-replicated blocks completed in 4 msec
20:34:00.479 INFO  NameNode - NameNode RPC up at: localhost/127.0.0.1:37855
20:34:00.479 WARN  MetricsLoggerTask - Metrics logging will not be async since the logger is not log4j
20:34:00.479 INFO  FSNamesystem - Starting services required for active state
20:34:00.479 INFO  FSDirectory - Initializing quota with 12 thread(s)
20:34:00.480 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
20:34:00.480 INFO  CacheReplicationMonitor - Starting CacheReplicationMonitor with interval 30000 milliseconds
20:34:00.481 INFO  MiniDFSCluster - Starting DataNode 0 with dfs.datanode.data.dir: [DISK]file:/tmp/minicluster_storage7736891337661321902/data/data1,[DISK]file:/tmp/minicluster_storage7736891337661321902/data/data2
20:34:00.482 INFO  ThrottledAsyncChecker - Scheduling a check for [DISK]file:/tmp/minicluster_storage7736891337661321902/data/data1
20:34:00.482 INFO  ThrottledAsyncChecker - Scheduling a check for [DISK]file:/tmp/minicluster_storage7736891337661321902/data/data2
20:34:00.490 INFO  MetricsSystemImpl - DataNode metrics system started (again)
20:34:00.491 INFO  Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
20:34:00.491 INFO  BlockScanner - Initialized block scanner with targetBytesPerSec 1048576
20:34:00.491 INFO  DataNode - Configured hostname is 127.0.0.1
20:34:00.491 INFO  Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
20:34:00.491 INFO  DataNode - Starting DataNode with maxLockedMemory = 0
20:34:00.491 INFO  DataNode - Opened streaming server at /127.0.0.1:42173
20:34:00.491 INFO  DataNode - Balancing bandwidth is 104857600 bytes/s
20:34:00.491 INFO  DataNode - Number threads for balancing is 100
20:34:00.493 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
20:34:00.493 WARN  HttpRequestLog - Jetty request log can only be enabled using Log4j
20:34:00.494 INFO  HttpServer2 - Added global filter 'safety' (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter)
20:34:00.494 INFO  HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context datanode
20:34:00.494 INFO  HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context static
20:34:00.495 INFO  HttpServer2 - Jetty bound to port 43419
20:34:00.495 INFO  Server - jetty-9.4.56.v20240826; built: 2024-08-26T17:15:05.868Z; git: ec6782ff5ead824dabdcf47fa98f90a4aedff401; jvm 17.0.6+10
20:34:00.496 INFO  session - DefaultSessionIdManager workerName=node0
20:34:00.496 INFO  session - No SessionScavenger set, using defaults
20:34:00.496 INFO  session - node0 Scavenging every 660000ms
20:34:00.496 INFO  ContextHandler - Started o.e.j.s.ServletContextHandler@97f4c47{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}
20:34:00.584 INFO  ContextHandler - Started o.e.j.w.WebAppContext@2a07126c{datanode,/,file:///tmp/jetty-localhost-43419-hadoop-hdfs-3_3_6-tests_jar-_-any-10423366314525496200/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}
20:34:00.584 INFO  AbstractConnector - Started ServerConnector@595fc8f{HTTP/1.1, (http/1.1)}{localhost:43419}
20:34:00.584 INFO  Server - Started @76334ms
20:34:00.585 WARN  DatanodeHttpServer - Got null for restCsrfPreventionFilter - will not do any filtering.
20:34:00.586 INFO  DatanodeHttpServer - Listening HTTP traffic on /127.0.0.1:34767
20:34:00.586 INFO  DataNode - dnUserName = runner
20:34:00.586 INFO  DataNode - supergroup = supergroup
20:34:00.586 INFO  JvmPauseMonitor - Starting JVM pause monitor
20:34:00.586 INFO  CallQueueManager - Using callQueue: class java.util.concurrent.LinkedBlockingQueue, queueCapacity: 1000, scheduler: class org.apache.hadoop.ipc.DefaultRpcScheduler, ipcBackoff: false.
20:34:00.587 INFO  Server - Listener at localhost:39693
20:34:00.587 INFO  Server - Starting Socket Reader #1 for port 0
20:34:00.588 INFO  DataNode - Opened IPC server at /127.0.0.1:39693
20:34:00.603 INFO  DataNode - Refresh request received for nameservices: null
20:34:00.603 INFO  DataNode - Starting BPOfferServices for nameservices: <default>
20:34:00.604 WARN  MetricsLoggerTask - Metrics logging will not be async since the logger is not log4j
20:34:00.604 INFO  DataNode - Block pool <registering> (Datanode Uuid unassigned) service to localhost/127.0.0.1:37855 starting to offer service
20:34:00.605 INFO  Server - IPC Server Responder: starting
20:34:00.605 INFO  Server - IPC Server listener on 0: starting
20:34:00.606 INFO  DataNode - Acknowledging ACTIVE Namenode during handshakeBlock pool <registering> (Datanode Uuid unassigned) service to localhost/127.0.0.1:37855
20:34:00.606 INFO  Storage - Using 2 threads to upgrade data directories (dfs.datanode.parallel.volumes.load.threads.num=2, dataDirs=2)
20:34:00.607 INFO  Storage - Lock on /tmp/minicluster_storage7736891337661321902/data/data1/in_use.lock acquired by nodename 3077@pkrvmq0rgcvqdmg
20:34:00.607 INFO  Storage - Storage directory with location [DISK]file:/tmp/minicluster_storage7736891337661321902/data/data1 is not formatted for namespace 816285785. Formatting...
20:34:00.607 INFO  Storage - Generated new storageID DS-19976cf8-e9b2-4c66-8448-5eb0d1566d0c for directory /tmp/minicluster_storage7736891337661321902/data/data1 
20:34:00.607 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=datanodeReport	src=null	dst=null	perm=null	proto=rpc
20:34:00.607 INFO  MiniDFSCluster - dnInfo.length != numDataNodes
20:34:00.607 INFO  MiniDFSCluster - Waiting for cluster to become active
20:34:00.609 INFO  Storage - Lock on /tmp/minicluster_storage7736891337661321902/data/data2/in_use.lock acquired by nodename 3077@pkrvmq0rgcvqdmg
20:34:00.609 INFO  Storage - Storage directory with location [DISK]file:/tmp/minicluster_storage7736891337661321902/data/data2 is not formatted for namespace 816285785. Formatting...
20:34:00.609 INFO  Storage - Generated new storageID DS-b3b94c92-c3e9-434b-8cc3-cfbef30bbce2 for directory /tmp/minicluster_storage7736891337661321902/data/data2 
20:34:00.623 INFO  Storage - Analyzing storage directories for bpid BP-1892518160-10.1.0.111-1752611640309
20:34:00.623 INFO  Storage - Locking is disabled for /tmp/minicluster_storage7736891337661321902/data/data1/current/BP-1892518160-10.1.0.111-1752611640309
20:34:00.623 INFO  Storage - Block pool storage directory for location [DISK]file:/tmp/minicluster_storage7736891337661321902/data/data1 and block pool id BP-1892518160-10.1.0.111-1752611640309 is not formatted. Formatting ...
20:34:00.623 INFO  Storage - Formatting block pool BP-1892518160-10.1.0.111-1752611640309 directory /tmp/minicluster_storage7736891337661321902/data/data1/current/BP-1892518160-10.1.0.111-1752611640309/current
20:34:00.639 INFO  Storage - Analyzing storage directories for bpid BP-1892518160-10.1.0.111-1752611640309
20:34:00.639 INFO  Storage - Locking is disabled for /tmp/minicluster_storage7736891337661321902/data/data2/current/BP-1892518160-10.1.0.111-1752611640309
20:34:00.640 INFO  Storage - Block pool storage directory for location [DISK]file:/tmp/minicluster_storage7736891337661321902/data/data2 and block pool id BP-1892518160-10.1.0.111-1752611640309 is not formatted. Formatting ...
20:34:00.640 INFO  Storage - Formatting block pool BP-1892518160-10.1.0.111-1752611640309 directory /tmp/minicluster_storage7736891337661321902/data/data2/current/BP-1892518160-10.1.0.111-1752611640309/current
20:34:00.641 INFO  DataNode - Setting up storage: nsid=816285785;bpid=BP-1892518160-10.1.0.111-1752611640309;lv=-57;nsInfo=lv=-66;cid=testClusterID;nsid=816285785;c=1752611640309;bpid=BP-1892518160-10.1.0.111-1752611640309;dnuuid=null
20:34:00.642 INFO  DataNode - Generated and persisted new Datanode UUID bb4847eb-3431-471e-b332-bbec8c8ee25f
20:34:00.642 INFO  FsDatasetImpl - The datanode lock is a read write lock
20:34:00.643 INFO  FsDatasetImpl - Added new volume: DS-19976cf8-e9b2-4c66-8448-5eb0d1566d0c
20:34:00.643 INFO  FsDatasetImpl - Added volume - [DISK]file:/tmp/minicluster_storage7736891337661321902/data/data1, StorageType: DISK
20:34:00.643 INFO  FsDatasetImpl - Added new volume: DS-b3b94c92-c3e9-434b-8cc3-cfbef30bbce2
20:34:00.643 INFO  FsDatasetImpl - Added volume - [DISK]file:/tmp/minicluster_storage7736891337661321902/data/data2, StorageType: DISK
20:34:00.643 INFO  MemoryMappableBlockLoader - Initializing cache loader: MemoryMappableBlockLoader.
20:34:00.644 INFO  FsDatasetImpl - Registered FSDatasetState MBean
20:34:00.645 INFO  FsDatasetImpl - Adding block pool BP-1892518160-10.1.0.111-1752611640309
20:34:00.645 INFO  FsDatasetImpl - Scanning block pool BP-1892518160-10.1.0.111-1752611640309 on volume /tmp/minicluster_storage7736891337661321902/data/data1...
20:34:00.645 INFO  FsDatasetImpl - Scanning block pool BP-1892518160-10.1.0.111-1752611640309 on volume /tmp/minicluster_storage7736891337661321902/data/data2...
20:34:00.645 WARN  FsDatasetImpl - dfsUsed file missing in /tmp/minicluster_storage7736891337661321902/data/data1/current/BP-1892518160-10.1.0.111-1752611640309/current, will proceed with Du for space computation calculation, 
20:34:00.645 WARN  FsDatasetImpl - dfsUsed file missing in /tmp/minicluster_storage7736891337661321902/data/data2/current/BP-1892518160-10.1.0.111-1752611640309/current, will proceed with Du for space computation calculation, 
20:34:00.660 INFO  FsDatasetImpl - Time taken to scan block pool BP-1892518160-10.1.0.111-1752611640309 on /tmp/minicluster_storage7736891337661321902/data/data2: 15ms
20:34:00.660 INFO  FsDatasetImpl - Time taken to scan block pool BP-1892518160-10.1.0.111-1752611640309 on /tmp/minicluster_storage7736891337661321902/data/data1: 15ms
20:34:00.660 INFO  FsDatasetImpl - Total time to scan all replicas for block pool BP-1892518160-10.1.0.111-1752611640309: 15ms
20:34:00.660 INFO  FsDatasetImpl - Adding replicas to map for block pool BP-1892518160-10.1.0.111-1752611640309 on volume /tmp/minicluster_storage7736891337661321902/data/data1...
20:34:00.660 INFO  BlockPoolSlice - Replica Cache file: /tmp/minicluster_storage7736891337661321902/data/data1/current/BP-1892518160-10.1.0.111-1752611640309/current/replicas doesn't exist 
20:34:00.660 INFO  FsDatasetImpl - Adding replicas to map for block pool BP-1892518160-10.1.0.111-1752611640309 on volume /tmp/minicluster_storage7736891337661321902/data/data2...
20:34:00.660 INFO  BlockPoolSlice - Replica Cache file: /tmp/minicluster_storage7736891337661321902/data/data2/current/BP-1892518160-10.1.0.111-1752611640309/current/replicas doesn't exist 
20:34:00.660 INFO  FsDatasetImpl - Time to add replicas to map for block pool BP-1892518160-10.1.0.111-1752611640309 on volume /tmp/minicluster_storage7736891337661321902/data/data1: 0ms
20:34:00.660 INFO  FsDatasetImpl - Time to add replicas to map for block pool BP-1892518160-10.1.0.111-1752611640309 on volume /tmp/minicluster_storage7736891337661321902/data/data2: 1ms
20:34:00.661 INFO  FsDatasetImpl - Total time to add all replicas to map for block pool BP-1892518160-10.1.0.111-1752611640309: 1ms
20:34:00.661 INFO  ThrottledAsyncChecker - Scheduling a check for /tmp/minicluster_storage7736891337661321902/data/data1
20:34:00.661 INFO  DatasetVolumeChecker - Scheduled health check for volume /tmp/minicluster_storage7736891337661321902/data/data1
20:34:00.661 INFO  ThrottledAsyncChecker - Scheduling a check for /tmp/minicluster_storage7736891337661321902/data/data2
20:34:00.661 INFO  DatasetVolumeChecker - Scheduled health check for volume /tmp/minicluster_storage7736891337661321902/data/data2
20:34:00.661 WARN  DirectoryScanner - dfs.datanode.directoryscan.throttle.limit.ms.per.sec set to value above 1000 ms/sec. Assuming default value of -1
20:34:00.661 INFO  VolumeScanner - Now scanning bpid BP-1892518160-10.1.0.111-1752611640309 on volume /tmp/minicluster_storage7736891337661321902/data/data2
20:34:00.661 INFO  DirectoryScanner - Periodic Directory Tree Verification scan starting in 20983034ms with interval of 21600000ms and throttle limit of -1ms/s
20:34:00.661 INFO  VolumeScanner - Now scanning bpid BP-1892518160-10.1.0.111-1752611640309 on volume /tmp/minicluster_storage7736891337661321902/data/data1
20:34:00.661 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage7736891337661321902/data/data2, DS-b3b94c92-c3e9-434b-8cc3-cfbef30bbce2): finished scanning block pool BP-1892518160-10.1.0.111-1752611640309
20:34:00.661 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage7736891337661321902/data/data1, DS-19976cf8-e9b2-4c66-8448-5eb0d1566d0c): finished scanning block pool BP-1892518160-10.1.0.111-1752611640309
20:34:00.661 INFO  DataNode - Block pool BP-1892518160-10.1.0.111-1752611640309 (Datanode Uuid bb4847eb-3431-471e-b332-bbec8c8ee25f) service to localhost/127.0.0.1:37855 beginning handshake with NN
20:34:00.662 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage7736891337661321902/data/data2, DS-b3b94c92-c3e9-434b-8cc3-cfbef30bbce2): no suitable block pools found to scan.  Waiting 1814399999 ms.
20:34:00.662 INFO  VolumeScanner - VolumeScanner(/tmp/minicluster_storage7736891337661321902/data/data1, DS-19976cf8-e9b2-4c66-8448-5eb0d1566d0c): no suitable block pools found to scan.  Waiting 1814399999 ms.
20:34:00.662 INFO  StateChange - BLOCK* registerDatanode: from DatanodeRegistration(127.0.0.1:42173, datanodeUuid=bb4847eb-3431-471e-b332-bbec8c8ee25f, infoPort=34767, infoSecurePort=0, ipcPort=39693, storageInfo=lv=-57;cid=testClusterID;nsid=816285785;c=1752611640309) storage bb4847eb-3431-471e-b332-bbec8c8ee25f
20:34:00.662 INFO  NetworkTopology - Adding a new node: /default-rack/127.0.0.1:42173
20:34:00.662 INFO  BlockReportLeaseManager - Registered DN bb4847eb-3431-471e-b332-bbec8c8ee25f (127.0.0.1:42173).
20:34:00.662 INFO  DataNode - Block pool BP-1892518160-10.1.0.111-1752611640309 (Datanode Uuid bb4847eb-3431-471e-b332-bbec8c8ee25f) service to localhost/127.0.0.1:37855 successfully registered with NN
20:34:00.663 INFO  DataNode - For namenode localhost/127.0.0.1:37855 using BLOCKREPORT_INTERVAL of 21600000msecs CACHEREPORT_INTERVAL of 10000msecs Initial delay: 0msecs; heartBeatInterval=3000
20:34:00.663 INFO  DataNode - Starting IBR Task Handler.
20:34:00.663 INFO  DatanodeDescriptor - Adding new storage ID DS-19976cf8-e9b2-4c66-8448-5eb0d1566d0c for DN 127.0.0.1:42173
20:34:00.663 INFO  DatanodeDescriptor - Adding new storage ID DS-b3b94c92-c3e9-434b-8cc3-cfbef30bbce2 for DN 127.0.0.1:42173
20:34:00.663 INFO  DataNode - After receiving heartbeat response, updating state of namenode localhost:37855 to active
20:34:00.664 INFO  BlockStateChange - BLOCK* processReport 0x88aa539cdb3e27d4 with lease ID 0x121588df91a0c612: Processing first storage report for DS-19976cf8-e9b2-4c66-8448-5eb0d1566d0c from datanode DatanodeRegistration(127.0.0.1:42173, datanodeUuid=bb4847eb-3431-471e-b332-bbec8c8ee25f, infoPort=34767, infoSecurePort=0, ipcPort=39693, storageInfo=lv=-57;cid=testClusterID;nsid=816285785;c=1752611640309)
20:34:00.664 INFO  BlockStateChange - BLOCK* processReport 0x88aa539cdb3e27d4 with lease ID 0x121588df91a0c612: from storage DS-19976cf8-e9b2-4c66-8448-5eb0d1566d0c node DatanodeRegistration(127.0.0.1:42173, datanodeUuid=bb4847eb-3431-471e-b332-bbec8c8ee25f, infoPort=34767, infoSecurePort=0, ipcPort=39693, storageInfo=lv=-57;cid=testClusterID;nsid=816285785;c=1752611640309), blocks: 0, hasStaleStorage: true, processing time: 0 msecs, invalidatedBlocks: 0
20:34:00.664 INFO  BlockStateChange - BLOCK* processReport 0x88aa539cdb3e27d4 with lease ID 0x121588df91a0c612: Processing first storage report for DS-b3b94c92-c3e9-434b-8cc3-cfbef30bbce2 from datanode DatanodeRegistration(127.0.0.1:42173, datanodeUuid=bb4847eb-3431-471e-b332-bbec8c8ee25f, infoPort=34767, infoSecurePort=0, ipcPort=39693, storageInfo=lv=-57;cid=testClusterID;nsid=816285785;c=1752611640309)
20:34:00.664 INFO  BlockStateChange - BLOCK* processReport 0x88aa539cdb3e27d4 with lease ID 0x121588df91a0c612: from storage DS-b3b94c92-c3e9-434b-8cc3-cfbef30bbce2 node DatanodeRegistration(127.0.0.1:42173, datanodeUuid=bb4847eb-3431-471e-b332-bbec8c8ee25f, infoPort=34767, infoSecurePort=0, ipcPort=39693, storageInfo=lv=-57;cid=testClusterID;nsid=816285785;c=1752611640309), blocks: 0, hasStaleStorage: false, processing time: 0 msecs, invalidatedBlocks: 0
20:34:00.664 INFO  DataNode - Successfully sent block report 0x88aa539cdb3e27d4 with lease ID 0x121588df91a0c612 to namenode: localhost/127.0.0.1:37855,  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.
20:34:00.664 INFO  DataNode - Got finalize command for block pool BP-1892518160-10.1.0.111-1752611640309
20:34:00.708 INFO  audit - allowed=true	ugi=runner (auth:SIMPLE)	ip=/127.0.0.1	cmd=datanodeReport	src=null	dst=null	perm=null	proto=rpc
20:34:00.708 INFO  MiniDFSCluster - Cluster is active
20:34:00.716 INFO  MemoryStore - Block broadcast_616 stored as values in memory (estimated size 3.0 KiB, free 1920.0 MiB)
20:34:00.720 INFO  MemoryStore - Block broadcast_616_piece0 stored as bytes in memory (estimated size 525.0 B, free 1920.0 MiB)
20:34:00.720 INFO  BlockManagerInfo - Added broadcast_616_piece0 in memory on localhost:45281 (size: 525.0 B, free: 1920.0 MiB)
20:34:00.721 INFO  SparkContext - Created broadcast 616 from broadcast at VcfSink.java:65
20:34:00.724 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
20:34:00.724 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
20:34:00.724 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
20:34:00.745 INFO  SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
20:34:00.746 INFO  DAGScheduler - Registering RDD 1485 (mapToPair at VariantsSparkSink.java:140) as input to shuffle 53
20:34:00.746 INFO  DAGScheduler - Got job 228 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
20:34:00.746 INFO  DAGScheduler - Final stage: ResultStage 293 (runJob at SparkHadoopWriter.scala:83)
20:34:00.746 INFO  DAGScheduler - Parents of final stage: List(ShuffleMapStage 292)
20:34:00.747 INFO  DAGScheduler - Missing parents: List(ShuffleMapStage 292)
20:34:00.747 INFO  DAGScheduler - Submitting ShuffleMapStage 292 (MapPartitionsRDD[1485] at mapToPair at VariantsSparkSink.java:140), which has no missing parents
20:34:00.748 INFO  MemoryStore - Block broadcast_617 stored as values in memory (estimated size 6.5 KiB, free 1920.0 MiB)
20:34:00.749 INFO  MemoryStore - Block broadcast_617_piece0 stored as bytes in memory (estimated size 3.7 KiB, free 1920.0 MiB)
20:34:00.749 INFO  BlockManagerInfo - Added broadcast_617_piece0 in memory on localhost:45281 (size: 3.7 KiB, free: 1920.0 MiB)
20:34:00.749 INFO  SparkContext - Created broadcast 617 from broadcast at DAGScheduler.scala:1580
20:34:00.749 INFO  DAGScheduler - Submitting 4 missing tasks from ShuffleMapStage 292 (MapPartitionsRDD[1485] at mapToPair at VariantsSparkSink.java:140) (first 15 tasks are for partitions Vector(0, 1, 2, 3))
20:34:00.749 INFO  TaskSchedulerImpl - Adding task set 292.0 with 4 tasks resource profile 0
20:34:00.751 INFO  TaskSetManager - Starting task 0.0 in stage 292.0 (TID 379) (localhost, executor driver, partition 0, PROCESS_LOCAL, 8087 bytes) 
20:34:00.752 INFO  TaskSetManager - Starting task 1.0 in stage 292.0 (TID 380) (localhost, executor driver, partition 1, PROCESS_LOCAL, 8193 bytes) 
20:34:00.752 INFO  TaskSetManager - Starting task 2.0 in stage 292.0 (TID 381) (localhost, executor driver, partition 2, PROCESS_LOCAL, 8087 bytes) 
20:34:00.753 INFO  TaskSetManager - Starting task 3.0 in stage 292.0 (TID 382) (localhost, executor driver, partition 3, PROCESS_LOCAL, 8193 bytes) 
20:34:00.754 INFO  Executor - Running task 1.0 in stage 292.0 (TID 380)
20:34:00.756 INFO  Executor - Running task 3.0 in stage 292.0 (TID 382)
20:34:00.756 INFO  Executor - Running task 2.0 in stage 292.0 (TID 381)
20:34:00.756 INFO  Executor - Running task 0.0 in stage 292.0 (TID 379)
20:34:00.764 INFO  Executor - Finished task 1.0 in stage 292.0 (TID 380). 1062 bytes result sent to driver
20:34:00.768 INFO  TaskSetManager - Finished task 1.0 in stage 292.0 (TID 380) in 17 ms on localhost (executor driver) (1/4)
20:34:00.769 INFO  Executor - Finished task 3.0 in stage 292.0 (TID 382). 1062 bytes result sent to driver
20:34:00.770 INFO  Executor - Finished task 2.0 in stage 292.0 (TID 381). 1062 bytes result sent to driver
20:34:00.770 INFO  TaskSetManager - Finished task 3.0 in stage 292.0 (TID 382) in 18 ms on localhost (executor driver) (2/4)
20:34:00.771 INFO  TaskSetManager - Finished task 2.0 in stage 292.0 (TID 381) in 19 ms on localhost (executor driver) (3/4)
20:34:00.772 INFO  Executor - Finished task 0.0 in stage 292.0 (TID 379). 1062 bytes result sent to driver
20:34:00.772 INFO  TaskSetManager - Finished task 0.0 in stage 292.0 (TID 379) in 22 ms on localhost (executor driver) (4/4)
20:34:00.772 INFO  TaskSchedulerImpl - Removed TaskSet 292.0, whose tasks have all completed, from pool 
20:34:00.772 INFO  DAGScheduler - ShuffleMapStage 292 (mapToPair at VariantsSparkSink.java:140) finished in 0.025 s
20:34:00.772 INFO  DAGScheduler - looking for newly runnable stages
20:34:00.772 INFO  DAGScheduler - running: HashSet()
20:34:00.772 INFO  DAGScheduler - waiting: HashSet(ResultStage 293)
20:34:00.772 INFO  DAGScheduler - failed: HashSet()
20:34:00.772 INFO  DAGScheduler - Submitting ResultStage 293 (MapPartitionsRDD[1489] at mapToPair at VcfSink.java:77), which has no missing parents
20:34:00.783 INFO  MemoryStore - Block broadcast_618 stored as values in memory (estimated size 149.6 KiB, free 1919.8 MiB)
20:34:00.784 INFO  MemoryStore - Block broadcast_618_piece0 stored as bytes in memory (estimated size 56.2 KiB, free 1919.8 MiB)
20:34:00.784 INFO  BlockManagerInfo - Added broadcast_618_piece0 in memory on localhost:45281 (size: 56.2 KiB, free: 1919.9 MiB)
20:34:00.784 INFO  SparkContext - Created broadcast 618 from broadcast at DAGScheduler.scala:1580
20:34:00.784 INFO  DAGScheduler - Submitting 1 missing tasks from ResultStage 293 (MapPartitionsRDD[1489] at mapToPair at VcfSink.java:77) (first 15 tasks are for partitions Vector(0))
20:34:00.784 INFO  TaskSchedulerImpl - Adding task set 293.0 with 1 tasks resource profile 0
20:34:00.785 INFO  TaskSetManager - Starting task 0.0 in stage 293.0 (TID 383) (localhost, executor driver, partition 0, NODE_LOCAL, 7513 bytes) 
20:34:00.785 INFO  Executor - Running task 0.0 in stage 293.0 (TID 383)
20:34:00.792 INFO  ShuffleBlockFetcherIterator - Getting 4 (1336.0 B) non-empty blocks including 4 (1336.0 B) local and 0 (0.0 B) host-local and 0 (0.0 B) push-merged-local and 0 (0.0 B) remote blocks
20:34:00.792 INFO  ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
20:34:00.800 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
20:34:00.800 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
20:34:00.800 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
20:34:00.800 INFO  PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
20:34:00.800 INFO  FileOutputCommitter - File Output Committer Algorithm version is 1
20:34:00.800 INFO  FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
20:34:00.817 INFO  FileOutputCommitter - Saved output of task 'attempt_202507152034004974248315439521157_1489_r_000000_0' to file:/tmp/VariantsSparkSinkUnitTest4724574715091414993.vcf.parts/_temporary/0/task_202507152034004974248315439521157_1489_r_000000
20:34:00.817 INFO  SparkHadoopMapRedUtil - attempt_202507152034004974248315439521157_1489_r_000000_0: Committed. Elapsed time: 0 ms.
20:34:00.817 INFO  Executor - Finished task 0.0 in stage 293.0 (TID 383). 1858 bytes result sent to driver
20:34:00.818 INFO  TaskSetManager - Finished task 0.0 in stage 293.0 (TID 383) in 33 ms on localhost (executor driver) (1/1)
20:34:00.818 INFO  TaskSchedulerImpl - Removed TaskSet 293.0, whose tasks have all completed, from pool 
20:34:00.818 INFO  DAGScheduler - ResultStage 293 (runJob at SparkHadoopWriter.scala:83) finished in 0.045 s
20:34:00.818 INFO  DAGScheduler - Job 228 is finished. Cancelling potential speculative or zombie tasks for this job
20:34:00.818 INFO  TaskSchedulerImpl - Killing all running tasks in stage 293: Stage finished
20:34:00.819 INFO  DAGScheduler - Job 228 finished: runJob at SparkHadoopWriter.scala:83, took 0.073858 s
20:34:00.820 INFO  SparkHadoopWriter - Start to commit write Job job_202507152034004974248315439521157_1489.
20:34:00.826 INFO  SparkHadoopWriter - Write Job job_202507152034004974248315439521157_1489 committed. Elapsed time: 5 ms.
20:34:00.853 INFO  HadoopFileSystemWrapper - Concatenating 2 parts to /tmp/VariantsSparkSinkUnitTest4724574715091414993.vcf
20:34:00.859 INFO  HadoopFileSystemWrapper - Concatenating to /tmp/VariantsSparkSinkUnitTest4724574715091414993.vcf done
[July 15, 2025 at 8:34:00 PM UTC] org.broadinstitute.hellbender.tools.IndexFeatureFile done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=702545920
[July 15, 2025 at 8:34:01 PM UTC] org.broadinstitute.hellbender.tools.IndexFeatureFile done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=702545920
[July 15, 2025 at 8:34:01 PM UTC] org.broadinstitute.hellbender.tools.IndexFeatureFile done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=702545920
[July 15, 2025 at 8:34:01 PM UTC] org.broadinstitute.hellbender.tools.IndexFeatureFile done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=702545920