19:49:05.785 INFO MiniDFSCluster - starting cluster: numNameNodes=1, numDataNodes=1
19:49:05.786 INFO NameNode - Formatting using clusterid: testClusterID
19:49:05.786 INFO FSEditLog - Edit logging is async:true
19:49:05.793 INFO FSNamesystem - KeyProvider: null
19:49:05.793 INFO FSNamesystem - fsLock is fair: true
19:49:05.793 INFO FSNamesystem - Detailed lock hold time metrics enabled: false
19:49:05.793 INFO FSNamesystem - fsOwner = runner (auth:SIMPLE)
19:49:05.793 INFO FSNamesystem - supergroup = supergroup
19:49:05.793 INFO FSNamesystem - isPermissionEnabled = true
19:49:05.793 INFO FSNamesystem - isStoragePolicyEnabled = true
19:49:05.793 INFO FSNamesystem - HA Enabled: false
19:49:05.793 INFO Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
19:49:05.794 INFO DatanodeManager - dfs.block.invalidate.limit : configured=1000, counted=60, effected=1000
19:49:05.794 INFO DatanodeManager - dfs.namenode.datanode.registration.ip-hostname-check=true
19:49:05.794 INFO BlockManager - dfs.namenode.startup.delay.block.deletion.sec is set to 000:00:00:00.000
19:49:05.794 INFO BlockManager - The block deletion will start around 2025 Jul 15 19:49:05
19:49:05.794 INFO GSet - Computing capacity for map BlocksMap
19:49:05.794 INFO GSet - VM type = 64-bit
19:49:05.794 INFO GSet - 2.0% max memory 3.4 GB = 70 MB
19:49:05.794 INFO GSet - capacity = 2^23 = 8388608 entries
19:49:05.797 INFO BlockManager - Storage policy satisfier is disabled
19:49:05.797 INFO BlockManager - dfs.block.access.token.enable = false
19:49:05.797 INFO BlockManagerSafeMode - dfs.namenode.safemode.threshold-pct = 0.999
19:49:05.797 INFO BlockManagerSafeMode - dfs.namenode.safemode.min.datanodes = 0
19:49:05.797 INFO BlockManagerSafeMode - dfs.namenode.safemode.extension = 0
19:49:05.797 INFO BlockManager - defaultReplication = 1
19:49:05.798 INFO BlockManager - maxReplication = 512
19:49:05.798 INFO BlockManager - minReplication = 1
19:49:05.798 INFO BlockManager - maxReplicationStreams = 2
19:49:05.798 INFO BlockManager - redundancyRecheckInterval = 3000ms
19:49:05.798 INFO BlockManager - encryptDataTransfer = false
19:49:05.798 INFO BlockManager - maxNumBlocksToLog = 1000
19:49:05.798 INFO GSet - Computing capacity for map INodeMap
19:49:05.798 INFO GSet - VM type = 64-bit
19:49:05.798 INFO GSet - 1.0% max memory 3.4 GB = 35 MB
19:49:05.798 INFO GSet - capacity = 2^22 = 4194304 entries
19:49:05.799 INFO FSDirectory - ACLs enabled? true
19:49:05.799 INFO FSDirectory - POSIX ACL inheritance enabled? true
19:49:05.799 INFO FSDirectory - XAttrs enabled? true
19:49:05.799 INFO NameNode - Caching file names occurring more than 10 times
19:49:05.799 INFO SnapshotManager - Loaded config captureOpenFiles: false, skipCaptureAccessTimeOnlyChange: false, snapshotDiffAllowSnapRootDescendant: true, maxSnapshotLimit: 65536
19:49:05.799 INFO SnapshotManager - SkipList is disabled
19:49:05.799 INFO GSet - Computing capacity for map cachedBlocks
19:49:05.799 INFO GSet - VM type = 64-bit
19:49:05.799 INFO GSet - 0.25% max memory 3.4 GB = 8.8 MB
19:49:05.799 INFO GSet - capacity = 2^20 = 1048576 entries
19:49:05.799 INFO TopMetrics - NNTop conf: dfs.namenode.top.window.num.buckets = 10
19:49:05.799 INFO TopMetrics - NNTop conf: dfs.namenode.top.num.users = 10
19:49:05.799 INFO TopMetrics - NNTop conf: dfs.namenode.top.windows.minutes = 1,5,25
19:49:05.799 INFO FSNamesystem - Retry cache on namenode is enabled
19:49:05.799 INFO FSNamesystem - Retry cache will use 0.03 of total heap and retry cache entry expiry time is 600000 millis
19:49:05.799 INFO GSet - Computing capacity for map NameNodeRetryCache
19:49:05.799 INFO GSet - VM type = 64-bit
19:49:05.799 INFO GSet - 0.029999999329447746% max memory 3.4 GB = 1.0 MB
19:49:05.799 INFO GSet - capacity = 2^17 = 131072 entries
19:49:05.800 INFO FSImage - Allocated new BlockPoolId: BP-213204104-10.1.0.127-1752608945800
19:49:05.801 INFO Storage - Storage directory /tmp/minicluster_storage5391834643678571027/name-0-1 has been successfully formatted.
19:49:05.803 INFO Storage - Storage directory /tmp/minicluster_storage5391834643678571027/name-0-2 has been successfully formatted.
19:49:05.814 INFO FSImageFormatProtobuf - Saving image file /tmp/minicluster_storage5391834643678571027/name-0-1/current/fsimage.ckpt_0000000000000000000 using no compression
19:49:05.815 INFO FSImageFormatProtobuf - Saving image file /tmp/minicluster_storage5391834643678571027/name-0-2/current/fsimage.ckpt_0000000000000000000 using no compression
19:49:05.817 INFO FSImageFormatProtobuf - Image file /tmp/minicluster_storage5391834643678571027/name-0-1/current/fsimage.ckpt_0000000000000000000 of size 419 bytes saved in 0 seconds .
19:49:05.819 INFO FSImageFormatProtobuf - Image file /tmp/minicluster_storage5391834643678571027/name-0-2/current/fsimage.ckpt_0000000000000000000 of size 419 bytes saved in 0 seconds .
19:49:05.820 INFO NNStorageRetentionManager - Going to retain 1 images with txid >= 0
19:49:05.825 INFO FSNamesystem - Stopping services started for active state
19:49:05.825 INFO FSNamesystem - Stopping services started for standby state
19:49:05.825 INFO NameNode - createNameNode []
19:49:05.826 WARN MetricsConfig - Cannot locate configuration: tried hadoop-metrics2-namenode.properties,hadoop-metrics2.properties
19:49:05.827 INFO MetricsSystemImpl - Scheduled Metric snapshot period at 10 second(s).
19:49:05.827 INFO MetricsSystemImpl - NameNode metrics system started
19:49:05.827 INFO NameNodeUtils - fs.defaultFS is hdfs://127.0.0.1:0
19:49:05.838 INFO JvmPauseMonitor - Starting JVM pause monitor
19:49:05.838 INFO DFSUtil - Filter initializers set : org.apache.hadoop.http.lib.StaticUserWebFilter,org.apache.hadoop.hdfs.web.AuthFilterInitializer
19:49:05.838 INFO DFSUtil - Starting Web-server for hdfs at: http://localhost:0
19:49:05.839 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
19:49:05.840 WARN HttpRequestLog - Jetty request log can only be enabled using Log4j
19:49:05.841 INFO HttpServer2 - Added global filter 'safety' (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter)
19:49:05.841 INFO HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context hdfs
19:49:05.841 INFO HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context static
19:49:05.843 INFO HttpServer2 - Added filter AuthFilter (class=org.apache.hadoop.hdfs.web.AuthFilter) to context hdfs
19:49:05.843 INFO HttpServer2 - Added filter AuthFilter (class=org.apache.hadoop.hdfs.web.AuthFilter) to context static
19:49:05.843 INFO HttpServer2 - addJerseyResourcePackage: packageName=org.apache.hadoop.hdfs.server.namenode.web.resources;org.apache.hadoop.hdfs.web.resources, pathSpec=/webhdfs/v1/*
19:49:05.843 INFO HttpServer2 - Jetty bound to port 33239
19:49:05.843 INFO Server - jetty-9.4.56.v20240826; built: 2024-08-26T17:15:05.868Z; git: ec6782ff5ead824dabdcf47fa98f90a4aedff401; jvm 17.0.6+10
19:49:05.845 INFO session - DefaultSessionIdManager workerName=node0
19:49:05.845 INFO session - No SessionScavenger set, using defaults
19:49:05.845 INFO session - node0 Scavenging every 600000ms
19:49:05.845 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
19:49:05.846 INFO ContextHandler - Started o.e.j.s.ServletContextHandler@42f8a964{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}
19:49:05.884 INFO BlockManagerInfo - Removed broadcast_614_piece0 on localhost:36125 in memory (size: 50.2 KiB, free: 1919.8 MiB)
19:49:05.884 INFO BlockManagerInfo - Removed broadcast_615_piece0 on localhost:36125 in memory (size: 154.0 KiB, free: 1920.0 MiB)
19:49:05.952 INFO ContextHandler - Started o.e.j.w.WebAppContext@177fb8a2{hdfs,/,file:///tmp/jetty-localhost-33239-hadoop-hdfs-3_3_6-tests_jar-_-any-16704576182821591076/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}
19:49:05.953 INFO AbstractConnector - Started ServerConnector@753912b7{HTTP/1.1, (http/1.1)}{localhost:33239}
19:49:05.953 INFO Server - Started @77166ms
19:49:05.954 INFO FSEditLog - Edit logging is async:true
19:49:05.962 INFO FSNamesystem - KeyProvider: null
19:49:05.962 INFO FSNamesystem - fsLock is fair: true
19:49:05.962 INFO FSNamesystem - Detailed lock hold time metrics enabled: false
19:49:05.962 INFO FSNamesystem - fsOwner = runner (auth:SIMPLE)
19:49:05.962 INFO FSNamesystem - supergroup = supergroup
19:49:05.962 INFO FSNamesystem - isPermissionEnabled = true
19:49:05.962 INFO FSNamesystem - isStoragePolicyEnabled = true
19:49:05.962 INFO FSNamesystem - HA Enabled: false
19:49:05.962 INFO Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
19:49:05.963 INFO DatanodeManager - dfs.block.invalidate.limit : configured=1000, counted=60, effected=1000
19:49:05.963 INFO DatanodeManager - dfs.namenode.datanode.registration.ip-hostname-check=true
19:49:05.963 INFO BlockManager - dfs.namenode.startup.delay.block.deletion.sec is set to 000:00:00:00.000
19:49:05.963 INFO BlockManager - The block deletion will start around 2025 Jul 15 19:49:05
19:49:05.963 INFO GSet - Computing capacity for map BlocksMap
19:49:05.963 INFO GSet - VM type = 64-bit
19:49:05.963 INFO GSet - 2.0% max memory 3.4 GB = 70 MB
19:49:05.963 INFO GSet - capacity = 2^23 = 8388608 entries
19:49:05.964 INFO BlockManager - Storage policy satisfier is disabled
19:49:05.964 INFO BlockManager - dfs.block.access.token.enable = false
19:49:05.964 INFO BlockManagerSafeMode - dfs.namenode.safemode.threshold-pct = 0.999
19:49:05.964 INFO BlockManagerSafeMode - dfs.namenode.safemode.min.datanodes = 0
19:49:05.964 INFO BlockManagerSafeMode - dfs.namenode.safemode.extension = 0
19:49:05.964 INFO BlockManager - defaultReplication = 1
19:49:05.964 INFO BlockManager - maxReplication = 512
19:49:05.964 INFO BlockManager - minReplication = 1
19:49:05.964 INFO BlockManager - maxReplicationStreams = 2
19:49:05.964 INFO BlockManager - redundancyRecheckInterval = 3000ms
19:49:05.964 INFO BlockManager - encryptDataTransfer = false
19:49:05.964 INFO BlockManager - maxNumBlocksToLog = 1000
19:49:05.964 INFO GSet - Computing capacity for map INodeMap
19:49:05.964 INFO GSet - VM type = 64-bit
19:49:05.964 INFO GSet - 1.0% max memory 3.4 GB = 35 MB
19:49:05.964 INFO GSet - capacity = 2^22 = 4194304 entries
19:49:05.965 INFO FSDirectory - ACLs enabled? true
19:49:05.965 INFO FSDirectory - POSIX ACL inheritance enabled? true
19:49:05.965 INFO FSDirectory - XAttrs enabled? true
19:49:05.965 INFO NameNode - Caching file names occurring more than 10 times
19:49:05.965 INFO SnapshotManager - Loaded config captureOpenFiles: false, skipCaptureAccessTimeOnlyChange: false, snapshotDiffAllowSnapRootDescendant: true, maxSnapshotLimit: 65536
19:49:05.965 INFO SnapshotManager - SkipList is disabled
19:49:05.965 INFO GSet - Computing capacity for map cachedBlocks
19:49:05.965 INFO GSet - VM type = 64-bit
19:49:05.965 INFO GSet - 0.25% max memory 3.4 GB = 8.8 MB
19:49:05.965 INFO GSet - capacity = 2^20 = 1048576 entries
19:49:05.966 INFO TopMetrics - NNTop conf: dfs.namenode.top.window.num.buckets = 10
19:49:05.966 INFO TopMetrics - NNTop conf: dfs.namenode.top.num.users = 10
19:49:05.966 INFO TopMetrics - NNTop conf: dfs.namenode.top.windows.minutes = 1,5,25
19:49:05.966 INFO FSNamesystem - Retry cache on namenode is enabled
19:49:05.966 INFO FSNamesystem - Retry cache will use 0.03 of total heap and retry cache entry expiry time is 600000 millis
19:49:05.966 INFO GSet - Computing capacity for map NameNodeRetryCache
19:49:05.966 INFO GSet - VM type = 64-bit
19:49:05.966 INFO GSet - 0.029999999329447746% max memory 3.4 GB = 1.0 MB
19:49:05.966 INFO GSet - capacity = 2^17 = 131072 entries
19:49:05.967 INFO Storage - Lock on /tmp/minicluster_storage5391834643678571027/name-0-1/in_use.lock acquired by nodename 3162@pkrvmq0rgcvqdmg
19:49:05.968 INFO Storage - Lock on /tmp/minicluster_storage5391834643678571027/name-0-2/in_use.lock acquired by nodename 3162@pkrvmq0rgcvqdmg
19:49:05.968 INFO FileJournalManager - Recovering unfinalized segments in /tmp/minicluster_storage5391834643678571027/name-0-1/current
19:49:05.969 INFO FileJournalManager - Recovering unfinalized segments in /tmp/minicluster_storage5391834643678571027/name-0-2/current
19:49:05.969 INFO FSImage - No edit log streams selected.
19:49:05.969 INFO FSImage - Planning to load image: FSImageFile(file=/tmp/minicluster_storage5391834643678571027/name-0-1/current/fsimage_0000000000000000000, cpktTxId=0000000000000000000)
19:49:05.969 INFO FSImageFormatPBINode - Loading 1 INodes.
19:49:05.970 INFO FSImageFormatPBINode - Successfully loaded 1 inodes
19:49:05.970 INFO FSImageFormatPBINode - Completed update blocks map and name cache, total waiting duration 0ms.
19:49:05.970 INFO FSImageFormatProtobuf - Loaded FSImage in 0 seconds.
19:49:05.970 INFO FSImage - Loaded image for txid 0 from /tmp/minicluster_storage5391834643678571027/name-0-1/current/fsimage_0000000000000000000
19:49:05.970 INFO FSNamesystem - Need to save fs image? false (staleImage=false, haEnabled=false, isRollingUpgrade=false)
19:49:05.970 INFO FSEditLog - Starting log segment at 1
19:49:05.973 INFO NameCache - initialized with 0 entries 0 lookups
19:49:05.973 INFO FSNamesystem - Finished loading FSImage in 7 msecs
19:49:05.974 INFO NameNode - RPC server is binding to localhost:0
19:49:05.974 INFO NameNode - Enable NameNode state context:false
19:49:05.974 INFO CallQueueManager - Using callQueue: class java.util.concurrent.LinkedBlockingQueue, queueCapacity: 1000, scheduler: class org.apache.hadoop.ipc.DefaultRpcScheduler, ipcBackoff: false.
19:49:05.974 INFO Server - Listener at localhost:35533
19:49:05.974 INFO Server - Starting Socket Reader #1 for port 0
19:49:05.976 INFO NameNode - Clients are to use localhost:35533 to access this namenode/service.
19:49:05.976 INFO FSNamesystem - Registered FSNamesystemState, ReplicatedBlocksState and ECBlockGroupsState MBeans.
19:49:05.987 INFO LeaseManager - Number of blocks under construction: 0
19:49:05.987 INFO DatanodeAdminDefaultMonitor - Initialized the Default Decommission and Maintenance monitor
19:49:05.988 INFO BlockManager - Start MarkedDeleteBlockScrubber thread
19:49:05.988 INFO BlockManager - initializing replication queues
19:49:05.988 INFO StateChange - STATE* Leaving safe mode after 0 secs
19:49:05.988 INFO StateChange - STATE* Network topology has 0 racks and 0 datanodes
19:49:05.988 INFO StateChange - STATE* UnderReplicatedBlocks has 0 blocks
19:49:05.992 INFO Server - IPC Server Responder: starting
19:49:05.992 INFO Server - IPC Server listener on 0: starting
19:49:05.994 INFO NameNode - NameNode RPC up at: localhost/127.0.0.1:35533
19:49:05.994 WARN MetricsLoggerTask - Metrics logging will not be async since the logger is not log4j
19:49:05.994 INFO FSNamesystem - Starting services required for active state
19:49:05.994 INFO FSDirectory - Initializing quota with 12 thread(s)
19:49:05.994 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
19:49:05.995 INFO BlockManager - Total number of blocks = 0
19:49:05.995 INFO BlockManager - Number of invalid blocks = 0
19:49:05.995 INFO BlockManager - Number of under-replicated blocks = 0
19:49:05.995 INFO BlockManager - Number of over-replicated blocks = 0
19:49:05.995 INFO BlockManager - Number of blocks being written = 0
19:49:05.995 INFO StateChange - STATE* Replication Queue initialization scan for invalid, over- and under-replicated blocks completed in 6 msec
19:49:05.995 INFO CacheReplicationMonitor - Starting CacheReplicationMonitor with interval 30000 milliseconds
19:49:05.996 INFO MiniDFSCluster - Starting DataNode 0 with dfs.datanode.data.dir: [DISK]file:/tmp/minicluster_storage5391834643678571027/data/data1,[DISK]file:/tmp/minicluster_storage5391834643678571027/data/data2
19:49:05.996 INFO ThrottledAsyncChecker - Scheduling a check for [DISK]file:/tmp/minicluster_storage5391834643678571027/data/data1
19:49:05.996 INFO ThrottledAsyncChecker - Scheduling a check for [DISK]file:/tmp/minicluster_storage5391834643678571027/data/data2
19:49:06.006 INFO MetricsSystemImpl - DataNode metrics system started (again)
19:49:06.006 INFO Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
19:49:06.006 INFO BlockScanner - Initialized block scanner with targetBytesPerSec 1048576
19:49:06.006 INFO DataNode - Configured hostname is 127.0.0.1
19:49:06.006 INFO Util - dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO profiling
19:49:06.006 INFO DataNode - Starting DataNode with maxLockedMemory = 0
19:49:06.007 INFO DataNode - Opened streaming server at /127.0.0.1:34959
19:49:06.007 INFO DataNode - Balancing bandwidth is 104857600 bytes/s
19:49:06.007 INFO DataNode - Number threads for balancing is 100
19:49:06.009 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
19:49:06.009 WARN HttpRequestLog - Jetty request log can only be enabled using Log4j
19:49:06.010 INFO HttpServer2 - Added global filter 'safety' (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter)
19:49:06.010 INFO HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context datanode
19:49:06.010 INFO HttpServer2 - Added filter static_user_filter (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to context static
19:49:06.011 INFO HttpServer2 - Jetty bound to port 34315
19:49:06.011 INFO Server - jetty-9.4.56.v20240826; built: 2024-08-26T17:15:05.868Z; git: ec6782ff5ead824dabdcf47fa98f90a4aedff401; jvm 17.0.6+10
19:49:06.011 INFO session - DefaultSessionIdManager workerName=node0
19:49:06.011 INFO session - No SessionScavenger set, using defaults
19:49:06.011 INFO session - node0 Scavenging every 600000ms
19:49:06.012 INFO ContextHandler - Started o.e.j.s.ServletContextHandler@3b65c6fd{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}
19:49:06.104 INFO ContextHandler - Started o.e.j.w.WebAppContext@be40ce6{datanode,/,file:///tmp/jetty-localhost-34315-hadoop-hdfs-3_3_6-tests_jar-_-any-13083629089021557553/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}
19:49:06.104 INFO AbstractConnector - Started ServerConnector@67eb9567{HTTP/1.1, (http/1.1)}{localhost:34315}
19:49:06.104 INFO Server - Started @77317ms
19:49:06.105 WARN DatanodeHttpServer - Got null for restCsrfPreventionFilter - will not do any filtering.
19:49:06.105 INFO DatanodeHttpServer - Listening HTTP traffic on /127.0.0.1:42689
19:49:06.106 INFO DataNode - dnUserName = runner
19:49:06.106 INFO DataNode - supergroup = supergroup
19:49:06.106 INFO JvmPauseMonitor - Starting JVM pause monitor
19:49:06.106 INFO CallQueueManager - Using callQueue: class java.util.concurrent.LinkedBlockingQueue, queueCapacity: 1000, scheduler: class org.apache.hadoop.ipc.DefaultRpcScheduler, ipcBackoff: false.
19:49:06.106 INFO Server - Listener at localhost:34841
19:49:06.106 INFO Server - Starting Socket Reader #1 for port 0
19:49:06.108 INFO DataNode - Opened IPC server at /127.0.0.1:34841
19:49:06.117 INFO DataNode - Refresh request received for nameservices: null
19:49:06.117 INFO DataNode - Starting BPOfferServices for nameservices: <default>
19:49:06.118 WARN MetricsLoggerTask - Metrics logging will not be async since the logger is not log4j
19:49:06.118 INFO DataNode - Block pool <registering> (Datanode Uuid unassigned) service to localhost/127.0.0.1:35533 starting to offer service
19:49:06.118 INFO Server - IPC Server Responder: starting
19:49:06.118 INFO Server - IPC Server listener on 0: starting
19:49:06.119 INFO DataNode - Acknowledging ACTIVE Namenode during handshakeBlock pool <registering> (Datanode Uuid unassigned) service to localhost/127.0.0.1:35533
19:49:06.119 INFO Storage - Using 2 threads to upgrade data directories (dfs.datanode.parallel.volumes.load.threads.num=2, dataDirs=2)
19:49:06.120 INFO Storage - Lock on /tmp/minicluster_storage5391834643678571027/data/data1/in_use.lock acquired by nodename 3162@pkrvmq0rgcvqdmg
19:49:06.120 INFO Storage - Storage directory with location [DISK]file:/tmp/minicluster_storage5391834643678571027/data/data1 is not formatted for namespace 540563428. Formatting...
19:49:06.120 INFO Storage - Generated new storageID DS-efa00c3d-c33b-4e42-b938-46c73b92a6a7 for directory /tmp/minicluster_storage5391834643678571027/data/data1
19:49:06.121 INFO audit - allowed=true ugi=runner (auth:SIMPLE) ip=/127.0.0.1 cmd=datanodeReport src=null dst=null perm=null proto=rpc
19:49:06.121 INFO MiniDFSCluster - dnInfo.length != numDataNodes
19:49:06.121 INFO MiniDFSCluster - Waiting for cluster to become active
19:49:06.122 INFO Storage - Lock on /tmp/minicluster_storage5391834643678571027/data/data2/in_use.lock acquired by nodename 3162@pkrvmq0rgcvqdmg
19:49:06.122 INFO Storage - Storage directory with location [DISK]file:/tmp/minicluster_storage5391834643678571027/data/data2 is not formatted for namespace 540563428. Formatting...
19:49:06.122 INFO Storage - Generated new storageID DS-62c25f49-00b4-481d-b7bb-6344f3ecd7f1 for directory /tmp/minicluster_storage5391834643678571027/data/data2
19:49:06.134 INFO Storage - Analyzing storage directories for bpid BP-213204104-10.1.0.127-1752608945800
19:49:06.134 INFO Storage - Locking is disabled for /tmp/minicluster_storage5391834643678571027/data/data1/current/BP-213204104-10.1.0.127-1752608945800
19:49:06.134 INFO Storage - Block pool storage directory for location [DISK]file:/tmp/minicluster_storage5391834643678571027/data/data1 and block pool id BP-213204104-10.1.0.127-1752608945800 is not formatted. Formatting ...
19:49:06.134 INFO Storage - Formatting block pool BP-213204104-10.1.0.127-1752608945800 directory /tmp/minicluster_storage5391834643678571027/data/data1/current/BP-213204104-10.1.0.127-1752608945800/current
19:49:06.146 INFO Storage - Analyzing storage directories for bpid BP-213204104-10.1.0.127-1752608945800
19:49:06.146 INFO Storage - Locking is disabled for /tmp/minicluster_storage5391834643678571027/data/data2/current/BP-213204104-10.1.0.127-1752608945800
19:49:06.146 INFO Storage - Block pool storage directory for location [DISK]file:/tmp/minicluster_storage5391834643678571027/data/data2 and block pool id BP-213204104-10.1.0.127-1752608945800 is not formatted. Formatting ...
19:49:06.146 INFO Storage - Formatting block pool BP-213204104-10.1.0.127-1752608945800 directory /tmp/minicluster_storage5391834643678571027/data/data2/current/BP-213204104-10.1.0.127-1752608945800/current
19:49:06.147 INFO DataNode - Setting up storage: nsid=540563428;bpid=BP-213204104-10.1.0.127-1752608945800;lv=-57;nsInfo=lv=-66;cid=testClusterID;nsid=540563428;c=1752608945800;bpid=BP-213204104-10.1.0.127-1752608945800;dnuuid=null
19:49:06.148 INFO DataNode - Generated and persisted new Datanode UUID 14141d0d-ea51-4e88-9669-859319118de8
19:49:06.148 INFO FsDatasetImpl - The datanode lock is a read write lock
19:49:06.149 INFO FsDatasetImpl - Added new volume: DS-efa00c3d-c33b-4e42-b938-46c73b92a6a7
19:49:06.149 INFO FsDatasetImpl - Added volume - [DISK]file:/tmp/minicluster_storage5391834643678571027/data/data1, StorageType: DISK
19:49:06.149 INFO FsDatasetImpl - Added new volume: DS-62c25f49-00b4-481d-b7bb-6344f3ecd7f1
19:49:06.149 INFO FsDatasetImpl - Added volume - [DISK]file:/tmp/minicluster_storage5391834643678571027/data/data2, StorageType: DISK
19:49:06.149 INFO MemoryMappableBlockLoader - Initializing cache loader: MemoryMappableBlockLoader.
19:49:06.150 INFO FsDatasetImpl - Registered FSDatasetState MBean
19:49:06.150 INFO FsDatasetImpl - Adding block pool BP-213204104-10.1.0.127-1752608945800
19:49:06.150 INFO FsDatasetImpl - Scanning block pool BP-213204104-10.1.0.127-1752608945800 on volume /tmp/minicluster_storage5391834643678571027/data/data1...
19:49:06.151 INFO FsDatasetImpl - Scanning block pool BP-213204104-10.1.0.127-1752608945800 on volume /tmp/minicluster_storage5391834643678571027/data/data2...
19:49:06.151 WARN FsDatasetImpl - dfsUsed file missing in /tmp/minicluster_storage5391834643678571027/data/data1/current/BP-213204104-10.1.0.127-1752608945800/current, will proceed with Du for space computation calculation,
19:49:06.151 WARN FsDatasetImpl - dfsUsed file missing in /tmp/minicluster_storage5391834643678571027/data/data2/current/BP-213204104-10.1.0.127-1752608945800/current, will proceed with Du for space computation calculation,
19:49:06.163 INFO FsDatasetImpl - Time taken to scan block pool BP-213204104-10.1.0.127-1752608945800 on /tmp/minicluster_storage5391834643678571027/data/data1: 13ms
19:49:06.163 INFO FsDatasetImpl - Time taken to scan block pool BP-213204104-10.1.0.127-1752608945800 on /tmp/minicluster_storage5391834643678571027/data/data2: 12ms
19:49:06.163 INFO FsDatasetImpl - Total time to scan all replicas for block pool BP-213204104-10.1.0.127-1752608945800: 13ms
19:49:06.164 INFO FsDatasetImpl - Adding replicas to map for block pool BP-213204104-10.1.0.127-1752608945800 on volume /tmp/minicluster_storage5391834643678571027/data/data1...
19:49:06.164 INFO BlockPoolSlice - Replica Cache file: /tmp/minicluster_storage5391834643678571027/data/data1/current/BP-213204104-10.1.0.127-1752608945800/current/replicas doesn't exist
19:49:06.164 INFO FsDatasetImpl - Adding replicas to map for block pool BP-213204104-10.1.0.127-1752608945800 on volume /tmp/minicluster_storage5391834643678571027/data/data2...
19:49:06.164 INFO BlockPoolSlice - Replica Cache file: /tmp/minicluster_storage5391834643678571027/data/data2/current/BP-213204104-10.1.0.127-1752608945800/current/replicas doesn't exist
19:49:06.164 INFO FsDatasetImpl - Time to add replicas to map for block pool BP-213204104-10.1.0.127-1752608945800 on volume /tmp/minicluster_storage5391834643678571027/data/data1: 0ms
19:49:06.164 INFO FsDatasetImpl - Time to add replicas to map for block pool BP-213204104-10.1.0.127-1752608945800 on volume /tmp/minicluster_storage5391834643678571027/data/data2: 0ms
19:49:06.164 INFO FsDatasetImpl - Total time to add all replicas to map for block pool BP-213204104-10.1.0.127-1752608945800: 1ms
19:49:06.164 INFO ThrottledAsyncChecker - Scheduling a check for /tmp/minicluster_storage5391834643678571027/data/data1
19:49:06.164 INFO DatasetVolumeChecker - Scheduled health check for volume /tmp/minicluster_storage5391834643678571027/data/data1
19:49:06.164 INFO ThrottledAsyncChecker - Scheduling a check for /tmp/minicluster_storage5391834643678571027/data/data2
19:49:06.164 INFO DatasetVolumeChecker - Scheduled health check for volume /tmp/minicluster_storage5391834643678571027/data/data2
19:49:06.165 INFO VolumeScanner - Now scanning bpid BP-213204104-10.1.0.127-1752608945800 on volume /tmp/minicluster_storage5391834643678571027/data/data2
19:49:06.165 INFO VolumeScanner - Now scanning bpid BP-213204104-10.1.0.127-1752608945800 on volume /tmp/minicluster_storage5391834643678571027/data/data1
19:49:06.165 INFO VolumeScanner - VolumeScanner(/tmp/minicluster_storage5391834643678571027/data/data1, DS-efa00c3d-c33b-4e42-b938-46c73b92a6a7): finished scanning block pool BP-213204104-10.1.0.127-1752608945800
19:49:06.165 INFO VolumeScanner - VolumeScanner(/tmp/minicluster_storage5391834643678571027/data/data2, DS-62c25f49-00b4-481d-b7bb-6344f3ecd7f1): finished scanning block pool BP-213204104-10.1.0.127-1752608945800
19:49:06.165 INFO VolumeScanner - VolumeScanner(/tmp/minicluster_storage5391834643678571027/data/data2, DS-62c25f49-00b4-481d-b7bb-6344f3ecd7f1): no suitable block pools found to scan. Waiting 1814400000 ms.
19:49:06.165 INFO VolumeScanner - VolumeScanner(/tmp/minicluster_storage5391834643678571027/data/data1, DS-efa00c3d-c33b-4e42-b938-46c73b92a6a7): no suitable block pools found to scan. Waiting 1814400000 ms.
19:49:06.165 WARN DirectoryScanner - dfs.datanode.directoryscan.throttle.limit.ms.per.sec set to value above 1000 ms/sec. Assuming default value of -1
19:49:06.165 INFO DirectoryScanner - Periodic Directory Tree Verification scan starting in 6027856ms with interval of 21600000ms and throttle limit of -1ms/s
19:49:06.165 INFO DataNode - Block pool BP-213204104-10.1.0.127-1752608945800 (Datanode Uuid 14141d0d-ea51-4e88-9669-859319118de8) service to localhost/127.0.0.1:35533 beginning handshake with NN
19:49:06.166 INFO StateChange - BLOCK* registerDatanode: from DatanodeRegistration(127.0.0.1:34959, datanodeUuid=14141d0d-ea51-4e88-9669-859319118de8, infoPort=42689, infoSecurePort=0, ipcPort=34841, storageInfo=lv=-57;cid=testClusterID;nsid=540563428;c=1752608945800) storage 14141d0d-ea51-4e88-9669-859319118de8
19:49:06.166 INFO NetworkTopology - Adding a new node: /default-rack/127.0.0.1:34959
19:49:06.166 INFO BlockReportLeaseManager - Registered DN 14141d0d-ea51-4e88-9669-859319118de8 (127.0.0.1:34959).
19:49:06.166 INFO DataNode - Block pool BP-213204104-10.1.0.127-1752608945800 (Datanode Uuid 14141d0d-ea51-4e88-9669-859319118de8) service to localhost/127.0.0.1:35533 successfully registered with NN
19:49:06.166 INFO DataNode - For namenode localhost/127.0.0.1:35533 using BLOCKREPORT_INTERVAL of 21600000msecs CACHEREPORT_INTERVAL of 10000msecs Initial delay: 0msecs; heartBeatInterval=3000
19:49:06.166 INFO DataNode - Starting IBR Task Handler.
19:49:06.167 INFO DatanodeDescriptor - Adding new storage ID DS-efa00c3d-c33b-4e42-b938-46c73b92a6a7 for DN 127.0.0.1:34959
19:49:06.167 INFO DatanodeDescriptor - Adding new storage ID DS-62c25f49-00b4-481d-b7bb-6344f3ecd7f1 for DN 127.0.0.1:34959
19:49:06.167 INFO DataNode - After receiving heartbeat response, updating state of namenode localhost:35533 to active
19:49:06.168 INFO BlockStateChange - BLOCK* processReport 0xd0e8e1baf95447ff with lease ID 0x7c5ce10c4d4b3609: Processing first storage report for DS-62c25f49-00b4-481d-b7bb-6344f3ecd7f1 from datanode DatanodeRegistration(127.0.0.1:34959, datanodeUuid=14141d0d-ea51-4e88-9669-859319118de8, infoPort=42689, infoSecurePort=0, ipcPort=34841, storageInfo=lv=-57;cid=testClusterID;nsid=540563428;c=1752608945800)
19:49:06.168 INFO BlockStateChange - BLOCK* processReport 0xd0e8e1baf95447ff with lease ID 0x7c5ce10c4d4b3609: from storage DS-62c25f49-00b4-481d-b7bb-6344f3ecd7f1 node DatanodeRegistration(127.0.0.1:34959, datanodeUuid=14141d0d-ea51-4e88-9669-859319118de8, infoPort=42689, infoSecurePort=0, ipcPort=34841, storageInfo=lv=-57;cid=testClusterID;nsid=540563428;c=1752608945800), blocks: 0, hasStaleStorage: true, processing time: 0 msecs, invalidatedBlocks: 0
19:49:06.168 INFO BlockStateChange - BLOCK* processReport 0xd0e8e1baf95447ff with lease ID 0x7c5ce10c4d4b3609: Processing first storage report for DS-efa00c3d-c33b-4e42-b938-46c73b92a6a7 from datanode DatanodeRegistration(127.0.0.1:34959, datanodeUuid=14141d0d-ea51-4e88-9669-859319118de8, infoPort=42689, infoSecurePort=0, ipcPort=34841, storageInfo=lv=-57;cid=testClusterID;nsid=540563428;c=1752608945800)
19:49:06.168 INFO BlockStateChange - BLOCK* processReport 0xd0e8e1baf95447ff with lease ID 0x7c5ce10c4d4b3609: from storage DS-efa00c3d-c33b-4e42-b938-46c73b92a6a7 node DatanodeRegistration(127.0.0.1:34959, datanodeUuid=14141d0d-ea51-4e88-9669-859319118de8, infoPort=42689, infoSecurePort=0, ipcPort=34841, storageInfo=lv=-57;cid=testClusterID;nsid=540563428;c=1752608945800), blocks: 0, hasStaleStorage: false, processing time: 0 msecs, invalidatedBlocks: 0
19:49:06.168 INFO DataNode - Successfully sent block report 0xd0e8e1baf95447ff with lease ID 0x7c5ce10c4d4b3609 to namenode: localhost/127.0.0.1:35533, 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.
19:49:06.168 INFO DataNode - Got finalize command for block pool BP-213204104-10.1.0.127-1752608945800
19:49:06.222 INFO audit - allowed=true ugi=runner (auth:SIMPLE) ip=/127.0.0.1 cmd=datanodeReport src=null dst=null perm=null proto=rpc
19:49:06.222 INFO MiniDFSCluster - Cluster is active
19:49:06.229 INFO MemoryStore - Block broadcast_616 stored as values in memory (estimated size 3.0 KiB, free 1920.0 MiB)
19:49:06.230 INFO MemoryStore - Block broadcast_616_piece0 stored as bytes in memory (estimated size 525.0 B, free 1920.0 MiB)
19:49:06.230 INFO BlockManagerInfo - Added broadcast_616_piece0 in memory on localhost:36125 (size: 525.0 B, free: 1920.0 MiB)
19:49:06.230 INFO SparkContext - Created broadcast 616 from broadcast at VcfSink.java:65
19:49:06.234 INFO PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
19:49:06.234 INFO FileOutputCommitter - File Output Committer Algorithm version is 1
19:49:06.234 INFO FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
19:49:06.251 INFO SparkContext - Starting job: runJob at SparkHadoopWriter.scala:83
19:49:06.251 INFO DAGScheduler - Registering RDD 1485 (mapToPair at VariantsSparkSink.java:140) as input to shuffle 53
19:49:06.252 INFO DAGScheduler - Got job 228 (runJob at SparkHadoopWriter.scala:83) with 1 output partitions
19:49:06.252 INFO DAGScheduler - Final stage: ResultStage 293 (runJob at SparkHadoopWriter.scala:83)
19:49:06.252 INFO DAGScheduler - Parents of final stage: List(ShuffleMapStage 292)
19:49:06.252 INFO DAGScheduler - Missing parents: List(ShuffleMapStage 292)
19:49:06.252 INFO DAGScheduler - Submitting ShuffleMapStage 292 (MapPartitionsRDD[1485] at mapToPair at VariantsSparkSink.java:140), which has no missing parents
19:49:06.253 INFO MemoryStore - Block broadcast_617 stored as values in memory (estimated size 6.5 KiB, free 1920.0 MiB)
19:49:06.253 INFO MemoryStore - Block broadcast_617_piece0 stored as bytes in memory (estimated size 3.7 KiB, free 1920.0 MiB)
19:49:06.253 INFO BlockManagerInfo - Added broadcast_617_piece0 in memory on localhost:36125 (size: 3.7 KiB, free: 1920.0 MiB)
19:49:06.254 INFO SparkContext - Created broadcast 617 from broadcast at DAGScheduler.scala:1580
19:49:06.254 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))
19:49:06.254 INFO TaskSchedulerImpl - Adding task set 292.0 with 4 tasks resource profile 0
19:49:06.255 INFO TaskSetManager - Starting task 0.0 in stage 292.0 (TID 379) (localhost, executor driver, partition 0, PROCESS_LOCAL, 8087 bytes)
19:49:06.255 INFO TaskSetManager - Starting task 1.0 in stage 292.0 (TID 380) (localhost, executor driver, partition 1, PROCESS_LOCAL, 8193 bytes)
19:49:06.256 INFO TaskSetManager - Starting task 2.0 in stage 292.0 (TID 381) (localhost, executor driver, partition 2, PROCESS_LOCAL, 8087 bytes)
19:49:06.256 INFO TaskSetManager - Starting task 3.0 in stage 292.0 (TID 382) (localhost, executor driver, partition 3, PROCESS_LOCAL, 8193 bytes)
19:49:06.256 INFO Executor - Running task 0.0 in stage 292.0 (TID 379)
19:49:06.256 INFO Executor - Running task 3.0 in stage 292.0 (TID 382)
19:49:06.256 INFO Executor - Running task 2.0 in stage 292.0 (TID 381)
19:49:06.257 INFO Executor - Running task 1.0 in stage 292.0 (TID 380)
19:49:06.268 INFO Executor - Finished task 3.0 in stage 292.0 (TID 382). 1062 bytes result sent to driver
19:49:06.270 INFO Executor - Finished task 0.0 in stage 292.0 (TID 379). 1062 bytes result sent to driver
19:49:06.271 INFO TaskSetManager - Finished task 3.0 in stage 292.0 (TID 382) in 15 ms on localhost (executor driver) (1/4)
19:49:06.271 INFO TaskSetManager - Finished task 0.0 in stage 292.0 (TID 379) in 17 ms on localhost (executor driver) (2/4)
19:49:06.272 INFO Executor - Finished task 2.0 in stage 292.0 (TID 381). 1062 bytes result sent to driver
19:49:06.272 INFO Executor - Finished task 1.0 in stage 292.0 (TID 380). 1062 bytes result sent to driver
19:49:06.272 INFO TaskSetManager - Finished task 2.0 in stage 292.0 (TID 381) in 17 ms on localhost (executor driver) (3/4)
19:49:06.272 INFO TaskSetManager - Finished task 1.0 in stage 292.0 (TID 380) in 17 ms on localhost (executor driver) (4/4)
19:49:06.273 INFO TaskSchedulerImpl - Removed TaskSet 292.0, whose tasks have all completed, from pool
19:49:06.273 INFO DAGScheduler - ShuffleMapStage 292 (mapToPair at VariantsSparkSink.java:140) finished in 0.021 s
19:49:06.273 INFO DAGScheduler - looking for newly runnable stages
19:49:06.273 INFO DAGScheduler - running: HashSet()
19:49:06.273 INFO DAGScheduler - waiting: HashSet(ResultStage 293)
19:49:06.273 INFO DAGScheduler - failed: HashSet()
19:49:06.273 INFO DAGScheduler - Submitting ResultStage 293 (MapPartitionsRDD[1489] at mapToPair at VcfSink.java:77), which has no missing parents
19:49:06.279 INFO MemoryStore - Block broadcast_618 stored as values in memory (estimated size 149.6 KiB, free 1919.8 MiB)
19:49:06.280 INFO MemoryStore - Block broadcast_618_piece0 stored as bytes in memory (estimated size 56.1 KiB, free 1919.8 MiB)
19:49:06.280 INFO BlockManagerInfo - Added broadcast_618_piece0 in memory on localhost:36125 (size: 56.1 KiB, free: 1919.9 MiB)
19:49:06.281 INFO SparkContext - Created broadcast 618 from broadcast at DAGScheduler.scala:1580
19:49:06.281 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))
19:49:06.281 INFO TaskSchedulerImpl - Adding task set 293.0 with 1 tasks resource profile 0
19:49:06.281 INFO TaskSetManager - Starting task 0.0 in stage 293.0 (TID 383) (localhost, executor driver, partition 0, NODE_LOCAL, 7513 bytes)
19:49:06.281 INFO Executor - Running task 0.0 in stage 293.0 (TID 383)
19:49:06.286 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
19:49:06.287 INFO ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
19:49:06.292 INFO PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
19:49:06.292 INFO FileOutputCommitter - File Output Committer Algorithm version is 1
19:49:06.292 INFO FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
19:49:06.292 INFO PathOutputCommitterFactory - No output committer factory defined, defaulting to FileOutputCommitterFactory
19:49:06.292 INFO FileOutputCommitter - File Output Committer Algorithm version is 1
19:49:06.292 INFO FileOutputCommitter - FileOutputCommitter skip cleanup _temporary folders under output directory:false, ignore cleanup failures: false
19:49:06.305 INFO FileOutputCommitter - Saved output of task 'attempt_20250715194906472278477651645746_1489_r_000000_0' to file:/tmp/VariantsSparkSinkUnitTest13070052158165970983.vcf.parts/_temporary/0/task_20250715194906472278477651645746_1489_r_000000
19:49:06.306 INFO SparkHadoopMapRedUtil - attempt_20250715194906472278477651645746_1489_r_000000_0: Committed. Elapsed time: 0 ms.
19:49:06.306 INFO Executor - Finished task 0.0 in stage 293.0 (TID 383). 1858 bytes result sent to driver
19:49:06.306 INFO TaskSetManager - Finished task 0.0 in stage 293.0 (TID 383) in 25 ms on localhost (executor driver) (1/1)
19:49:06.306 INFO TaskSchedulerImpl - Removed TaskSet 293.0, whose tasks have all completed, from pool
19:49:06.307 INFO DAGScheduler - ResultStage 293 (runJob at SparkHadoopWriter.scala:83) finished in 0.034 s
19:49:06.307 INFO DAGScheduler - Job 228 is finished. Cancelling potential speculative or zombie tasks for this job
19:49:06.307 INFO TaskSchedulerImpl - Killing all running tasks in stage 293: Stage finished
19:49:06.307 INFO DAGScheduler - Job 228 finished: runJob at SparkHadoopWriter.scala:83, took 0.055884 s
19:49:06.307 INFO SparkHadoopWriter - Start to commit write Job job_20250715194906472278477651645746_1489.
19:49:06.312 INFO SparkHadoopWriter - Write Job job_20250715194906472278477651645746_1489 committed. Elapsed time: 4 ms.
19:49:06.320 INFO HadoopFileSystemWrapper - Concatenating 2 parts to /tmp/VariantsSparkSinkUnitTest13070052158165970983.vcf
19:49:06.324 INFO HadoopFileSystemWrapper - Concatenating to /tmp/VariantsSparkSinkUnitTest13070052158165970983.vcf done
[July 15, 2025 at 7:49:06 PM UTC] org.broadinstitute.hellbender.tools.IndexFeatureFile done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=622854144
[July 15, 2025 at 7:49:06 PM UTC] org.broadinstitute.hellbender.tools.IndexFeatureFile done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=622854144
[July 15, 2025 at 7:49:06 PM UTC] org.broadinstitute.hellbender.tools.IndexFeatureFile done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=622854144
[July 15, 2025 at 7:49:06 PM UTC] org.broadinstitute.hellbender.tools.IndexFeatureFile done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=622854144