[
https://issues.apache.org/jira/browse/HDFS-13837?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Xiao Chen updated HDFS-13837:
-----------------------------
Summary: Enable debug log for LeaseRenewer in TestDistributedFileSystem
(was: hdfs.TestDistributedFileSystem.testDFSClient: test is flaky)
> Enable debug log for LeaseRenewer in TestDistributedFileSystem
> --------------------------------------------------------------
>
> Key: HDFS-13837
> URL: https://issues.apache.org/jira/browse/HDFS-13837
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: hdfs
> Affects Versions: 3.2.0
> Reporter: Shweta
> Assignee: Shweta
> Priority: Major
> Attachments: HDFS-13837.001.patch, HDFS-13837.002.patch,
> HDFS-13837.003.patch, HDFS-13837.004.patch,
> TestDistributedFileSystem.testDFSClient_Stderr_log
>
>
> Stack Trace :
> {noformat}
> java.lang.AssertionError
> at
> org.apache.hadoop.hdfs.TestDistributedFileSystem.testDFSClient(TestDistributedFileSystem.java:449)
> {noformat}
> Stdout:
> {noformat}
> [truncated]kmanagement.BlockManager
> (BlockManager.java:processMisReplicatesAsync(3385)) - Number of blocks being
> written = 0
> 2018-07-31 21:42:46,675 [Reconstruction Queue Initializer] INFO
> hdfs.StateChange (BlockManager.java:processMisReplicatesAsync(3388)) - STATE*
> Replication Queue initialization scan for invalid, over- and under-replicated
> blocks completed in 5 msec
> 2018-07-31 21:42:46,676 [IPC Server Responder] INFO ipc.Server
> (Server.java:run(1307)) - IPC Server Responder: starting
> 2018-07-31 21:42:46,676 [IPC Server listener on port1] INFO ipc.Server
> (Server.java:run(1146)) - IPC Server listener on port1: starting
> 2018-07-31 21:42:46,678 [main] INFO namenode.NameNode
> (NameNode.java:startCommonServices(831)) - NameNode RPC up at:
> localhost/x.x.x.x:port1
> 2018-07-31 21:42:46,678 [main] INFO namenode.FSNamesystem
> (FSNamesystem.java:startActiveServices(1230)) - Starting services required
> for active state
> 2018-07-31 21:42:46,678 [main] INFO namenode.FSDirectory
> (FSDirectory.java:updateCountForQuota(758)) - Initializing quota with 4
> thread(s)
> 2018-07-31 21:42:46,679 [main] INFO namenode.FSDirectory
> (FSDirectory.java:updateCountForQuota(767)) - Quota initialization completed
> in 0 milliseconds
> name space=1
> storage space=0
> storage types=RAM_DISK=0, SSD=0, DISK=0, ARCHIVE=0
> 2018-07-31 21:42:46,682 [CacheReplicationMonitor(1111752355)] INFO
> blockmanagement.CacheReplicationMonitor
> (CacheReplicationMonitor.java:run(160)) - Starting CacheReplicationMonitor
> with interval 30000 milliseconds
> 2018-07-31 21:42:46,686 [main] INFO hdfs.MiniDFSCluster
> (MiniDFSCluster.java:startDataNodes(1599)) - Starting DataNode 0 with
> dfs.datanode.data.dir:
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1,[DISK][file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2|file:///tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2]
> 2018-07-31 21:42:46,687 [main] INFO checker.ThrottledAsyncChecker
> (ThrottledAsyncChecker.java:schedule(122)) - Scheduling a check for
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1
> 2018-07-31 21:42:46,687 [main] INFO checker.ThrottledAsyncChecker
> (ThrottledAsyncChecker.java:schedule(122)) - Scheduling a check for
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2
> 2018-07-31 21:42:46,695 [main] INFO impl.MetricsSystemImpl
> (MetricsSystemImpl.java:init(158)) - DataNode metrics system started (again)
> 2018-07-31 21:42:46,695 [main] INFO common.Util
> (Util.java:isDiskStatsEnabled(395)) -
> dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO
> profiling
> 2018-07-31 21:42:46,695 [main] INFO datanode.BlockScanner
> (BlockScanner.java:<init>(184)) - Initialized block scanner with
> targetBytesPerSec 1048576
> 2018-07-31 21:42:46,696 [main] INFO datanode.DataNode
> (DataNode.java:<init>(496)) - Configured hostname is x.x.x.x
> 2018-07-31 21:42:46,696 [main] INFO common.Util
> (Util.java:isDiskStatsEnabled(395)) -
> dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO
> profiling
> 2018-07-31 21:42:46,696 [main] INFO datanode.DataNode
> (DataNode.java:startDataNode(1385)) - Starting DataNode with maxLockedMemory
> = 0
> 2018-07-31 21:42:46,697 [main] INFO datanode.DataNode
> (DataNode.java:initDataXceiver(1142)) - Opened streaming server at
> /x.x.x.x:port2
> 2018-07-31 21:42:46,697 [main] INFO datanode.DataNode
> (DataXceiverServer.java:<init>(78)) - Balancing bandwidth is 10485760 bytes/s
> 2018-07-31 21:42:46,697 [main] INFO datanode.DataNode
> (DataXceiverServer.java:<init>(79)) - Number threads for balancing is 50
> 2018-07-31 21:42:46,699 [main] INFO server.AuthenticationFilter
> (AuthenticationFilter.java:constructSecretProvider(240)) - Unable to
> initialize FileSignerSecretProvider, falling back to use random secrets.
> 2018-07-31 21:42:46,699 [main] INFO http.HttpRequestLog
> (HttpRequestLog.java:getRequestLog(81)) - Http request log for
> http.requests.datanode is not defined
> 2018-07-31 21:42:46,700 [main] INFO http.HttpServer2
> (HttpServer2.java:addGlobalFilter(923)) - Added global filter 'safety'
> (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter)
> 2018-07-31 21:42:46,701 [main] INFO http.HttpServer2
> (HttpServer2.java:addFilter(896)) - Added filter static_user_filter
> (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to
> context datanode
> 2018-07-31 21:42:46,701 [main] INFO http.HttpServer2
> (HttpServer2.java:addFilter(906)) - Added filter static_user_filter
> (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to
> context static
> 2018-07-31 21:42:46,701 [main] INFO http.HttpServer2
> (HttpServer2.java:addFilter(906)) - Added filter static_user_filter
> (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to
> context logs
> 2018-07-31 21:42:46,702 [main] INFO http.HttpServer2
> (HttpServer2.java:bindListener(1123)) - Jetty bound to port 35341
> 2018-07-31 21:42:46,702 [main] INFO server.Server (Server.java:doStart(346))
> - jetty-9.3.20.v20170531
> 2018-07-31 21:42:46,704 [main] INFO handler.ContextHandler
> (ContextHandler.java:doStart(781)) - Started
> o.e.j.s.ServletContextHandler@38b5f25
> {/logs,file:///tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/log/,AVAILABLE}
> 2018-07-31 21:42:46,705 [main] INFO handler.ContextHandler
> (ContextHandler.java:doStart(781)) - Started
> o.e.j.s.ServletContextHandler@67594471
> {/static,file:///tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test-classes/webapps/static/,AVAILABLE}
> 2018-07-31 21:42:46,711 [main] INFO handler.ContextHandler
> (ContextHandler.java:doStart(781)) - Started o.e.j.w.WebAppContext@68fe48d7
> {/,file:///tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test-classes/webapps/datanode/,AVAILABLE}
> \{/datanode}
> 2018-07-31 21:42:46,712 [main] INFO server.AbstractConnector
> (AbstractConnector.java:doStart(278)) - Started
> ServerConnector@379ce046\{HTTP/1.1,[http/1.1]}{localhost:35341}
> 2018-07-31 21:42:46,712 [main] INFO server.Server (Server.java:doStart(414))
> - Started @27029ms
> 2018-07-31 21:42:46,715 [main] INFO web.DatanodeHttpServer
> (DatanodeHttpServer.java:start(239)) - Listening HTTP traffic on
> /x.x.x.x:port3
> 2018-07-31 21:42:46,716 [main] INFO datanode.DataNode
> (DataNode.java:startDataNode(1412)) - dnUserName = jenkins
> 2018-07-31 21:42:46,716
> [org.apache.hadoop.util.JvmPauseMonitor$Monitor@10acd6] INFO
> util.JvmPauseMonitor (JvmPauseMonitor.java:run(188)) - Starting JVM pause
> monitor
> 2018-07-31 21:42:46,716 [main] INFO datanode.DataNode
> (DataNode.java:startDataNode(1413)) - supergroup = supergroup
> 2018-07-31 21:42:46,717 [main] INFO ipc.CallQueueManager
> (CallQueueManager.java:<init>(84)) - Using callQueue: class
> java.util.concurrent.LinkedBlockingQueue queueCapacity: 1000 scheduler: class
> org.apache.hadoop.ipc.DefaultRpcScheduler
> 2018-07-31 21:42:46,718 [Socket Reader #1 for port port4|#1 for port port4]
> INFO ipc.Server (Server.java:run(1067)) - Starting Socket Reader #1 for port
> port4
> 2018-07-31 21:42:46,719 [main] INFO datanode.DataNode
> (DataNode.java:initIpcServer(1029)) - Opened IPC server at /x.x.x.x:port4
> 2018-07-31 21:42:46,721 [main] INFO datanode.DataNode
> (BlockPoolManager.java:refreshNamenodes(149)) - Refresh request received for
> nameservices: null
> 2018-07-31 21:42:46,721 [main] INFO datanode.DataNode
> (BlockPoolManager.java:doRefreshNamenodes(198)) - Starting BPOfferServices
> for nameservices: <default>
> 2018-07-31 21:42:46,722 [Thread-2206] INFO datanode.DataNode
> (BPServiceActor.java:run(809)) - Block pool <registering> (Datanode Uuid
> unassigned) service to localhost/x.x.x.x:port1 starting to offer service
> 2018-07-31 21:42:46,724 [IPC Server Responder] INFO ipc.Server
> (Server.java:run(1307)) - IPC Server Responder: starting
> 2018-07-31 21:42:46,726 [IPC Server listener on port4] INFO ipc.Server
> (Server.java:run(1146)) - IPC Server listener on port4: starting
> 2018-07-31 21:42:46,729 [main] INFO hdfs.MiniDFSCluster
> (MiniDFSCluster.java:startDataNodes(1599)) - Starting DataNode 1 with
> dfs.datanode.data.dir:
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3,[DISK][file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4|file:///tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4]
> 2018-07-31 21:42:46,730 [Thread-2206] INFO datanode.DataNode
> (BPOfferService.java:verifyAndSetNamespaceInfo(378)) - Acknowledging ACTIVE
> Namenode during handshakeBlock pool <registering> (Datanode Uuid unassigned)
> service to localhost/x.x.x.x:port1
> 2018-07-31 21:42:46,730 [main] INFO checker.ThrottledAsyncChecker
> (ThrottledAsyncChecker.java:schedule(122)) - Scheduling a check for
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3
> 2018-07-31 21:42:46,731 [main] INFO checker.ThrottledAsyncChecker
> (ThrottledAsyncChecker.java:schedule(122)) - Scheduling a check for
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4
> 2018-07-31 21:42:46,732 [Thread-2206] INFO common.Storage
> (DataStorage.java:getParallelVolumeLoadThreadsNum(346)) - Using 2 threads to
> upgrade data directories (dfs.datanode.parallel.volumes.load.threads.num=2,
> dataDirs=2)
> 2018-07-31 21:42:46,735 [Thread-2206] INFO common.Storage
> (Storage.java:tryLock(847)) - Lock on
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1/in_use.lock
> acquired by nodename 7...@quasar-ztplxb-1.vpc.cloudera.com
> 2018-07-31 21:42:46,736 [Thread-2206] INFO common.Storage
> (DataStorage.java:loadStorageDirectory(273)) - Storage directory with
> location
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1
> is not formatted for namespace 1027244560. Formatting...
> 2018-07-31 21:42:46,736 [Thread-2206] INFO common.Storage
> (DataStorage.java:createStorageID(150)) - Generated new storageID
> DS-1d19d47a-b472-463a-a1ed-43be073676f5 for directory
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1
> 2018-07-31 21:42:46,740 [main] INFO impl.MetricsSystemImpl
> (MetricsSystemImpl.java:init(158)) - DataNode metrics system started (again)
> 2018-07-31 21:42:46,740 [main] INFO common.Util
> (Util.java:isDiskStatsEnabled(395)) -
> dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO
> profiling
> 2018-07-31 21:42:46,740 [main] INFO datanode.BlockScanner
> (BlockScanner.java:<init>(184)) - Initialized block scanner with
> targetBytesPerSec 1048576
> 2018-07-31 21:42:46,740 [main] INFO datanode.DataNode
> (DataNode.java:<init>(496)) - Configured hostname is x.x.x.x
> 2018-07-31 21:42:46,741 [main] INFO common.Util
> (Util.java:isDiskStatsEnabled(395)) -
> dfs.datanode.fileio.profiling.sampling.percentage set to 0. Disabling file IO
> profiling
> 2018-07-31 21:42:46,741 [main] INFO datanode.DataNode
> (DataNode.java:startDataNode(1385)) - Starting DataNode with maxLockedMemory
> = 0
> 2018-07-31 21:42:46,741 [main] INFO datanode.DataNode
> (DataNode.java:initDataXceiver(1142)) - Opened streaming server at
> /x.x.x.x:port5
> 2018-07-31 21:42:46,742 [main] INFO datanode.DataNode
> (DataXceiverServer.java:<init>(78)) - Balancing bandwidth is 10485760 bytes/s
> 2018-07-31 21:42:46,742 [main] INFO datanode.DataNode
> (DataXceiverServer.java:<init>(79)) - Number threads for balancing is 50
> 2018-07-31 21:42:46,744 [main] INFO server.AuthenticationFilter
> (AuthenticationFilter.java:constructSecretProvider(240)) - Unable to
> initialize FileSignerSecretProvider, falling back to use random secrets.
> 2018-07-31 21:42:46,744 [Thread-2206] INFO common.Storage
> (Storage.java:tryLock(847)) - Lock on
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2/in_use.lock
> acquired by nodename 7...@quasar-ztplxb-1.vpc.cloudera.com
> 2018-07-31 21:42:46,744 [main] INFO http.HttpRequestLog
> (HttpRequestLog.java:getRequestLog(81)) - Http request log for
> http.requests.datanode is not defined
> 2018-07-31 21:42:46,744 [Thread-2206] INFO common.Storage
> (DataStorage.java:loadStorageDirectory(273)) - Storage directory with
> location
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2
> is not formatted for namespace 1027244560. Formatting...
> 2018-07-31 21:42:46,744 [Thread-2206] INFO common.Storage
> (DataStorage.java:createStorageID(150)) - Generated new storageID
> DS-c307fe32-1d7b-4c82-9d8f-6c43bb6ebe3f for directory
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2
> 2018-07-31 21:42:46,745 [main] INFO http.HttpServer2
> (HttpServer2.java:addGlobalFilter(923)) - Added global filter 'safety'
> (class=org.apache.hadoop.http.HttpServer2$QuotingInputFilter)
> 2018-07-31 21:42:46,746 [main] INFO http.HttpServer2
> (HttpServer2.java:addFilter(896)) - Added filter static_user_filter
> (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to
> context datanode
> 2018-07-31 21:42:46,746 [main] INFO http.HttpServer2
> (HttpServer2.java:addFilter(906)) - Added filter static_user_filter
> (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to
> context logs
> 2018-07-31 21:42:46,746 [main] INFO http.HttpServer2
> (HttpServer2.java:addFilter(906)) - Added filter static_user_filter
> (class=org.apache.hadoop.http.lib.StaticUserWebFilter$StaticUserFilter) to
> context static
> 2018-07-31 21:42:46,746 [main] INFO http.HttpServer2
> (HttpServer2.java:bindListener(1123)) - Jetty bound to port 35966
> 2018-07-31 21:42:46,747 [main] INFO server.Server (Server.java:doStart(346))
> - jetty-9.3.20.v20170531
> 2018-07-31 21:42:46,749 [main] INFO handler.ContextHandler
> (ContextHandler.java:doStart(781)) - Started
> o.e.j.s.ServletContextHandler@2c6aed22\{/logs,file:///tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/log/,AVAILABLE}
> 2018-07-31 21:42:46,750 [main] INFO handler.ContextHandler
> (ContextHandler.java:doStart(781)) - Started
> o.e.j.s.ServletContextHandler@7acfb656\{/static,file:///tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test-classes/webapps/static/,AVAILABLE}
> 2018-07-31 21:42:46,755 [main] INFO handler.ContextHandler
> (ContextHandler.java:doStart(781)) - Started
> o.e.j.w.WebAppContext@41ffaeb8\{/,file:///tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test-classes/webapps/datanode/,AVAILABLE}{/datanode}
> 2018-07-31 21:42:46,756 [main] INFO server.AbstractConnector
> (AbstractConnector.java:doStart(278)) - Started ServerConnector@43f0c2d1
> {HTTP/1.1,[http/1.1]}\{localhost:35966}
> 2018-07-31 21:42:46,756 [main] INFO server.Server (Server.java:doStart(414))
> - Started @27074ms
> 2018-07-31 21:42:46,760 [main] INFO web.DatanodeHttpServer
> (DatanodeHttpServer.java:start(239)) - Listening HTTP traffic on
> /x.x.x.x:port6
> 2018-07-31 21:42:46,761 [main] INFO datanode.DataNode
> (DataNode.java:startDataNode(1412)) - dnUserName = jenkins
> 2018-07-31 21:42:46,761 [main] INFO datanode.DataNode
> (DataNode.java:startDataNode(1413)) - supergroup = supergroup
> 2018-07-31 21:42:46,761 [Thread-2206] INFO common.Storage
> (BlockPoolSliceStorage.java:recoverTransitionRead(252)) - Analyzing storage
> directories for bpid BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,761 [main] INFO ipc.CallQueueManager
> (CallQueueManager.java:<init>(84)) - Using callQueue: class
> java.util.concurrent.LinkedBlockingQueue queueCapacity: 1000 scheduler: class
> org.apache.hadoop.ipc.DefaultRpcScheduler
> 2018-07-31 21:42:46,761
> [org.apache.hadoop.util.JvmPauseMonitor$Monitor@4096aa05] INFO
> util.JvmPauseMonitor (JvmPauseMonitor.java:run(188)) - Starting JVM pause
> monitor
> 2018-07-31 21:42:46,761 [Thread-2206] INFO common.Storage
> (Storage.java:lock(806)) - Locking is disabled for
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1/current/BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,761 [Thread-2206] INFO common.Storage
> (BlockPoolSliceStorage.java:loadStorageDirectory(168)) - Block pool storage
> directory for location
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1
> and block pool id BP-1309332346-172.26.0.186-1533098566550 is not formatted
> for BP-1309332346-172.26.0.186-1533098566550. Formatting ...
> 2018-07-31 21:42:46,762 [Thread-2206] INFO common.Storage
> (BlockPoolSliceStorage.java:format(280)) - Formatting block pool
> BP-1309332346-172.26.0.186-1533098566550 directory
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1/current/BP-1309332346-172.26.0.186-1533098566550/current
> 2018-07-31 21:42:46,762 [Socket Reader #1 for port port7|#1 for port port7]
> INFO ipc.Server (Server.java:run(1067)) - Starting Socket Reader #1 for port
> port7
> 2018-07-31 21:42:46,764 [main] INFO datanode.DataNode
> (DataNode.java:initIpcServer(1029)) - Opened IPC server at /x.x.x.x:port7
> 2018-07-31 21:42:46,766 [main] INFO datanode.DataNode
> (BlockPoolManager.java:refreshNamenodes(149)) - Refresh request received for
> nameservices: null
> 2018-07-31 21:42:46,766 [main] INFO datanode.DataNode
> (BlockPoolManager.java:doRefreshNamenodes(198)) - Starting BPOfferServices
> for nameservices: <default>
> 2018-07-31 21:42:46,767 [Thread-2237] INFO datanode.DataNode
> (BPServiceActor.java:run(809)) - Block pool <registering> (Datanode Uuid
> unassigned) service to localhost/x.x.x.x:port1 starting to offer service
> 2018-07-31 21:42:46,768 [IPC Server Responder] INFO ipc.Server
> (Server.java:run(1307)) - IPC Server Responder: starting
> 2018-07-31 21:42:46,769 [IPC Server listener on port7] INFO ipc.Server
> (Server.java:run(1146)) - IPC Server listener on port7: starting
> 2018-07-31 21:42:46,770 [Thread-2237] INFO datanode.DataNode
> (BPOfferService.java:verifyAndSetNamespaceInfo(378)) - Acknowledging ACTIVE
> Namenode during handshakeBlock pool <registering> (Datanode Uuid unassigned)
> service to localhost/x.x.x.x:port1
> 2018-07-31 21:42:46,770 [Thread-2237] INFO common.Storage
> (DataStorage.java:getParallelVolumeLoadThreadsNum(346)) - Using 2 threads to
> upgrade data directories (dfs.datanode.parallel.volumes.load.threads.num=2,
> dataDirs=2)
> 2018-07-31 21:42:46,772 [main] DEBUG hdfs.DFSClient
> (DFSClient.java:<init>(311)) - Sets
> dfs.client.block.write.replace-datanode-on-failure.min-replication to 0
> 2018-07-31 21:42:46,775 [IPC Server handler 2 on port1] INFO
> FSNamesystem.audit (FSNamesystem.java:logAuditMessage(7816)) - allowed=true
> ugi=jenkins (auth:SIMPLE) ip=/x.x.x.x cmd=datanodeReport src=null dst=null
> perm=null proto=rpc
> 2018-07-31 21:42:46,776 [main] INFO hdfs.MiniDFSCluster
> (MiniDFSCluster.java:shouldWait(2653)) - dnInfo.length != numDataNodes
> 2018-07-31 21:42:46,776 [main] INFO hdfs.MiniDFSCluster
> (MiniDFSCluster.java:waitActive(2574)) - Waiting for cluster to become active
> 2018-07-31 21:42:46,780 [Thread-2206] INFO common.Storage
> (BlockPoolSliceStorage.java:recoverTransitionRead(252)) - Analyzing storage
> directories for bpid BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,780 [Thread-2206] INFO common.Storage
> (Storage.java:lock(806)) - Locking is disabled for
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2/current/BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,780 [Thread-2237] INFO common.Storage
> (Storage.java:tryLock(847)) - Lock on
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3/in_use.lock
> acquired by nodename 7...@quasar-ztplxb-1.vpc.cloudera.com
> 2018-07-31 21:42:46,780 [Thread-2206] INFO common.Storage
> (BlockPoolSliceStorage.java:loadStorageDirectory(168)) - Block pool storage
> directory for location
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2
> and block pool id BP-1309332346-172.26.0.186-1533098566550 is not formatted
> for BP-1309332346-172.26.0.186-1533098566550. Formatting ...
> 2018-07-31 21:42:46,780 [Thread-2206] INFO common.Storage
> (BlockPoolSliceStorage.java:format(280)) - Formatting block pool
> BP-1309332346-172.26.0.186-1533098566550 directory
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2/current/BP-1309332346-172.26.0.186-1533098566550/current
> 2018-07-31 21:42:46,780 [Thread-2237] INFO common.Storage
> (DataStorage.java:loadStorageDirectory(273)) - Storage directory with
> location
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3
> is not formatted for namespace 1027244560. Formatting...
> 2018-07-31 21:42:46,781 [Thread-2237] INFO common.Storage
> (DataStorage.java:createStorageID(150)) - Generated new storageID
> DS-386f4969-f72d-4a3a-baad-ef59d4bc3016 for directory
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3
> 2018-07-31 21:42:46,789 [Thread-2206] INFO datanode.DataNode
> (DataNode.java:initStorage(1693)) - Setting up storage:
> nsid=1027244560;bpid=BP-1309332346-172.26.0.186-1533098566550;lv=-57;nsInfo=lv=-64;cid=testClusterID;nsid=1027244560;c=1533098566550;bpid=BP-1309332346-172.26.0.186-1533098566550;dnuuid=null
> 2018-07-31 21:42:46,792 [Thread-2237] INFO common.Storage
> (Storage.java:tryLock(847)) - Lock on
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4/in_use.lock
> acquired by nodename 7...@quasar-ztplxb-1.vpc.cloudera.com
> 2018-07-31 21:42:46,792 [Thread-2237] INFO common.Storage
> (DataStorage.java:loadStorageDirectory(273)) - Storage directory with
> location
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4
> is not formatted for namespace 1027244560. Formatting...
> 2018-07-31 21:42:46,792 [Thread-2237] INFO common.Storage
> (DataStorage.java:createStorageID(150)) - Generated new storageID
> DS-cac8e9dc-026d-474d-a76b-57d577c44846 for directory
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4
> 2018-07-31 21:42:46,794 [Thread-2206] INFO datanode.DataNode
> (DataNode.java:checkDatanodeUuid(1517)) - Generated and persisted new
> Datanode UUID 785a0dd8-bdae-40c1-94f6-a6b639dafb14
> 2018-07-31 21:42:46,796 [Thread-2206] INFO impl.FsDatasetImpl
> (FsVolumeList.java:addVolume(306)) - Added new volume:
> DS-1d19d47a-b472-463a-a1ed-43be073676f5
> 2018-07-31 21:42:46,796 [Thread-2206] INFO impl.FsDatasetImpl
> (FsDatasetImpl.java:addVolume(431)) - Added volume -
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1,
> StorageType: DISK
> 2018-07-31 21:42:46,797 [Thread-2206] INFO impl.FsDatasetImpl
> (FsVolumeList.java:addVolume(306)) - Added new volume:
> DS-c307fe32-1d7b-4c82-9d8f-6c43bb6ebe3f
> 2018-07-31 21:42:46,797 [Thread-2206] INFO impl.FsDatasetImpl
> (FsDatasetImpl.java:addVolume(431)) - Added volume -
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2,
> StorageType: DISK
> 2018-07-31 21:42:46,797 [Thread-2206] INFO impl.FsDatasetImpl
> (FsDatasetImpl.java:registerMBean(2169)) - Registered FSDatasetState MBean
> 2018-07-31 21:42:46,798 [Thread-2206] INFO checker.ThrottledAsyncChecker
> (ThrottledAsyncChecker.java:schedule(122)) - Scheduling a check for
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1
> 2018-07-31 21:42:46,799 [Thread-2206] INFO checker.DatasetVolumeChecker
> (DatasetVolumeChecker.java:checkAllVolumes(219)) - Scheduled health check for
> volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1
> 2018-07-31 21:42:46,799 [Thread-2206] INFO checker.ThrottledAsyncChecker
> (ThrottledAsyncChecker.java:schedule(122)) - Scheduling a check for
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2
> 2018-07-31 21:42:46,799 [Thread-2206] INFO checker.DatasetVolumeChecker
> (DatasetVolumeChecker.java:checkAllVolumes(219)) - Scheduled health check for
> volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2
> 2018-07-31 21:42:46,799 [Thread-2206] INFO impl.FsDatasetImpl
> (FsDatasetImpl.java:addBlockPool(2655)) - Adding block pool
> BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,800 [Thread-2251] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(409)) - Scanning block pool
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1...
> 2018-07-31 21:42:46,801 [Thread-2237] INFO common.Storage
> (BlockPoolSliceStorage.java:recoverTransitionRead(252)) - Analyzing storage
> directories for bpid BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,801 [Thread-2237] INFO common.Storage
> (Storage.java:lock(806)) - Locking is disabled for
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3/current/BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,801 [Thread-2237] INFO common.Storage
> (BlockPoolSliceStorage.java:loadStorageDirectory(168)) - Block pool storage
> directory for location
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3
> and block pool id BP-1309332346-172.26.0.186-1533098566550 is not formatted
> for BP-1309332346-172.26.0.186-1533098566550. Formatting ...
> 2018-07-31 21:42:46,801 [Thread-2237] INFO common.Storage
> (BlockPoolSliceStorage.java:format(280)) - Formatting block pool
> BP-1309332346-172.26.0.186-1533098566550 directory
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3/current/BP-1309332346-172.26.0.186-1533098566550/current
> 2018-07-31 21:42:46,804 [Thread-2252] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(409)) - Scanning block pool
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2...
> 2018-07-31 21:42:46,811 [Thread-2237] INFO common.Storage
> (BlockPoolSliceStorage.java:recoverTransitionRead(252)) - Analyzing storage
> directories for bpid BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,811 [Thread-2237] INFO common.Storage
> (Storage.java:lock(806)) - Locking is disabled for
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4/current/BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,811 [Thread-2237] INFO common.Storage
> (BlockPoolSliceStorage.java:loadStorageDirectory(168)) - Block pool storage
> directory for location
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4
> and block pool id BP-1309332346-172.26.0.186-1533098566550 is not formatted
> for BP-1309332346-172.26.0.186-1533098566550. Formatting ...
> 2018-07-31 21:42:46,812 [Thread-2237] INFO common.Storage
> (BlockPoolSliceStorage.java:format(280)) - Formatting block pool
> BP-1309332346-172.26.0.186-1533098566550 directory
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4/current/BP-1309332346-172.26.0.186-1533098566550/current
> 2018-07-31 21:42:46,813 [Thread-2252] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(414)) - Time taken to scan block pool
> BP-1309332346-172.26.0.186-1533098566550 on
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2:
> 9ms
> 2018-07-31 21:42:46,816 [Thread-2237] INFO datanode.DataNode
> (DataNode.java:initStorage(1693)) - Setting up storage:
> nsid=1027244560;bpid=BP-1309332346-172.26.0.186-1533098566550;lv=-57;nsInfo=lv=-64;cid=testClusterID;nsid=1027244560;c=1533098566550;bpid=BP-1309332346-172.26.0.186-1533098566550;dnuuid=null
> 2018-07-31 21:42:46,817 [Thread-2251] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(414)) - Time taken to scan block pool
> BP-1309332346-172.26.0.186-1533098566550 on
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1:
> 17ms
> 2018-07-31 21:42:46,817 [Thread-2206] INFO impl.FsDatasetImpl
> (FsVolumeList.java:addBlockPool(440)) - Total time to scan all replicas for
> block pool BP-1309332346-172.26.0.186-1533098566550: 18ms
> 2018-07-31 21:42:46,817 [Thread-2255] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(198)) - Adding replicas to map for block pool
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1...
> 2018-07-31 21:42:46,818 [Thread-2255] INFO impl.BlockPoolSlice
> (BlockPoolSlice.java:readReplicasFromCache(770)) - Replica Cache file:
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1/current/BP-1309332346-172.26.0.186-1533098566550/current/replicas
> doesn't exist
> 2018-07-31 21:42:46,818 [Thread-2256] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(198)) - Adding replicas to map for block pool
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2...
> 2018-07-31 21:42:46,818 [Thread-2255] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(203)) - Time to add replicas to map for block pool
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1:
> 0ms
> 2018-07-31 21:42:46,818 [Thread-2256] INFO impl.BlockPoolSlice
> (BlockPoolSlice.java:readReplicasFromCache(770)) - Replica Cache file:
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2/current/BP-1309332346-172.26.0.186-1533098566550/current/replicas
> doesn't exist
> 2018-07-31 21:42:46,818 [Thread-2256] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(203)) - Time to add replicas to map for block pool
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2:
> 0ms
> 2018-07-31 21:42:46,819 [Thread-2206] INFO impl.FsDatasetImpl
> (FsVolumeList.java:getAllVolumesMap(229)) - Total time to add all replicas to
> map: 2ms
> 2018-07-31 21:42:46,819
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1)]
> INFO datanode.VolumeScanner
> (VolumeScanner.java:findNextUsableBlockIter(386)) - Now scanning bpid
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1
> 2018-07-31 21:42:46,819
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2)]
> INFO datanode.VolumeScanner
> (VolumeScanner.java:findNextUsableBlockIter(386)) - Now scanning bpid
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2
> 2018-07-31 21:42:46,819 [Thread-2206] INFO datanode.DirectoryScanner
> (DirectoryScanner.java:start(281)) - Periodic Directory Tree Verification
> scan starting at 7/31/18 10:52 PM with interval of 21600000ms
> 2018-07-31 21:42:46,819
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2)]
> INFO datanode.VolumeScanner (VolumeScanner.java:runLoop(544)) -
> VolumeScanner(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2,
> DS-c307fe32-1d7b-4c82-9d8f-6c43bb6ebe3f): finished scanning block pool
> BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,819
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1)]
> INFO datanode.VolumeScanner (VolumeScanner.java:runLoop(544)) -
> VolumeScanner(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1,
> DS-1d19d47a-b472-463a-a1ed-43be073676f5): finished scanning block pool
> BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,820 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] INFO datanode.DataNode
> (BPServiceActor.java:register(763)) - Block pool
> BP-1309332346-172.26.0.186-1533098566550 (Datanode Uuid
> 785a0dd8-bdae-40c1-94f6-a6b639dafb14) service to localhost/x.x.x.x:port1
> beginning handshake with NN
> 2018-07-31 21:42:46,821 [IPC Server handler 3 on port1] INFO
> hdfs.StateChange (DatanodeManager.java:registerDatanode(1038)) - BLOCK*
> registerDatanode: from DatanodeRegistration(x.x.x.x:port2,
> datanodeUuid=785a0dd8-bdae-40c1-94f6-a6b639dafb14, infoPort=port3,
> infoSecurePort=0, ipcPort=port4,
> storageInfo=lv=-57;cid=testClusterID;nsid=1027244560;c=1533098566550) storage
> 785a0dd8-bdae-40c1-94f6-a6b639dafb14
> 2018-07-31 21:42:46,821 [IPC Server handler 3 on port1] INFO
> net.NetworkTopology (NetworkTopology.java:add(145)) - Adding a new node:
> /default-rack/x.x.x.x:port2
> 2018-07-31 21:42:46,821 [IPC Server handler 3 on port1] INFO
> blockmanagement.BlockReportLeaseManager
> (BlockReportLeaseManager.java:registerNode(204)) - Registered DN
> 785a0dd8-bdae-40c1-94f6-a6b639dafb14 (x.x.x.x:port2).
> 2018-07-31 21:42:46,823 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] INFO datanode.DataNode
> (BPServiceActor.java:register(782)) - Block pool Block pool
> BP-1309332346-172.26.0.186-1533098566550 (Datanode Uuid
> 785a0dd8-bdae-40c1-94f6-a6b639dafb14) service to localhost/x.x.x.x:port1
> successfully registered with NN
> 2018-07-31 21:42:46,823 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] INFO datanode.DataNode
> (BPServiceActor.java:offerService(612)) - For namenode
> localhost/x.x.x.x:port1 using BLOCKREPORT_INTERVAL of 21600000msec
> CACHEREPORT_INTERVAL of 10000msec Initial delay: 0msec; heartBeatInterval=3000
> 2018-07-31 21:42:46,824
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1)]
> INFO datanode.VolumeScanner
> (VolumeScanner.java:findNextUsableBlockIter(403)) -
> VolumeScanner(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1,
> DS-1d19d47a-b472-463a-a1ed-43be073676f5): no suitable block pools found to
> scan. Waiting 1814399995 ms.
> 2018-07-31 21:42:46,824
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2)]
> INFO datanode.VolumeScanner
> (VolumeScanner.java:findNextUsableBlockIter(403)) -
> VolumeScanner(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2,
> DS-c307fe32-1d7b-4c82-9d8f-6c43bb6ebe3f): no suitable block pools found to
> scan. Waiting 1814399995 ms.
> 2018-07-31 21:42:46,825 [IPC Server handler 4 on port1] INFO
> blockmanagement.DatanodeDescriptor
> (DatanodeDescriptor.java:updateStorage(949)) - Adding new storage ID
> DS-1d19d47a-b472-463a-a1ed-43be073676f5 for DN x.x.x.x:port2
> 2018-07-31 21:42:46,825 [IPC Server handler 4 on port1] INFO
> blockmanagement.DatanodeDescriptor
> (DatanodeDescriptor.java:updateStorage(949)) - Adding new storage ID
> DS-c307fe32-1d7b-4c82-9d8f-6c43bb6ebe3f for DN x.x.x.x:port2
> 2018-07-31 21:42:46,827 [Block report processor] INFO BlockStateChange
> (BlockManager.java:processReport(2462)) - BLOCK* processReport
> 0xa2b93752cc445e4b: Processing first storage report for
> DS-1d19d47a-b472-463a-a1ed-43be073676f5 from datanode
> 785a0dd8-bdae-40c1-94f6-a6b639dafb14
> 2018-07-31 21:42:46,828 [Block report processor] INFO BlockStateChange
> (BlockManager.java:processReport(2488)) - BLOCK* processReport
> 0xa2b93752cc445e4b: from storage DS-1d19d47a-b472-463a-a1ed-43be073676f5 node
> DatanodeRegistration(x.x.x.x:port2,
> datanodeUuid=785a0dd8-bdae-40c1-94f6-a6b639dafb14, infoPort=port3,
> infoSecurePort=0, ipcPort=port4,
> storageInfo=lv=-57;cid=testClusterID;nsid=1027244560;c=1533098566550),
> blocks: 0, hasStaleStorage: true, processing time: 1 msecs,
> invalidatedBlocks: 0
> 2018-07-31 21:42:46,828 [Block report processor] INFO BlockStateChange
> (BlockManager.java:processReport(2462)) - BLOCK* processReport
> 0xa2b93752cc445e4b: Processing first storage report for
> DS-c307fe32-1d7b-4c82-9d8f-6c43bb6ebe3f from datanode
> 785a0dd8-bdae-40c1-94f6-a6b639dafb14
> 2018-07-31 21:42:46,828 [Thread-2237] INFO datanode.DataNode
> (DataNode.java:checkDatanodeUuid(1517)) - Generated and persisted new
> Datanode UUID 48eaddaf-0bf7-47e5-bc33-4a640b4cde9d
> 2018-07-31 21:42:46,828 [Block report processor] INFO BlockStateChange
> (BlockManager.java:processReport(2488)) - BLOCK* processReport
> 0xa2b93752cc445e4b: from storage DS-c307fe32-1d7b-4c82-9d8f-6c43bb6ebe3f node
> DatanodeRegistration(x.x.x.x:port2,
> datanodeUuid=785a0dd8-bdae-40c1-94f6-a6b639dafb14, infoPort=port3,
> infoSecurePort=0, ipcPort=port4,
> storageInfo=lv=-57;cid=testClusterID;nsid=1027244560;c=1533098566550),
> blocks: 0, hasStaleStorage: false, processing time: 0 msecs,
> invalidatedBlocks: 0
> 2018-07-31 21:42:46,830 [Thread-2237] INFO impl.FsDatasetImpl
> (FsVolumeList.java:addVolume(306)) - Added new volume:
> DS-386f4969-f72d-4a3a-baad-ef59d4bc3016
> 2018-07-31 21:42:46,830 [Thread-2237] INFO impl.FsDatasetImpl
> (FsDatasetImpl.java:addVolume(431)) - Added volume -
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3,
> StorageType: DISK
> 2018-07-31 21:42:46,830 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] INFO datanode.DataNode
> (BPServiceActor.java:blockReport(422)) - Successfully sent block report
> 0xa2b93752cc445e4b, containing 2 storage report(s), of which we sent 2. The
> reports had 0 total blocks and used 1 RPC(s). This took 0 msec to generate
> and 3 msecs for RPC and NN processing. Got back one command:
> FinalizeCommand/5.
> 2018-07-31 21:42:46,830 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] INFO datanode.DataNode
> (BPOfferService.java:processCommandFromActive(759)) - Got finalize command
> for block pool BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,831 [Thread-2237] INFO impl.FsDatasetImpl
> (FsVolumeList.java:addVolume(306)) - Added new volume:
> DS-cac8e9dc-026d-474d-a76b-57d577c44846
> 2018-07-31 21:42:46,831 [Thread-2237] INFO impl.FsDatasetImpl
> (FsDatasetImpl.java:addVolume(431)) - Added volume -
> [DISK]file:/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4,
> StorageType: DISK
> 2018-07-31 21:42:46,831 [Thread-2237] INFO impl.FsDatasetImpl
> (FsDatasetImpl.java:registerMBean(2169)) - Registered FSDatasetState MBean
> 2018-07-31 21:42:46,832 [Thread-2237] INFO checker.ThrottledAsyncChecker
> (ThrottledAsyncChecker.java:schedule(122)) - Scheduling a check for
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3
> 2018-07-31 21:42:46,833 [Thread-2237] INFO checker.DatasetVolumeChecker
> (DatasetVolumeChecker.java:checkAllVolumes(219)) - Scheduled health check for
> volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3
> 2018-07-31 21:42:46,833 [Thread-2237] INFO checker.ThrottledAsyncChecker
> (ThrottledAsyncChecker.java:schedule(122)) - Scheduling a check for
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4
> 2018-07-31 21:42:46,833 [Thread-2237] INFO checker.DatasetVolumeChecker
> (DatasetVolumeChecker.java:checkAllVolumes(219)) - Scheduled health check for
> volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4
> 2018-07-31 21:42:46,833 [Thread-2237] INFO impl.FsDatasetImpl
> (FsDatasetImpl.java:addBlockPool(2655)) - Adding block pool
> BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,834 [Thread-2262] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(409)) - Scanning block pool
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3...
> 2018-07-31 21:42:46,834 [Thread-2263] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(409)) - Scanning block pool
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4...
> 2018-07-31 21:42:46,840 [Thread-2263] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(414)) - Time taken to scan block pool
> BP-1309332346-172.26.0.186-1533098566550 on
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4:
> 6ms
> 2018-07-31 21:42:46,842 [Thread-2262] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(414)) - Time taken to scan block pool
> BP-1309332346-172.26.0.186-1533098566550 on
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3:
> 8ms
> 2018-07-31 21:42:46,842 [Thread-2237] INFO impl.FsDatasetImpl
> (FsVolumeList.java:addBlockPool(440)) - Total time to scan all replicas for
> block pool BP-1309332346-172.26.0.186-1533098566550: 9ms
> 2018-07-31 21:42:46,842 [Thread-2266] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(198)) - Adding replicas to map for block pool
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3...
> 2018-07-31 21:42:46,843 [Thread-2266] INFO impl.BlockPoolSlice
> (BlockPoolSlice.java:readReplicasFromCache(770)) - Replica Cache file:
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3/current/BP-1309332346-172.26.0.186-1533098566550/current/replicas
> doesn't exist
> 2018-07-31 21:42:46,843 [Thread-2267] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(198)) - Adding replicas to map for block pool
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4...
> 2018-07-31 21:42:46,843 [Thread-2266] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(203)) - Time to add replicas to map for block pool
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3:
> 0ms
> 2018-07-31 21:42:46,843 [Thread-2267] INFO impl.BlockPoolSlice
> (BlockPoolSlice.java:readReplicasFromCache(770)) - Replica Cache file:
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4/current/BP-1309332346-172.26.0.186-1533098566550/current/replicas
> doesn't exist
> 2018-07-31 21:42:46,843 [Thread-2267] INFO impl.FsDatasetImpl
> (FsVolumeList.java:run(203)) - Time to add replicas to map for block pool
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4:
> 0ms
> 2018-07-31 21:42:46,843 [Thread-2237] INFO impl.FsDatasetImpl
> (FsVolumeList.java:getAllVolumesMap(229)) - Total time to add all replicas to
> map: 1ms
> 2018-07-31 21:42:46,844
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3)]
> INFO datanode.VolumeScanner
> (VolumeScanner.java:findNextUsableBlockIter(386)) - Now scanning bpid
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3
> 2018-07-31 21:42:46,844
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4)]
> INFO datanode.VolumeScanner
> (VolumeScanner.java:findNextUsableBlockIter(386)) - Now scanning bpid
> BP-1309332346-172.26.0.186-1533098566550 on volume
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4
> 2018-07-31 21:42:46,844
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3)]
> INFO datanode.VolumeScanner (VolumeScanner.java:runLoop(544)) -
> VolumeScanner(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3,
> DS-386f4969-f72d-4a3a-baad-ef59d4bc3016): finished scanning block pool
> BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,844
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4)]
> INFO datanode.VolumeScanner (VolumeScanner.java:runLoop(544)) -
> VolumeScanner(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4,
> DS-cac8e9dc-026d-474d-a76b-57d577c44846): finished scanning block pool
> BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,844 [Thread-2237] INFO datanode.DirectoryScanner
> (DirectoryScanner.java:start(281)) - Periodic Directory Tree Verification
> scan starting at 7/31/18 10:08 PM with interval of 21600000ms
> 2018-07-31 21:42:46,844
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3)]
> INFO datanode.VolumeScanner
> (VolumeScanner.java:findNextUsableBlockIter(403)) -
> VolumeScanner(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3,
> DS-386f4969-f72d-4a3a-baad-ef59d4bc3016): no suitable block pools found to
> scan. Waiting 1814400000 ms.
> 2018-07-31 21:42:46,844
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4)]
> INFO datanode.VolumeScanner
> (VolumeScanner.java:findNextUsableBlockIter(403)) -
> VolumeScanner(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4,
> DS-cac8e9dc-026d-474d-a76b-57d577c44846): no suitable block pools found to
> scan. Waiting 1814400000 ms.
> 2018-07-31 21:42:46,845 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] INFO datanode.DataNode
> (BPServiceActor.java:register(763)) - Block pool
> BP-1309332346-172.26.0.186-1533098566550 (Datanode Uuid
> 48eaddaf-0bf7-47e5-bc33-4a640b4cde9d) service to localhost/x.x.x.x:port1
> beginning handshake with NN
> 2018-07-31 21:42:46,846 [IPC Server handler 6 on port1] INFO
> hdfs.StateChange (DatanodeManager.java:registerDatanode(1038)) - BLOCK*
> registerDatanode: from DatanodeRegistration(x.x.x.x:port5,
> datanodeUuid=48eaddaf-0bf7-47e5-bc33-4a640b4cde9d, infoPort=port6,
> infoSecurePort=0, ipcPort=port7,
> storageInfo=lv=-57;cid=testClusterID;nsid=1027244560;c=1533098566550) storage
> 48eaddaf-0bf7-47e5-bc33-4a640b4cde9d
> 2018-07-31 21:42:46,846 [IPC Server handler 6 on port1] INFO
> net.NetworkTopology (NetworkTopology.java:add(145)) - Adding a new node:
> /default-rack/x.x.x.x:port5
> 2018-07-31 21:42:46,846 [IPC Server handler 6 on port1] INFO
> blockmanagement.BlockReportLeaseManager
> (BlockReportLeaseManager.java:registerNode(204)) - Registered DN
> 48eaddaf-0bf7-47e5-bc33-4a640b4cde9d (x.x.x.x:port5).
> 2018-07-31 21:42:46,847 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] INFO datanode.DataNode
> (BPServiceActor.java:register(782)) - Block pool Block pool
> BP-1309332346-172.26.0.186-1533098566550 (Datanode Uuid
> 48eaddaf-0bf7-47e5-bc33-4a640b4cde9d) service to localhost/x.x.x.x:port1
> successfully registered with NN
> 2018-07-31 21:42:46,847 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] INFO datanode.DataNode
> (BPServiceActor.java:offerService(612)) - For namenode
> localhost/x.x.x.x:port1 using BLOCKREPORT_INTERVAL of 21600000msec
> CACHEREPORT_INTERVAL of 10000msec Initial delay: 0msec; heartBeatInterval=3000
> 2018-07-31 21:42:46,848 [IPC Server handler 7 on port1] INFO
> blockmanagement.DatanodeDescriptor
> (DatanodeDescriptor.java:updateStorage(949)) - Adding new storage ID
> DS-386f4969-f72d-4a3a-baad-ef59d4bc3016 for DN x.x.x.x:port5
> 2018-07-31 21:42:46,850 [IPC Server handler 7 on port1] INFO
> blockmanagement.DatanodeDescriptor
> (DatanodeDescriptor.java:updateStorage(949)) - Adding new storage ID
> DS-cac8e9dc-026d-474d-a76b-57d577c44846 for DN x.x.x.x:port5
> 2018-07-31 21:42:46,852 [Block report processor] INFO BlockStateChange
> (BlockManager.java:processReport(2462)) - BLOCK* processReport
> 0xcb3b9727741549e0: Processing first storage report for
> DS-cac8e9dc-026d-474d-a76b-57d577c44846 from datanode
> 48eaddaf-0bf7-47e5-bc33-4a640b4cde9d
> 2018-07-31 21:42:46,852 [Block report processor] INFO BlockStateChange
> (BlockManager.java:processReport(2488)) - BLOCK* processReport
> 0xcb3b9727741549e0: from storage DS-cac8e9dc-026d-474d-a76b-57d577c44846 node
> DatanodeRegistration(x.x.x.x:port5,
> datanodeUuid=48eaddaf-0bf7-47e5-bc33-4a640b4cde9d, infoPort=port6,
> infoSecurePort=0, ipcPort=port7,
> storageInfo=lv=-57;cid=testClusterID;nsid=1027244560;c=1533098566550),
> blocks: 0, hasStaleStorage: true, processing time: 0 msecs,
> invalidatedBlocks: 0
> 2018-07-31 21:42:46,852 [Block report processor] INFO BlockStateChange
> (BlockManager.java:processReport(2462)) - BLOCK* processReport
> 0xcb3b9727741549e0: Processing first storage report for
> DS-386f4969-f72d-4a3a-baad-ef59d4bc3016 from datanode
> 48eaddaf-0bf7-47e5-bc33-4a640b4cde9d
> 2018-07-31 21:42:46,852 [Block report processor] INFO BlockStateChange
> (BlockManager.java:processReport(2488)) - BLOCK* processReport
> 0xcb3b9727741549e0: from storage DS-386f4969-f72d-4a3a-baad-ef59d4bc3016 node
> DatanodeRegistration(x.x.x.x:port5,
> datanodeUuid=48eaddaf-0bf7-47e5-bc33-4a640b4cde9d, infoPort=port6,
> infoSecurePort=0, ipcPort=port7,
> storageInfo=lv=-57;cid=testClusterID;nsid=1027244560;c=1533098566550),
> blocks: 0, hasStaleStorage: false, processing time: 0 msecs,
> invalidatedBlocks: 0
> 2018-07-31 21:42:46,853 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] INFO datanode.DataNode
> (BPServiceActor.java:blockReport(422)) - Successfully sent block report
> 0xcb3b9727741549e0, containing 2 storage report(s), of which we sent 2. The
> reports had 0 total blocks and used 1 RPC(s). This took 0 msec to generate
> and 3 msecs for RPC and NN processing. Got back one command:
> FinalizeCommand/5.
> 2018-07-31 21:42:46,853 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] INFO datanode.DataNode
> (BPOfferService.java:processCommandFromActive(759)) - Got finalize command
> for block pool BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,878 [IPC Server handler 9 on port1] INFO
> FSNamesystem.audit (FSNamesystem.java:logAuditMessage(7816)) - allowed=true
> ugi=jenkins (auth:SIMPLE) ip=/x.x.x.x cmd=datanodeReport src=null dst=null
> perm=null proto=rpc
> 2018-07-31 21:42:46,878 [main] INFO hdfs.MiniDFSCluster
> (MiniDFSCluster.java:waitActive(2629)) - Cluster is active
> 2018-07-31 21:42:46,880 [main] DEBUG hdfs.DFSClient
> (DFSClient.java:<init>(311)) - Sets
> dfs.client.block.write.replace-datanode-on-failure.min-replication to 0
> 2018-07-31 21:42:46,881 [main] INFO hdfs.MiniDFSCluster
> (MiniDFSCluster.java:shutdown(1965)) - Shutting down the Mini HDFS Cluster
> 2018-07-31 21:42:46,881 [main] INFO hdfs.MiniDFSCluster
> (MiniDFSCluster.java:shutdownDataNode(2013)) - Shutting down DataNode 1
> 2018-07-31 21:42:46,881 [main] WARN datanode.DirectoryScanner
> (DirectoryScanner.java:shutdown(340)) - DirectoryScanner: shutdown has been
> called
> 2018-07-31 21:42:46,881
> [org.apache.hadoop.hdfs.server.datanode.DataXceiverServer@6aba5d30] INFO
> datanode.DataNode (DataXceiverServer.java:closeAllPeers(281)) - Closing all
> peers.
> 2018-07-31 21:42:46,882
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3)]
> INFO datanode.VolumeScanner (VolumeScanner.java:run(642)) -
> VolumeScanner(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3,
> DS-386f4969-f72d-4a3a-baad-ef59d4bc3016) exiting.
> 2018-07-31 21:42:46,882
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4)]
> INFO datanode.VolumeScanner (VolumeScanner.java:run(642)) -
> VolumeScanner(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4,
> DS-cac8e9dc-026d-474d-a76b-57d577c44846) exiting.
> 2018-07-31 21:42:46,887 [main] INFO handler.ContextHandler
> (ContextHandler.java:doStop(910)) - Stopped
> o.e.j.w.WebAppContext@41ffaeb8\{/,null,UNAVAILABLE}{/datanode}
> 2018-07-31 21:42:46,888 [main] INFO server.AbstractConnector
> (AbstractConnector.java:doStop(318)) - Stopped
> ServerConnector@43f0c2d1\{HTTP/1.1,[http/1.1]} \{localhost:0}
> 2018-07-31 21:42:46,888 [main] INFO handler.ContextHandler
> (ContextHandler.java:doStop(910)) - Stopped
> o.e.j.s.ServletContextHandler@7acfb656
> {/static,file:///tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test-classes/webapps/static/,UNAVAILABLE}
> 2018-07-31 21:42:46,888 [main] INFO handler.ContextHandler
> (ContextHandler.java:doStop(910)) - Stopped
> o.e.j.s.ServletContextHandler@2c6aed22
> {/logs,file:///tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/log/,UNAVAILABLE}
> 2018-07-31 21:42:46,890 [main] INFO ipc.Server (Server.java:stop(3074)) -
> Stopping server on port7
> 2018-07-31 21:42:46,891 [IPC Server listener on port7] INFO ipc.Server
> (Server.java:run(1178)) - Stopping IPC Server listener on port7
> 2018-07-31 21:42:46,892 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] WARN
> datanode.IncrementalBlockReportManager
> (IncrementalBlockReportManager.java:waitTillNextIBR(160)) -
> IncrementalBlockReportManager interrupted
> 2018-07-31 21:42:46,891 [IPC Server Responder] INFO ipc.Server
> (Server.java:run(1312)) - Stopping IPC Server Responder
> 2018-07-31 21:42:46,892 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] WARN datanode.DataNode
> (BPServiceActor.java:run(852)) - Ending block pool service for: Block pool
> BP-1309332346-172.26.0.186-1533098566550 (Datanode Uuid
> 48eaddaf-0bf7-47e5-bc33-4a640b4cde9d) service to localhost/x.x.x.x:port1
> 2018-07-31 21:42:46,892 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] INFO datanode.DataNode
> (BlockPoolManager.java:remove(102)) - Removed Block pool
> BP-1309332346-172.26.0.186-1533098566550 (Datanode Uuid
> 48eaddaf-0bf7-47e5-bc33-4a640b4cde9d)
> 2018-07-31 21:42:46,892 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] INFO impl.FsDatasetImpl
> (FsDatasetImpl.java:shutdownBlockPool(2666)) - Removing block pool
> BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:46,893
> [refreshUsed-/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data4/current/BP-1309332346-172.26.0.186-1533098566550]
> WARN fs.CachingGetSpaceUsed (CachingGetSpaceUsed.java:run(183)) - Thread
> Interrupted waiting to refresh disk information: sleep interrupted
> 2018-07-31 21:42:46,893
> [refreshUsed-/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data3/current/BP-1309332346-172.26.0.186-1533098566550]
> WARN fs.CachingGetSpaceUsed (CachingGetSpaceUsed.java:run(183)) - Thread
> Interrupted waiting to refresh disk information: sleep interrupted
> 2018-07-31 21:42:46,894 [main] INFO impl.FsDatasetAsyncDiskService
> (FsDatasetAsyncDiskService.java:shutdown(191)) - Shutting down all async disk
> service threads
> 2018-07-31 21:42:46,894 [main] INFO impl.FsDatasetAsyncDiskService
> (FsDatasetAsyncDiskService.java:shutdown(199)) - All async disk service
> threads have been shut down
> 2018-07-31 21:42:46,895 [main] INFO impl.RamDiskAsyncLazyPersistService
> (RamDiskAsyncLazyPersistService.java:shutdown(176)) - Shutting down all async
> lazy persist service threads
> 2018-07-31 21:42:46,895 [main] INFO impl.RamDiskAsyncLazyPersistService
> (RamDiskAsyncLazyPersistService.java:shutdown(183)) - All async lazy persist
> service threads have been shut down
> 2018-07-31 21:42:46,895 [main] INFO datanode.DataNode
> (DataNode.java:shutdown(2113)) - Shutdown complete.
> 2018-07-31 21:42:46,896 [main] INFO hdfs.MiniDFSCluster
> (MiniDFSCluster.java:shutdownDataNode(2013)) - Shutting down DataNode 0
> 2018-07-31 21:42:46,896 [main] WARN datanode.DirectoryScanner
> (DirectoryScanner.java:shutdown(340)) - DirectoryScanner: shutdown has been
> called
> 2018-07-31 21:42:46,896
> [org.apache.hadoop.hdfs.server.datanode.DataXceiverServer@74db12c2] INFO
> datanode.DataNode (DataXceiverServer.java:closeAllPeers(281)) - Closing all
> peers.
> 2018-07-31 21:42:46,897
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1)]
> INFO datanode.VolumeScanner (VolumeScanner.java:run(642)) -
> VolumeScanner(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1,
> DS-1d19d47a-b472-463a-a1ed-43be073676f5) exiting.
> 2018-07-31 21:42:46,897
> [VolumeScannerThread(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2)]
> INFO datanode.VolumeScanner (VolumeScanner.java:run(642)) -
> VolumeScanner(/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2,
> DS-c307fe32-1d7b-4c82-9d8f-6c43bb6ebe3f) exiting.
> 2018-07-31 21:42:46,901 [main] INFO handler.ContextHandler
> (ContextHandler.java:doStop(910)) - Stopped o.e.j.w.WebAppContext@68fe48d7
> {/,null,UNAVAILABLE}\{/datanode}
> 2018-07-31 21:42:46,902 [main] INFO server.AbstractConnector
> (AbstractConnector.java:doStop(318)) - Stopped
> ServerConnector@379ce046\{HTTP/1.1,[http/1.1]}{localhost:0}
> 2018-07-31 21:42:46,902 [main] INFO handler.ContextHandler
> (ContextHandler.java:doStop(910)) - Stopped
> o.e.j.s.ServletContextHandler@67594471\{/static,file:///tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test-classes/webapps/static/,UNAVAILABLE}
> 2018-07-31 21:42:46,902 [main] INFO handler.ContextHandler
> (ContextHandler.java:doStop(910)) - Stopped
> o.e.j.s.ServletContextHandler@38b5f25\{/logs,file:///tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/log/,UNAVAILABLE}
> 2018-07-31 21:42:46,904 [main] INFO ipc.Server (Server.java:stop(3074)) -
> Stopping server on port4
> 2018-07-31 21:42:46,905 [IPC Server listener on port4] INFO ipc.Server
> (Server.java:run(1178)) - Stopping IPC Server listener on port4
> 2018-07-31 21:42:46,906 [IPC Server Responder] INFO ipc.Server
> (Server.java:run(1312)) - Stopping IPC Server Responder
> 2018-07-31 21:42:46,906 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] WARN
> datanode.IncrementalBlockReportManager
> (IncrementalBlockReportManager.java:waitTillNextIBR(160)) -
> IncrementalBlockReportManager interrupted
> 2018-07-31 21:42:46,906 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] WARN datanode.DataNode
> (BPServiceActor.java:run(852)) - Ending block pool service for: Block pool
> BP-1309332346-172.26.0.186-1533098566550 (Datanode Uuid
> 785a0dd8-bdae-40c1-94f6-a6b639dafb14) service to localhost/x.x.x.x:port1
> 2018-07-31 21:42:47,006 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] INFO datanode.DataNode
> (BlockPoolManager.java:remove(102)) - Removed Block pool
> BP-1309332346-172.26.0.186-1533098566550 (Datanode Uuid
> 785a0dd8-bdae-40c1-94f6-a6b639dafb14)
> 2018-07-31 21:42:47,007 [BP-1309332346-172.26.0.186-1533098566550
> heartbeating to localhost/x.x.x.x:port1] INFO impl.FsDatasetImpl
> (FsDatasetImpl.java:shutdownBlockPool(2666)) - Removing block pool
> BP-1309332346-172.26.0.186-1533098566550
> 2018-07-31 21:42:47,007
> [refreshUsed-/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data1/current/BP-1309332346-172.26.0.186-1533098566550]
> WARN fs.CachingGetSpaceUsed (CachingGetSpaceUsed.java:run(183)) - Thread
> Interrupted waiting to refresh disk information: sleep interrupted
> 2018-07-31 21:42:47,007
> [refreshUsed-/tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/data/data2/current/BP-1309332346-172.26.0.186-1533098566550]
> WARN fs.CachingGetSpaceUsed (CachingGetSpaceUsed.java:run(183)) - Thread
> Interrupted waiting to refresh disk information: sleep interrupted
> 2018-07-31 21:42:47,008 [main] INFO impl.FsDatasetAsyncDiskService
> (FsDatasetAsyncDiskService.java:shutdown(191)) - Shutting down all async disk
> service threads
> 2018-07-31 21:42:47,008 [main] INFO impl.FsDatasetAsyncDiskService
> (FsDatasetAsyncDiskService.java:shutdown(199)) - All async disk service
> threads have been shut down
> 2018-07-31 21:42:47,009 [main] INFO impl.RamDiskAsyncLazyPersistService
> (RamDiskAsyncLazyPersistService.java:shutdown(176)) - Shutting down all async
> lazy persist service threads
> 2018-07-31 21:42:47,009 [main] INFO impl.RamDiskAsyncLazyPersistService
> (RamDiskAsyncLazyPersistService.java:shutdown(183)) - All async lazy persist
> service threads have been shut down
> 2018-07-31 21:42:47,009 [main] INFO datanode.DataNode
> (DataNode.java:shutdown(2113)) - Shutdown complete.
> 2018-07-31 21:42:47,010 [main] INFO hdfs.MiniDFSCluster
> (MiniDFSCluster.java:stopAndJoinNameNode(2046)) - Shutting down the namenode
> 2018-07-31 21:42:47,010 [main] INFO namenode.FSNamesystem
> (FSNamesystem.java:stopActiveServices(1339)) - Stopping services started for
> active state
> 2018-07-31 21:42:47,010 [main] INFO namenode.FSEditLog
> (FSEditLog.java:endCurrentLogSegment(1407)) - Ending log segment 1, 1
> 2018-07-31 21:42:47,010
> [org.apache.hadoop.hdfs.server.namenode.FSNamesystem$NameNodeEditLogRoller@263bbfeb]
> INFO namenode.FSNamesystem (FSNamesystem.java:run(4010)) -
> NameNodeEditLogRoller was interrupted, exiting
> 2018-07-31 21:42:47,011
> [org.apache.hadoop.hdfs.server.namenode.FSNamesystem$LazyPersistFileScrubber@31edeac]
> INFO namenode.FSNamesystem (FSNamesystem.java:run(4101)) -
> LazyPersistFileScrubber was interrupted, exiting
> 2018-07-31 21:42:47,011 [main] INFO namenode.FSEditLog
> (FSEditLog.java:printStatistics(775)) - Number of transactions: 2 Total time
> for transactions(ms): 0 Number of transactions batched in Syncs: 0 Number of
> syncs: 3 SyncTimes(ms): 1 1
> 2018-07-31 21:42:47,011 [main] INFO namenode.FileJournalManager
> (FileJournalManager.java:finalizeLogSegment(143)) - Finalizing edits file
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name-0-1/current/edits_inprogress_0000000000000000001
> ->
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name-0-1/current/edits_0000000000000000001-0000000000000000002
> 2018-07-31 21:42:47,012 [main] INFO namenode.FileJournalManager
> (FileJournalManager.java:finalizeLogSegment(143)) - Finalizing edits file
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name-0-2/current/edits_inprogress_0000000000000000001
> ->
> /tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name-0-2/current/edits_0000000000000000001-0000000000000000002
> 2018-07-31 21:42:47,012 [FSEditLogAsync] INFO namenode.FSEditLog
> (FSEditLogAsync.java:run(198)) - FSEditLogAsync was interrupted, exiting
> 2018-07-31 21:42:47,013 [CacheReplicationMonitor(1111752355)] INFO
> blockmanagement.CacheReplicationMonitor
> (CacheReplicationMonitor.java:run(169)) - Shutting down
> CacheReplicationMonitor
> 2018-07-31 21:42:47,014 [main] INFO ipc.Server (Server.java:stop(3074)) -
> Stopping server on port1
> 2018-07-31 21:42:47,015 [IPC Server Responder] INFO ipc.Server
> (Server.java:run(1312)) - Stopping IPC Server Responder
> 2018-07-31 21:42:47,015 [IPC Server listener on port1] INFO ipc.Server
> (Server.java:run(1178)) - Stopping IPC Server listener on port1
> 2018-07-31 21:42:47,015 [StorageInfoMonitor] INFO
> blockmanagement.BlockManager (BlockManager.java:run(4479)) - Stopping thread.
> 2018-07-31 21:42:47,017 [RedundancyMonitor] INFO
> blockmanagement.BlockManager (BlockManager.java:run(4444)) - Stopping
> RedundancyMonitor.
> 2018-07-31 21:42:47,026 [main] INFO namenode.FSNamesystem
> (FSNamesystem.java:stopActiveServices(1339)) - Stopping services started for
> active state
> 2018-07-31 21:42:47,026 [main] INFO namenode.FSNamesystem
> (FSNamesystem.java:stopStandbyServices(1435)) - Stopping services started for
> standby state
> 2018-07-31 21:42:47,028 [main] INFO handler.ContextHandler
> (ContextHandler.java:doStop(910)) - Stopped
> o.e.j.w.WebAppContext@1c758545\{/,null,UNAVAILABLE} \{/hdfs}
> 2018-07-31 21:42:47,029 [main] INFO server.AbstractConnector
> (AbstractConnector.java:doStop(318)) - Stopped ServerConnector@117bcfdc
> {HTTP/1.1,[http/1.1]} \{localhost:0}
> 2018-07-31 21:42:47,029 [main] INFO handler.ContextHandler
> (ContextHandler.java:doStop(910)) - Stopped
> o.e.j.s.ServletContextHandler@6f4ade6e
> {/static,file:///tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test-classes/webapps/static/,UNAVAILABLE}
> 2018-07-31 21:42:47,029 [main] INFO handler.ContextHandler
> (ContextHandler.java:doStop(910)) - Stopped
> o.e.j.s.ServletContextHandler@514cd540
> {/logs,file:///tmp/tmp.u8GhlLcdks/src/CDH/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/log/,UNAVAILABLE}
> 2018-07-31 21:42:47,030 [main] INFO impl.MetricsSystemImpl
> (MetricsSystemImpl.java:stop(210)) - Stopping DataNode metrics system...
> 2018-07-31 21:42:47,031 [main] INFO impl.MetricsSystemImpl
> (MetricsSystemImpl.java:stop(216)) - DataNode metrics system stopped.
> 2018-07-31 21:42:47,031 [main] INFO impl.MetricsSystemImpl
> (MetricsSystemImpl.java:shutdown(607)) - DataNode metrics system shutdown
> complete.
> {noformat}
>
>
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: hdfs-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: hdfs-issues-h...@hadoop.apache.org
