Shweta created HDFS-13837:
-----------------------------
Summary: hdfs.TestDistributedFileSystem.testDFSClient: test is
flaky
Key: HDFS-13837
URL: https://issues.apache.org/jira/browse/HDFS-13837
Project: Hadoop HDFS
Issue Type: Bug
Components: hdfs
Reporter: Shweta
Assignee: Shweta
Attachments: TestDistributedFileSystem.testDFSClient_Stderr_log
Stack Trace :
java.lang.AssertionError
at
org.apache.hadoop.hdfs.TestDistributedFileSystem.testDFSClient(TestDistributedFileSystem.java:449)
Stdout:
{no format}
[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
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] 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
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] 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.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: hdfs-dev-unsubscr...@hadoop.apache.org
For additional commands, e-mail: hdfs-dev-h...@hadoop.apache.org
