[
https://issues.apache.org/jira/browse/HBASE-13294?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14372477#comment-14372477
]
Srikanth Srungarapu commented on HBASE-13294:
---------------------------------------------
Looking at the cause for test failures in jenkins, there seems to be a problem
spinning up cluster. The test is running well on local box. Re-attaching the
patch for another try.
{code}
Failed
org.apache.hadoop.hbase.security.access.TestAccessController.org.apache.hadoop.hbase.security.access.TestAccessController
Failing for the past 1 build (Since Failed#13344 )
Took 6 ms.
Error Message
Shutting down
Stacktrace
java.io.IOException: Shutting down
at
org.apache.hadoop.hbase.util.JVMClusterUtil.startup(JVMClusterUtil.java:225)
at
org.apache.hadoop.hbase.LocalHBaseCluster.startup(LocalHBaseCluster.java:437)
at
org.apache.hadoop.hbase.MiniHBaseCluster.init(MiniHBaseCluster.java:224)
at
org.apache.hadoop.hbase.MiniHBaseCluster.<init>(MiniHBaseCluster.java:93)
at
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniHBaseCluster(HBaseTestingUtility.java:1008)
at
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:968)
at
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:842)
at
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:836)
at
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:780)
at
org.apache.hadoop.hbase.security.access.TestAccessController.setupBeforeClass(TestAccessController.java:191)
Standard Output
Formatting using clusterid: testClusterID
Process Thread Dump: Thread dump because: Master not initialized after 200000ms
seconds
70 active threads
Thread 287 (IPC Parameter Sending Thread #1):
State: TIMED_WAITING
Blocked count: 0
Waited count: 66
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:359)
java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:942)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:744)
Thread 263 (HBase-Metrics2-1):
State: TIMED_WAITING
Blocked count: 0
Waited count: 79
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:744)
Thread 189 (AsyncRpcChannel-timer-pool1-t1):
State: TIMED_WAITING
Blocked count: 0
Waited count: 1986
Stack:
java.lang.Thread.sleep(Native Method)
io.netty.util.HashedWheelTimer$Worker.waitForNextTick(HashedWheelTimer.java:461)
io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:360)
java.lang.Thread.run(Thread.java:744)
Thread 190 (AsyncRpcChannel-pool2-t1):
State: RUNNABLE
Blocked count: 0
Waited count: 0
Stack:
sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:622)
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:310)
io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116)
java.lang.Thread.run(Thread.java:744)
Thread 251 (snapshot-hfile-cleaner-cache-refresher):
State: TIMED_WAITING
Blocked count: 0
Waited count: 1
Stack:
java.lang.Object.wait(Native Method)
java.util.TimerThread.mainLoop(Timer.java:552)
java.util.TimerThread.run(Timer.java:505)
Thread 250 (snapshot-log-cleaner-cache-refresher):
State: TIMED_WAITING
Blocked count: 0
Waited count: 1
Stack:
java.lang.Object.wait(Native Method)
java.util.TimerThread.mainLoop(Timer.java:552)
java.util.TimerThread.run(Timer.java:505)
Thread 248 (proserpina:38530.activeMasterManager-EventThread):
State: WAITING
Blocked count: 0
Waited count: 3
Waiting on
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@707a9713
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:494)
Thread 247 (proserpina:38530.activeMasterManager-SendThread(localhost:55239)):
State: RUNNABLE
Blocked count: 2
Waited count: 0
Stack:
sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:349)
org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1081)
Thread 155 (org.apache.hadoop.hdfs.PeerCache@37f28e66):
State: TIMED_WAITING
Blocked count: 0
Waited count: 67
Stack:
java.lang.Thread.sleep(Native Method)
org.apache.hadoop.hdfs.PeerCache.run(PeerCache.java:244)
org.apache.hadoop.hdfs.PeerCache.access$000(PeerCache.java:41)
org.apache.hadoop.hdfs.PeerCache$1.run(PeerCache.java:119)
java.lang.Thread.run(Thread.java:744)
Thread 140 (Thread-102):
State: TIMED_WAITING
Blocked count: 0
Waited count: 1
Stack:
java.lang.Thread.sleep(Native Method)
org.apache.hadoop.hbase.master.HMaster$InitializationMonitor.run(HMaster.java:197)
java.lang.Thread.run(Thread.java:744)
Thread 93 (ProcessThread(sid:0 cport:-1):):
State: WAITING
Blocked count: 0
Waited count: 158
Waiting on
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@3c0bc4b5
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
org.apache.zookeeper.server.PrepRequestProcessor.run(PrepRequestProcessor.java:120)
Thread 92 (SyncThread:0):
State: WAITING
Blocked count: 0
Waited count: 128
Waiting on
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@289f65df
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
org.apache.zookeeper.server.SyncRequestProcessor.run(SyncRequestProcessor.java:127)
Thread 91 (SessionTracker):
State: TIMED_WAITING
Blocked count: 0
Waited count: 103
Stack:
java.lang.Object.wait(Native Method)
org.apache.zookeeper.server.SessionTrackerImpl.run(SessionTrackerImpl.java:146)
Thread 90 (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:55239):
State: RUNNABLE
Blocked count: 3
Waited count: 0
Stack:
sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:178)
java.lang.Thread.run(Thread.java:744)
Thread 87
(refreshUsed-/home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-server/target/test-data/5d031ef7-820c-47c8-9f14-20a54526f48a/dfscluster_d80b1d01-c629-432f-832e-eb812b7810fa/dfs/data/data2/current/BP-27234177-67.195.81.189-1426903856367):
State: TIMED_WAITING
Blocked count: 0
Waited count: 1
Stack:
java.lang.Thread.sleep(Native Method)
org.apache.hadoop.fs.DU$DURefreshThread.run(DU.java:115)
java.lang.Thread.run(Thread.java:744)
Thread 86
(refreshUsed-/home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-server/target/test-data/5d031ef7-820c-47c8-9f14-20a54526f48a/dfscluster_d80b1d01-c629-432f-832e-eb812b7810fa/dfs/data/data1/current/BP-27234177-67.195.81.189-1426903856367):
State: TIMED_WAITING
Blocked count: 0
Waited count: 1
Stack:
java.lang.Thread.sleep(Native Method)
org.apache.hadoop.fs.DU$DURefreshThread.run(DU.java:115)
java.lang.Thread.run(Thread.java:744)
Thread 80 (java.util.concurrent.ThreadPoolExecutor$Worker@4b35baa7[State = -1,
empty queue]):
State: TIMED_WAITING
Blocked count: 0
Waited count: 1
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090)
java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
java.lang.Thread.run(Thread.java:744)
Thread 77 (Thread-62):
State: TIMED_WAITING
Blocked count: 0
Waited count: 41
Stack:
java.lang.Thread.sleep(Native Method)
org.apache.hadoop.hdfs.server.datanode.DataBlockScanner.run(DataBlockScanner.java:78)
java.lang.Thread.run(Thread.java:744)
Thread 71 (IPC Client (1743776012) connection to localhost/127.0.0.1:42912 from
jenkins):
State: TIMED_WAITING
Blocked count: 83
Waited count: 83
Stack:
java.lang.Object.wait(Native Method)
org.apache.hadoop.ipc.Client$Connection.waitForWork(Client.java:904)
org.apache.hadoop.ipc.Client$Connection.run(Client.java:949)
Thread 70 (IPC Server handler 9 on 34438):
State: TIMED_WAITING
Blocked count: 0
Waited count: 252
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 69 (IPC Server handler 8 on 34438):
State: TIMED_WAITING
Blocked count: 0
Waited count: 247
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 68 (IPC Server handler 7 on 34438):
State: TIMED_WAITING
Blocked count: 0
Waited count: 214
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 67 (IPC Server handler 6 on 34438):
State: TIMED_WAITING
Blocked count: 0
Waited count: 246
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 66 (IPC Server handler 5 on 34438):
State: TIMED_WAITING
Blocked count: 0
Waited count: 256
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 65 (IPC Server handler 4 on 34438):
State: TIMED_WAITING
Blocked count: 0
Waited count: 229
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 64 (IPC Server handler 3 on 34438):
State: TIMED_WAITING
Blocked count: 0
Waited count: 255
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 63 (IPC Server handler 2 on 34438):
State: TIMED_WAITING
Blocked count: 0
Waited count: 242
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 62 (IPC Server handler 1 on 34438):
State: TIMED_WAITING
Blocked count: 0
Waited count: 236
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 61 (IPC Server handler 0 on 34438):
State: TIMED_WAITING
Blocked count: 0
Waited count: 238
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 56 (IPC Server listener on 34438):
State: RUNNABLE
Blocked count: 0
Waited count: 0
Stack:
sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
sun.nio.ch.SelectorImpl.select(SelectorImpl.java:102)
org.apache.hadoop.ipc.Server$Listener.run(Server.java:668)
Thread 59 (IPC Server Responder):
State: RUNNABLE
Blocked count: 0
Waited count: 0
Stack:
sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
org.apache.hadoop.ipc.Server$Responder.doRunLoop(Server.java:835)
org.apache.hadoop.ipc.Server$Responder.run(Server.java:818)
Thread 51 (org.apache.hadoop.hdfs.server.datanode.DataXceiverServer@599556aa):
State: RUNNABLE
Blocked count: 0
Waited count: 0
Stack:
sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:241)
sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:100)
org.apache.hadoop.hdfs.net.TcpPeerServer.accept(TcpPeerServer.java:134)
org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:137)
java.lang.Thread.run(Thread.java:744)
Thread 60 (DataNode:
[[[DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-server/target/test-data/5d031ef7-820c-47c8-9f14-20a54526f48a/dfscluster_d80b1d01-c629-432f-832e-eb812b7810fa/dfs/data/data1/,
[DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-server/target/test-data/5d031ef7-820c-47c8-9f14-20a54526f48a/dfscluster_d80b1d01-c629-432f-832e-eb812b7810fa/dfs/data/data2/]]
heartbeating to localhost/127.0.0.1:42912):
State: TIMED_WAITING
Blocked count: 128
Waited count: 245
Stack:
java.lang.Object.wait(Native Method)
org.apache.hadoop.hdfs.server.datanode.BPServiceActor.offerService(BPServiceActor.java:720)
org.apache.hadoop.hdfs.server.datanode.BPServiceActor.run(BPServiceActor.java:834)
java.lang.Thread.run(Thread.java:744)
Thread 58 (IPC Server idle connection scanner for port 34438):
State: TIMED_WAITING
Blocked count: 1
Waited count: 22
Stack:
java.lang.Object.wait(Native Method)
java.util.TimerThread.mainLoop(Timer.java:552)
java.util.TimerThread.run(Timer.java:505)
Thread 57 (Socket Reader #1 for port 34438):
State: RUNNABLE
Blocked count: 0
Waited count: 0
Stack:
sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
sun.nio.ch.SelectorImpl.select(SelectorImpl.java:102)
org.apache.hadoop.ipc.Server$Listener$Reader.doRunLoop(Server.java:616)
org.apache.hadoop.ipc.Server$Listener$Reader.run(Server.java:595)
Thread 55 (org.apache.hadoop.util.JvmPauseMonitor$Monitor@3c65666c):
State: TIMED_WAITING
Blocked count: 0
Waited count: 411
Stack:
java.lang.Thread.sleep(Native Method)
org.apache.hadoop.util.JvmPauseMonitor$Monitor.run(JvmPauseMonitor.java:180)
java.lang.Thread.run(Thread.java:744)
Thread 54 (Timer-1):
State: TIMED_WAITING
Blocked count: 0
Waited count: 7
Stack:
java.lang.Object.wait(Native Method)
java.util.TimerThread.mainLoop(Timer.java:552)
java.util.TimerThread.run(Timer.java:505)
Thread 53 (743692891@qtp-424890708-1 - Acceptor0
HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:37974):
State: RUNNABLE
Blocked count: 1
Waited count: 1
Stack:
sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
org.mortbay.io.nio.SelectorManager$SelectSet.doSelect(SelectorManager.java:498)
org.mortbay.io.nio.SelectorManager.doSelect(SelectorManager.java:192)
org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:124)
org.mortbay.jetty.AbstractConnector$Acceptor.run(AbstractConnector.java:708)
org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)
Thread 52 (1114171041@qtp-424890708-0):
State: TIMED_WAITING
Blocked count: 0
Waited count: 4
Stack:
java.lang.Object.wait(Native Method)
org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:626)
Thread 46 (CacheReplicationMonitor(1637185326)):
State: TIMED_WAITING
Blocked count: 0
Waited count: 7
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2176)
org.apache.hadoop.hdfs.server.blockmanagement.CacheReplicationMonitor.run(CacheReplicationMonitor.java:181)
Thread 45
(org.apache.hadoop.hdfs.server.namenode.FSNamesystem$NameNodeEditLogRoller@7cc8b288):
State: TIMED_WAITING
Blocked count: 0
Waited count: 1
Stack:
java.lang.Thread.sleep(Native Method)
org.apache.hadoop.hdfs.server.namenode.FSNamesystem$NameNodeEditLogRoller.run(FSNamesystem.java:4726)
java.lang.Thread.run(Thread.java:744)
Thread 44
(org.apache.hadoop.hdfs.server.namenode.FSNamesystem$NameNodeResourceMonitor@1bbbfb71):
State: TIMED_WAITING
Blocked count: 0
Waited count: 42
Stack:
java.lang.Thread.sleep(Native Method)
org.apache.hadoop.hdfs.server.namenode.FSNamesystem$NameNodeResourceMonitor.run(FSNamesystem.java:4687)
java.lang.Thread.run(Thread.java:744)
Thread 43
(org.apache.hadoop.hdfs.server.namenode.LeaseManager$Monitor@57b3fe3c):
State: TIMED_WAITING
Blocked count: 0
Waited count: 104
Stack:
java.lang.Thread.sleep(Native Method)
org.apache.hadoop.hdfs.server.namenode.LeaseManager$Monitor.run(LeaseManager.java:392)
java.lang.Thread.run(Thread.java:744)
Thread 42 (IPC Server handler 9 on 42912):
State: TIMED_WAITING
Blocked count: 0
Waited count: 239
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 41 (IPC Server handler 8 on 42912):
State: TIMED_WAITING
Blocked count: 0
Waited count: 213
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 40 (IPC Server handler 7 on 42912):
State: TIMED_WAITING
Blocked count: 0
Waited count: 260
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 39 (IPC Server handler 6 on 42912):
State: TIMED_WAITING
Blocked count: 0
Waited count: 213
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 38 (IPC Server handler 5 on 42912):
State: TIMED_WAITING
Blocked count: 1
Waited count: 214
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 37 (IPC Server handler 4 on 42912):
State: TIMED_WAITING
Blocked count: 0
Waited count: 213
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 36 (IPC Server handler 3 on 42912):
State: TIMED_WAITING
Blocked count: 0
Waited count: 213
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 35 (IPC Server handler 2 on 42912):
State: TIMED_WAITING
Blocked count: 0
Waited count: 214
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 34 (IPC Server handler 1 on 42912):
State: TIMED_WAITING
Blocked count: 0
Waited count: 214
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 33 (IPC Server handler 0 on 42912):
State: TIMED_WAITING
Blocked count: 12
Waited count: 243
Stack:
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
org.apache.hadoop.ipc.CallQueueManager.take(CallQueueManager.java:109)
org.apache.hadoop.ipc.Server$Handler.run(Server.java:1985)
Thread 23 (IPC Server listener on 42912):
State: RUNNABLE
Blocked count: 0
Waited count: 0
Stack:
sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
sun.nio.ch.SelectorImpl.select(SelectorImpl.java:102)
org.apache.hadoop.ipc.Server$Listener.run(Server.java:668)
Thread 26 (IPC Server Responder):
State: RUNNABLE
Blocked count: 0
Waited count: 0
Stack:
sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
org.apache.hadoop.ipc.Server$Responder.doRunLoop(Server.java:835)
org.apache.hadoop.ipc.Server$Responder.run(Server.java:818)
Thread 21
(org.apache.hadoop.hdfs.server.blockmanagement.BlockManager$ReplicationMonitor@6b7dcfcd):
State: TIMED_WAITING
Blocked count: 0
Waited count: 70
Stack:
java.lang.Thread.sleep(Native Method)
org.apache.hadoop.hdfs.server.blockmanagement.BlockManager$ReplicationMonitor.run(BlockManager.java:3397)
java.lang.Thread.run(Thread.java:744)
Thread 22
(org.apache.hadoop.hdfs.server.blockmanagement.HeartbeatManager$Monitor@10d5d2dd):
State: TIMED_WAITING
Blocked count: 0
Waited count: 42
Stack:
java.lang.Thread.sleep(Native Method)
org.apache.hadoop.hdfs.server.blockmanagement.HeartbeatManager$Monitor.run(HeartbeatManager.java:319)
java.lang.Thread.run(Thread.java:744)
Thread 32
(org.apache.hadoop.hdfs.server.blockmanagement.DecommissionManager$Monitor@10c8414a):
State: TIMED_WAITING
Blocked count: 0
Waited count: 70
Stack:
java.lang.Thread.sleep(Native Method)
org.apache.hadoop.hdfs.server.blockmanagement.DecommissionManager$Monitor.run(DecommissionManager.java:76)
java.lang.Thread.run(Thread.java:744)
Thread 31
(org.apache.hadoop.hdfs.server.blockmanagement.PendingReplicationBlocks$PendingReplicationMonitor@4ba6ee31):
State: TIMED_WAITING
Blocked count: 0
Waited count: 1
Stack:
java.lang.Thread.sleep(Native Method)
org.apache.hadoop.hdfs.server.blockmanagement.PendingReplicationBlocks$PendingReplicationMonitor.run(PendingReplicationBlocks.java:221)
java.lang.Thread.run(Thread.java:744)
Thread 27 (org.apache.hadoop.util.JvmPauseMonitor$Monitor@3301378d):
State: TIMED_WAITING
Blocked count: 1
Waited count: 412
Stack:
java.lang.Thread.sleep(Native Method)
org.apache.hadoop.util.JvmPauseMonitor$Monitor.run(JvmPauseMonitor.java:180)
java.lang.Thread.run(Thread.java:744)
Thread 25 (IPC Server idle connection scanner for port 42912):
State: TIMED_WAITING
Blocked count: 1
Waited count: 22
Stack:
java.lang.Object.wait(Native Method)
java.util.TimerThread.mainLoop(Timer.java:552)
java.util.TimerThread.run(Timer.java:505)
Thread 24 (Socket Reader #1 for port 42912):
State: RUNNABLE
Blocked count: 1
Waited count: 0
Stack:
sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
sun.nio.ch.SelectorImpl.select(SelectorImpl.java:102)
org.apache.hadoop.ipc.Server$Listener$Reader.doRunLoop(Server.java:616)
org.apache.hadoop.ipc.Server$Listener$Reader.run(Server.java:595)
Thread 20 (Timer-0):
State: TIMED_WAITING
Blocked count: 1
Waited count: 8
Stack:
java.lang.Object.wait(Native Method)
java.util.TimerThread.mainLoop(Timer.java:552)
java.util.TimerThread.run(Timer.java:505)
Thread 19 (108697051@qtp-1424309400-1 - Acceptor0
HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:46463):
State: RUNNABLE
Blocked count: 1
Waited count: 1
Stack:
sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
org.mortbay.io.nio.SelectorManager$SelectSet.doSelect(SelectorManager.java:498)
org.mortbay.io.nio.SelectorManager.doSelect(SelectorManager.java:192)
org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:124)
org.mortbay.jetty.AbstractConnector$Acceptor.run(AbstractConnector.java:708)
org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)
Thread 18 (2111490614@qtp-1424309400-0):
State: TIMED_WAITING
Blocked count: 0
Waited count: 4
Stack:
java.lang.Object.wait(Native Method)
org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:626)
Thread 16 (Timer for 'NameNode' metrics system):
State: TIMED_WAITING
Blocked count: 0
Waited count: 21
Stack:
java.lang.Object.wait(Native Method)
java.util.TimerThread.mainLoop(Timer.java:552)
java.util.TimerThread.run(Timer.java:505)
Thread 4 (Signal Dispatcher):
State: RUNNABLE
Blocked count: 0
Waited count: 0
Stack:
Thread 3 (Finalizer):
State: WAITING
Blocked count: 34
Waited count: 3
Waiting on java.lang.ref.ReferenceQueue$Lock@7ce28a19
Stack:
java.lang.Object.wait(Native Method)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:189)
Thread 2 (Reference Handler):
State: WAITING
Blocked count: 5
Waited count: 4
Waiting on java.lang.ref.Reference$Lock@7cd8af5c
Stack:
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:503)
java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
Thread 1 (main):
State: RUNNABLE
Blocked count: 93
Waited count: 506
Stack:
sun.management.ThreadImpl.getThreadInfo1(Native Method)
sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:174)
sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:139)
org.apache.hadoop.util.ReflectionUtils.printThreadInfo(ReflectionUtils.java:165)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:606)
org.apache.hadoop.hbase.util.Threads.printThreadInfo(Threads.java:302)
org.apache.hadoop.hbase.util.JVMClusterUtil.startup(JVMClusterUtil.java:223)
org.apache.hadoop.hbase.LocalHBaseCluster.startup(LocalHBaseCluster.java:437)
org.apache.hadoop.hbase.MiniHBaseCluster.init(MiniHBaseCluster.java:224)
org.apache.hadoop.hbase.MiniHBaseCluster.<init>(MiniHBaseCluster.java:93)
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniHBaseCluster(HBaseTestingUtility.java:1008)
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:968)
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:842)
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:836)
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:780)
org.apache.hadoop.hbase.security.access.TestAccessController.setupBeforeClass(TestAccessController.java:191)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Standard Error
2015-03-21 02:10:53,725 WARN [main] util.NativeCodeLoader(62): Unable to load
native-hadoop library for your platform... using builtin-java classes where
applicable
2015-03-21 02:10:54,071 INFO [main] hbase.HBaseTestingUtility(946): Starting
up minicluster with 1 master(s) and 1 regionserver(s) and 1 datanode(s)
2015-03-21 02:10:54,156 INFO [main] hbase.HBaseTestingUtility(436): Created
new mini-cluster data directory:
/home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-server/target/test-data/5d031ef7-820c-47c8-9f14-20a54526f48a/dfscluster_d80b1d01-c629-432f-832e-eb812b7810fa,
deleteOnExit=true
2015-03-21 02:10:54,158 INFO [main] hbase.HBaseTestingUtility(676): Setting
test.cache.data to
/home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-server/target/test-data/5d031ef7-820c-47c8-9f14-20a54526f48a/cache_data
in system properties and HBase conf
2015-03-21 02:10:54,159 INFO [main] hbase.HBaseTestingUtility(676): Setting
hadoop.tmp.dir to
/home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-server/target/test-data/5d031ef7-820c-47c8-9f14-20a54526f48a/hadoop_tmp
in system properties and HBase conf
2015-03-21 02:10:54,160 INFO [main] hbase.HBaseTestingUtility(676): Setting
hadoop.log.dir to
/home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-server/target/test-data/5d031ef7-820c-47c8-9f14-20a54526f48a/hadoop_logs
in system properties and HBase conf
2015-03-21 02:10:54,161 INFO [main] hbase.HBaseTestingUtility(676): Setting
mapreduce.cluster.local.dir to
/home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-server/target/test-data/5d031ef7-820c-47c8-9f14-20a54526f48a/mapred_local
in system properties and HBase conf
2015-03-21 02:10:54,162 INFO [main] hbase.HBaseTestingUtility(676): Setting
mapreduce.cluster.temp.dir to
/home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-server/target/test-data/5d031ef7-820c-47c8-9f14-20a54526f48a/mapred_temp
in system properties and HBase conf
2015-03-21 02:10:54,167 INFO [main] hbase.HBaseTestingUtility(667): read short
circuit is OFF
2015-03-21 02:10:54,519 DEBUG [main] fs.HFileSystem(221): The file system is
not a DistributedFileSystem. Skipping on block location reordering
2015-03-21 02:10:57,128 WARN [main] impl.MetricsConfig(124): Cannot locate
configuration: tried
hadoop-metrics2-namenode.properties,hadoop-metrics2.properties
2015-03-21 02:10:57,371 INFO [main] log.Slf4jLog(67): Logging to
org.slf4j.impl.Log4jLoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog
2015-03-21 02:10:57,457 INFO [main] log.Slf4jLog(67): jetty-6.1.26
2015-03-21 02:10:57,501 INFO [main] log.Slf4jLog(67): Extract
jar:file:/home/jenkins/.m2/repository/org/apache/hadoop/hadoop-hdfs/2.5.1/hadoop-hdfs-2.5.1-tests.jar!/webapps/hdfs
to /tmp/Jetty_localhost_46463_hdfs____.smgs9z/webapp
2015-03-21 02:10:57,923 WARN [main] server.AuthenticationFilter(166):
'signature.secret' configuration not set, using a random value as secret
2015-03-21 02:10:57,997 INFO [main] log.Slf4jLog(67): Started
HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:46463
2015-03-21 02:10:59,540 INFO [main] log.Slf4jLog(67): jetty-6.1.26
2015-03-21 02:10:59,562 INFO [main] log.Slf4jLog(67): Extract
jar:file:/home/jenkins/.m2/repository/org/apache/hadoop/hadoop-hdfs/2.5.1/hadoop-hdfs-2.5.1-tests.jar!/webapps/datanode
to /tmp/Jetty_localhost_37974_datanode____72s1cp/webapp
2015-03-21 02:10:59,764 INFO [main] log.Slf4jLog(67): Started
HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:37974
2015-03-21 02:11:01,200 INFO [IPC Server handler 7 on 42912]
blockmanagement.BlockManager(1753): BLOCK* processReport: from storage
DS-20704df4-ae22-40c7-8dcd-b411672f6980 node DatanodeRegistration(127.0.0.1,
datanodeUuid=bf0194c5-f830-4a3c-a9e4-a3e5516d3196, infoPort=37974,
ipcPort=34438, storageInfo=lv=-55;cid=testClusterID;nsid=1057254946;c=0),
blocks: 0, hasStaleStorages: true, processing time: 3 msecs
2015-03-21 02:11:01,200 INFO [IPC Server handler 7 on 42912]
blockmanagement.BlockManager(1753): BLOCK* processReport: from storage
DS-a2d75141-06d2-4e32-a0f7-999efc9c94fc node DatanodeRegistration(127.0.0.1,
datanodeUuid=bf0194c5-f830-4a3c-a9e4-a3e5516d3196, infoPort=37974,
ipcPort=34438, storageInfo=lv=-55;cid=testClusterID;nsid=1057254946;c=0),
blocks: 0, hasStaleStorages: false, processing time: 0 msecs
2015-03-21 02:11:01,374 INFO [main] zookeeper.MiniZooKeeperCluster(273):
Started MiniZooKeeperCluster and ran successful 'stat' on client port=55239
2015-03-21 02:11:01,409 INFO [main] fs.HFileSystem(252): Added intercepting
call to namenode#getBlockLocations so can do block reordering using class class
org.apache.hadoop.hbase.fs.HFileSystem$ReorderWALBlocks
2015-03-21 02:11:01,418 INFO [main] fs.HFileSystem(252): Added intercepting
call to namenode#getBlockLocations so can do block reordering using class class
org.apache.hadoop.hbase.fs.HFileSystem$ReorderWALBlocks
2015-03-21 02:11:02,029 INFO [IPC Server handler 8 on 42912]
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated:
127.0.0.1:54374 is added to
blk_1073741825_1001{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-20704df4-ae22-40c7-8dcd-b411672f6980:NORMAL|RBW]]}
size 0
2015-03-21 02:11:02,074 INFO [main] util.FSUtils(712): Created version file at
hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6
with version=8
2015-03-21 02:11:02,354 INFO [main] client.ConnectionUtils(105):
master/proserpina.apache.org/67.195.81.189:0 server-side HConnection retries=350
2015-03-21 02:11:02,728 INFO [main] ipc.SimpleRpcScheduler(128): Using
deadline as user call queue, count=1
2015-03-21 02:11:02,829 INFO [main] ipc.RpcServer$Listener(567):
master/proserpina.apache.org/67.195.81.189:0: started 10 reader(s).
2015-03-21 02:11:02,870 INFO [main] fs.HFileSystem(252): Added intercepting
call to namenode#getBlockLocations so can do block reordering using class class
org.apache.hadoop.hbase.fs.HFileSystem$ReorderWALBlocks
2015-03-21 02:11:03,102 INFO [main] zookeeper.RecoverableZooKeeper(121):
Process identifier=master:38530 connecting to ZooKeeper ensemble=localhost:55239
2015-03-21 02:11:03,938 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): master:385300x0, quorum=localhost:55239,
baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected,
path=null
2015-03-21 02:11:03,940 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(472): master:38530-0x14c3a1908520000 connected
2015-03-21 02:11:04,142 DEBUG [main] zookeeper.ZKUtil(488):
master:38530-0x14c3a1908520000, quorum=localhost:55239, baseZNode=/hbase Set
watcher on znode that does not yet exist, /hbase/master
2015-03-21 02:11:04,144 DEBUG [main] zookeeper.ZKUtil(488):
master:38530-0x14c3a1908520000, quorum=localhost:55239, baseZNode=/hbase Set
watcher on znode that does not yet exist, /hbase/running
2015-03-21 02:11:04,162 INFO [RpcServer.responder]
ipc.RpcServer$Responder(886): RpcServer.responder: starting
2015-03-21 02:11:04,186 DEBUG [main] ipc.RpcExecutor(114): B.default Start
Handler index=0 queue=0
2015-03-21 02:11:04,187 INFO [RpcServer.listener,port=38530]
ipc.RpcServer$Listener(698): RpcServer.listener,port=38530: starting
2015-03-21 02:11:04,187 DEBUG [main] ipc.RpcExecutor(114): B.default Start
Handler index=1 queue=0
2015-03-21 02:11:04,206 DEBUG [main] ipc.RpcExecutor(114): B.default Start
Handler index=2 queue=0
2015-03-21 02:11:04,209 DEBUG [main] ipc.RpcExecutor(114): B.default Start
Handler index=3 queue=0
2015-03-21 02:11:04,209 DEBUG [main] ipc.RpcExecutor(114): B.default Start
Handler index=4 queue=0
2015-03-21 02:11:04,212 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=0 queue=0
2015-03-21 02:11:04,214 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=1 queue=1
2015-03-21 02:11:04,215 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=2 queue=0
2015-03-21 02:11:04,215 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=3 queue=1
2015-03-21 02:11:04,216 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=4 queue=0
2015-03-21 02:11:04,233 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=5 queue=1
2015-03-21 02:11:04,239 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=6 queue=0
2015-03-21 02:11:04,244 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=7 queue=1
2015-03-21 02:11:04,250 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=8 queue=0
2015-03-21 02:11:04,255 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=9 queue=1
2015-03-21 02:11:04,256 DEBUG [main] ipc.RpcExecutor(114): Replication Start
Handler index=0 queue=0
2015-03-21 02:11:04,257 DEBUG [main] ipc.RpcExecutor(114): Replication Start
Handler index=1 queue=0
2015-03-21 02:11:04,257 DEBUG [main] ipc.RpcExecutor(114): Replication Start
Handler index=2 queue=0
2015-03-21 02:11:04,268 INFO [main] http.HttpRequestLog(69): Http request log
for http.requests.master is not defined
2015-03-21 02:11:04,273 INFO [main] http.HttpServer(819): Added global filter
'safety' (class=org.apache.hadoop.hbase.http.HttpServer$QuotingInputFilter)
2015-03-21 02:11:04,276 INFO [main] http.HttpServer(797): Added filter
static_user_filter
(class=org.apache.hadoop.hbase.http.lib.StaticUserWebFilter$StaticUserFilter)
to context master
2015-03-21 02:11:04,277 INFO [main] http.HttpServer(804): Added filter
static_user_filter
(class=org.apache.hadoop.hbase.http.lib.StaticUserWebFilter$StaticUserFilter)
to context logs
2015-03-21 02:11:04,277 INFO [main] http.HttpServer(804): Added filter
static_user_filter
(class=org.apache.hadoop.hbase.http.lib.StaticUserWebFilter$StaticUserFilter)
to context static
2015-03-21 02:11:04,292 INFO [main] http.HttpServer(1011): Jetty bound to port
56508
2015-03-21 02:11:04,292 INFO [main] log.Slf4jLog(67): jetty-6.1.26
2015-03-21 02:11:04,364 INFO [main] log.Slf4jLog(67): Started
[email protected]:56508
2015-03-21 02:11:04,383 INFO [main] master.HMaster(338):
hbase.rootdir=hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6,
hbase.cluster.distributed=false
2015-03-21 02:11:04,400 INFO [main] master.HMaster(1423): Adding backup master
ZNode /hbase/backup-masters/proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:04,432 DEBUG [main] zookeeper.ZKUtil(486):
master:38530-0x14c3a1908520000, quorum=localhost:55239, baseZNode=/hbase Set
watcher on existing
znode=/hbase/backup-masters/proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:04,499 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): master:38530-0x14c3a1908520000,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event,
type=NodeCreated, state=SyncConnected, path=/hbase/master
2015-03-21 02:11:04,512 DEBUG [proserpina:38530.activeMasterManager]
zookeeper.ZKUtil(486): master:38530-0x14c3a1908520000, quorum=localhost:55239,
baseZNode=/hbase Set watcher on existing znode=/hbase/master
2015-03-21 02:11:04,515 INFO [proserpina:38530.activeMasterManager]
master.ActiveMasterManager(170): Deleting ZNode for
/hbase/backup-masters/proserpina.apache.org,38530,1426903862856 from backup
master directory
2015-03-21 02:11:04,533 DEBUG [main-EventThread] zookeeper.ZKUtil(486):
master:38530-0x14c3a1908520000, quorum=localhost:55239, baseZNode=/hbase Set
watcher on existing znode=/hbase/master
2015-03-21 02:11:04,533 DEBUG [main-EventThread]
master.ActiveMasterManager(126): A master is now available
2015-03-21 02:11:04,541 WARN [proserpina:38530.activeMasterManager]
hbase.ZNodeClearer(58): Environment variable HBASE_ZNODE_FILE not set; znodes
will not be cleared on crash by start scripts (Longer MTTR!)
2015-03-21 02:11:04,542 INFO [proserpina:38530.activeMasterManager]
master.ActiveMasterManager(179): Registered Active
Master=proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:04,542 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): master:38530-0x14c3a1908520000,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event,
type=NodeDeleted, state=SyncConnected,
path=/hbase/backup-masters/proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:04,657 INFO [main] client.ConnectionUtils(105):
regionserver/proserpina.apache.org/67.195.81.189:0 server-side HConnection
retries=350
2015-03-21 02:11:04,658 INFO [main] ipc.SimpleRpcScheduler(128): Using
deadline as user call queue, count=1
2015-03-21 02:11:04,681 INFO [main] ipc.RpcServer$Listener(567):
regionserver/proserpina.apache.org/67.195.81.189:0: started 10 reader(s).
2015-03-21 02:11:04,692 INFO [main] fs.HFileSystem(252): Added intercepting
call to namenode#getBlockLocations so can do block reordering using class class
org.apache.hadoop.hbase.fs.HFileSystem$ReorderWALBlocks
2015-03-21 02:11:04,696 INFO [main] zookeeper.RecoverableZooKeeper(121):
Process identifier=regionserver:51019 connecting to ZooKeeper
ensemble=localhost:55239
2015-03-21 02:11:04,712 DEBUG [main] zookeeper.ZKUtil(486):
regionserver:510190x0, quorum=localhost:55239, baseZNode=/hbase Set watcher on
existing znode=/hbase/master
2015-03-21 02:11:04,716 DEBUG [main] zookeeper.ZKUtil(488):
regionserver:510190x0, quorum=localhost:55239, baseZNode=/hbase Set watcher on
znode that does not yet exist, /hbase/running
2015-03-21 02:11:04,721 INFO [RpcServer.responder]
ipc.RpcServer$Responder(886): RpcServer.responder: starting
2015-03-21 02:11:04,716 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): regionserver:510190x0, quorum=localhost:55239,
baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected,
path=null
2015-03-21 02:11:04,724 INFO [RpcServer.listener,port=51019]
ipc.RpcServer$Listener(698): RpcServer.listener,port=51019: starting
2015-03-21 02:11:04,723 DEBUG [main] ipc.RpcExecutor(114): B.default Start
Handler index=0 queue=0
2015-03-21 02:11:04,732 DEBUG [main] ipc.RpcExecutor(114): B.default Start
Handler index=1 queue=0
2015-03-21 02:11:04,734 DEBUG [main] ipc.RpcExecutor(114): B.default Start
Handler index=2 queue=0
2015-03-21 02:11:04,739 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(472): regionserver:51019-0x14c3a1908520001 connected
2015-03-21 02:11:04,739 DEBUG [main] ipc.RpcExecutor(114): B.default Start
Handler index=3 queue=0
2015-03-21 02:11:04,740 DEBUG [main] ipc.RpcExecutor(114): B.default Start
Handler index=4 queue=0
2015-03-21 02:11:04,741 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=0 queue=0
2015-03-21 02:11:04,741 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=1 queue=1
2015-03-21 02:11:04,743 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=2 queue=0
2015-03-21 02:11:04,744 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=3 queue=1
2015-03-21 02:11:04,744 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=4 queue=0
2015-03-21 02:11:04,745 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=5 queue=1
2015-03-21 02:11:04,745 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=6 queue=0
2015-03-21 02:11:04,746 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=7 queue=1
2015-03-21 02:11:04,754 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=8 queue=0
2015-03-21 02:11:04,755 DEBUG [main] ipc.RpcExecutor(114): Priority Start
Handler index=9 queue=1
2015-03-21 02:11:04,755 DEBUG [main] ipc.RpcExecutor(114): Replication Start
Handler index=0 queue=0
2015-03-21 02:11:04,756 DEBUG [main] ipc.RpcExecutor(114): Replication Start
Handler index=1 queue=0
2015-03-21 02:11:04,756 DEBUG [main] ipc.RpcExecutor(114): Replication Start
Handler index=2 queue=0
2015-03-21 02:11:04,757 INFO [main] http.HttpRequestLog(69): Http request log
for http.requests.regionserver is not defined
2015-03-21 02:11:04,759 INFO [main] http.HttpServer(819): Added global filter
'safety' (class=org.apache.hadoop.hbase.http.HttpServer$QuotingInputFilter)
2015-03-21 02:11:04,760 INFO [main] http.HttpServer(797): Added filter
static_user_filter
(class=org.apache.hadoop.hbase.http.lib.StaticUserWebFilter$StaticUserFilter)
to context regionserver
2015-03-21 02:11:04,760 INFO [main] http.HttpServer(804): Added filter
static_user_filter
(class=org.apache.hadoop.hbase.http.lib.StaticUserWebFilter$StaticUserFilter)
to context logs
2015-03-21 02:11:04,761 INFO [main] http.HttpServer(804): Added filter
static_user_filter
(class=org.apache.hadoop.hbase.http.lib.StaticUserWebFilter$StaticUserFilter)
to context static
2015-03-21 02:11:04,761 INFO [IPC Server handler 5 on 42912]
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated:
127.0.0.1:54374 is added to blk_1073741826_1002{blockUCState=COMMITTED,
primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-a2d75141-06d2-4e32-a0f7-999efc9c94fc:NORMAL|RBW]]}
size 42
2015-03-21 02:11:04,764 INFO [main] http.HttpServer(1011): Jetty bound to port
57648
2015-03-21 02:11:04,764 INFO [main] log.Slf4jLog(67): jetty-6.1.26
2015-03-21 02:11:04,801 INFO [main] log.Slf4jLog(67): Started
[email protected]:57648
2015-03-21 02:11:04,889 INFO [RS:0;proserpina:51019]
zookeeper.RecoverableZooKeeper(121): Process identifier=hconnection-0x65ff3336
connecting to ZooKeeper ensemble=localhost:55239
2015-03-21 02:11:04,890 INFO [M:0;proserpina:38530]
zookeeper.RecoverableZooKeeper(121): Process identifier=hconnection-0x557b528a
connecting to ZooKeeper ensemble=localhost:55239
2015-03-21 02:11:04,911 DEBUG [RS:0;proserpina:51019-EventThread]
zookeeper.ZooKeeperWatcher(388): hconnection-0x65ff33360x0,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event, type=None,
state=SyncConnected, path=null
2015-03-21 02:11:04,913 DEBUG [RS:0;proserpina:51019-EventThread]
zookeeper.ZooKeeperWatcher(472): hconnection-0x65ff3336-0x14c3a1908520002
connected
2015-03-21 02:11:04,944 DEBUG [M:0;proserpina:38530-EventThread]
zookeeper.ZooKeeperWatcher(388): hconnection-0x557b528a0x0,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event, type=None,
state=SyncConnected, path=null
2015-03-21 02:11:04,945 INFO [RS:0;proserpina:51019]
client.ZooKeeperRegistry(104): ClusterId read in ZooKeeper is null
2015-03-21 02:11:04,945 DEBUG [RS:0;proserpina:51019]
client.ConnectionManager$HConnectionImplementation(847): clusterid came back
null, using default default-cluster
2015-03-21 02:11:04,946 DEBUG [M:0;proserpina:38530-EventThread]
zookeeper.ZooKeeperWatcher(472): hconnection-0x557b528a-0x14c3a1908520003
connected
2015-03-21 02:11:04,946 INFO [M:0;proserpina:38530]
client.ZooKeeperRegistry(104): ClusterId read in ZooKeeper is null
2015-03-21 02:11:04,948 DEBUG [M:0;proserpina:38530]
client.ConnectionManager$HConnectionImplementation(847): clusterid came back
null, using default default-cluster
2015-03-21 02:11:05,020 DEBUG [RS:0;proserpina:51019]
ipc.AbstractRpcClient(105):
Codec=org.apache.hadoop.hbase.codec.KeyValueCodec@3f8429a7, compressor=null,
tcpKeepAlive=true, tcpNoDelay=true, connectTO=10000, readTO=20000,
writeTO=60000, minIdleTimeBeforeClose=120000, maxRetries=0,
fallbackAllowed=true, bind address=null
2015-03-21 02:11:05,020 DEBUG [M:0;proserpina:38530]
ipc.AbstractRpcClient(105):
Codec=org.apache.hadoop.hbase.codec.KeyValueCodec@1c0ba133, compressor=null,
tcpKeepAlive=true, tcpNoDelay=true, connectTO=10000, readTO=20000,
writeTO=60000, minIdleTimeBeforeClose=120000, maxRetries=0,
fallbackAllowed=true, bind address=null
2015-03-21 02:11:05,021 DEBUG [RS:0;proserpina:51019] ipc.AsyncRpcClient(152):
Starting async Hbase RPC client
2015-03-21 02:11:05,021 DEBUG [M:0;proserpina:38530] ipc.AsyncRpcClient(152):
Starting async Hbase RPC client
2015-03-21 02:11:05,021 DEBUG [RS:0;proserpina:51019] ipc.AsyncRpcClient(131):
Create NioEventLoopGroup with maxThreads = 0
2015-03-21 02:11:05,106 DEBUG [RS:0;proserpina:51019] ipc.AsyncRpcClient(106):
Create global event loop group NioEventLoopGroup
2015-03-21 02:11:05,107 DEBUG [M:0;proserpina:38530] ipc.AsyncRpcClient(163):
Use global event loop group NioEventLoopGroup
2015-03-21 02:11:05,107 DEBUG [RS:0;proserpina:51019] ipc.AsyncRpcClient(163):
Use global event loop group NioEventLoopGroup
2015-03-21 02:11:05,173 DEBUG [proserpina:38530.activeMasterManager]
util.FSUtils(864): Created cluster ID file at
hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/hbase.id
with ID: 9500695b-0220-487d-9d12-037e9eed7bc7
2015-03-21 02:11:05,236 INFO [proserpina:38530.activeMasterManager]
master.MasterFileSystem(507): BOOTSTRAP: creating hbase:meta region
2015-03-21 02:11:05,241 INFO [proserpina:38530.activeMasterManager]
regionserver.HRegion(6001): creating HRegion hbase:meta HTD == 'hbase:meta',
{TABLE_ATTRIBUTES => {IS_META => 'true', coprocessor$1 =>
'|org.apache.hadoop.hbase.coprocessor.MultiRowMutationEndpoint|536870911|'},
{NAME => 'info', DATA_BLOCK_ENCODING => 'NONE', BLOOMFILTER => 'NONE',
REPLICATION_SCOPE => '0', COMPRESSION => 'NONE', VERSIONS => '3', TTL =>
'FOREVER', MIN_VERSIONS => '0', CACHE_DATA_IN_L1 => 'true', KEEP_DELETED_CELLS
=> 'FALSE', BLOCKSIZE => '8192', IN_MEMORY => 'false', BLOCKCACHE => 'false'},
{NAME => 'table', DATA_BLOCK_ENCODING => 'NONE', BLOOMFILTER => 'NONE',
REPLICATION_SCOPE => '0', COMPRESSION => 'NONE', VERSIONS => '10', TTL =>
'FOREVER', MIN_VERSIONS => '0', CACHE_DATA_IN_L1 => 'true', KEEP_DELETED_CELLS
=> 'FALSE', BLOCKSIZE => '8192', IN_MEMORY => 'true', BLOCKCACHE => 'true'}
RootDir =
hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6
Table name == hbase:meta
2015-03-21 02:11:05,303 INFO [IPC Server handler 8 on 42912]
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated:
127.0.0.1:54374 is added to
blk_1073741827_1003{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-20704df4-ae22-40c7-8dcd-b411672f6980:NORMAL|RBW]]}
size 0
2015-03-21 02:11:05,312 DEBUG [proserpina:38530.activeMasterManager]
regionserver.HRegion(770): Instantiated hbase:meta,,1.1588230740
2015-03-21 02:11:05,469 INFO [StoreOpener-1588230740-1]
hfile.CacheConfig(470): Allocating LruBlockCache size=995.60 MB, blockSize=64 KB
2015-03-21 02:11:05,498 INFO [StoreOpener-1588230740-1]
hfile.CacheConfig(260): blockCache=LruBlockCache{blockCount=0,
currentSize=1071760, freeSize=1042890544, maxSize=1043962304, heapSize=1071760,
minSize=991764160, minFactor=0.95, multiSize=495882080, multiFactor=0.5,
singleSize=247941040, singleFactor=0.25}, cacheDataOnRead=false,
cacheDataOnWrite=false, cacheIndexesOnWrite=false, cacheBloomsOnWrite=false,
cacheEvictOnClose=false, cacheDataCompressed=false, prefetchOnOpen=false
2015-03-21 02:11:05,510 INFO [StoreOpener-1588230740-1]
compactions.CompactionConfiguration(97): size [134217728, 9223372036854775807);
files [3, 10); ratio 1.200000; off-peak ratio 5.000000; throttle point
2684354560; major period 604800000, major jitter 0.500000, min locality to
compact 0.000000
2015-03-21 02:11:05,519 DEBUG [StoreOpener-1588230740-1]
regionserver.HRegionFileSystem(201): No StoreFiles for:
hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/data/hbase/meta/1588230740/info
2015-03-21 02:11:05,531 DEBUG [StoreOpener-1588230740-1]
util.ChecksumType$2(70): org.apache.hadoop.util.PureJavaCrc32 available
2015-03-21 02:11:05,531 DEBUG [StoreOpener-1588230740-1]
util.ChecksumType$3(113): org.apache.hadoop.util.PureJavaCrc32C available
2015-03-21 02:11:05,539 INFO [StoreOpener-1588230740-1]
hfile.CacheConfig(260): blockCache=LruBlockCache{blockCount=0,
currentSize=1071760, freeSize=1042890544, maxSize=1043962304, heapSize=1071760,
minSize=991764160, minFactor=0.95, multiSize=495882080, multiFactor=0.5,
singleSize=247941040, singleFactor=0.25}, cacheDataOnRead=true,
cacheDataOnWrite=false, cacheIndexesOnWrite=false, cacheBloomsOnWrite=false,
cacheEvictOnClose=false, cacheDataCompressed=false, prefetchOnOpen=false
2015-03-21 02:11:05,542 INFO [StoreOpener-1588230740-1]
compactions.CompactionConfiguration(97): size [134217728, 9223372036854775807);
files [3, 10); ratio 1.200000; off-peak ratio 5.000000; throttle point
2684354560; major period 604800000, major jitter 0.500000, min locality to
compact 0.000000
2015-03-21 02:11:05,547 DEBUG [StoreOpener-1588230740-1]
regionserver.HRegionFileSystem(201): No StoreFiles for:
hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/data/hbase/meta/1588230740/table
2015-03-21 02:11:05,558 DEBUG [proserpina:38530.activeMasterManager]
regionserver.HRegion(3910): Found 0 recovered edits file(s) under
hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/data/hbase/meta/1588230740
2015-03-21 02:11:05,581 DEBUG [proserpina:38530.activeMasterManager]
regionserver.FlushLargeStoresPolicy(56):
hbase.hregion.percolumnfamilyflush.size.lower.bound is not specified, use
global config(16777216) instead
2015-03-21 02:11:05,593 DEBUG [proserpina:38530.activeMasterManager]
wal.WALSplitter(712): Wrote region
seqId=hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/data/hbase/meta/1588230740/recovered.edits/2.seqid
to file, newSeqId=2, maxSeqId=0
2015-03-21 02:11:05,593 INFO [proserpina:38530.activeMasterManager]
regionserver.HRegion(898): Onlined 1588230740; next sequenceid=2
2015-03-21 02:11:05,594 DEBUG [proserpina:38530.activeMasterManager]
regionserver.HRegion(1357): Closing hbase:meta,,1.1588230740: disabling
compactions & flushes
2015-03-21 02:11:05,594 DEBUG [proserpina:38530.activeMasterManager]
regionserver.HRegion(1384): Updates disabled for region hbase:meta,,1.1588230740
2015-03-21 02:11:05,609 INFO [StoreCloserThread-hbase:meta,,1.1588230740-1]
regionserver.HStore(879): Closed info
2015-03-21 02:11:05,610 INFO [StoreCloserThread-hbase:meta,,1.1588230740-1]
regionserver.HStore(879): Closed table
2015-03-21 02:11:05,610 INFO [proserpina:38530.activeMasterManager]
regionserver.HRegion(1476): Closed hbase:meta,,1.1588230740
2015-03-21 02:11:05,677 INFO [IPC Server handler 7 on 42912]
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated:
127.0.0.1:54374 is added to
blk_1073741828_1004{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-a2d75141-06d2-4e32-a0f7-999efc9c94fc:NORMAL|RBW]]}
size 0
2015-03-21 02:11:05,693 DEBUG [proserpina:38530.activeMasterManager]
util.FSTableDescriptors(718): Wrote descriptor into:
hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/data/hbase/meta/.tabledesc/.tableinfo.0000000001
2015-03-21 02:11:05,720 INFO [proserpina:38530.activeMasterManager]
fs.HFileSystem(252): Added intercepting call to namenode#getBlockLocations so
can do block reordering using class class
org.apache.hadoop.hbase.fs.HFileSystem$ReorderWALBlocks
2015-03-21 02:11:05,728 DEBUG [proserpina:38530.activeMasterManager]
coordination.ZKSplitLogManagerCoordination(886): Distributed log replay=true
2015-03-21 02:11:05,736 INFO [proserpina:38530.activeMasterManager]
coordination.ZKSplitLogManagerCoordination(599): Found 0 orphan tasks and 0
rescan nodes
2015-03-21 02:11:05,738 DEBUG [proserpina:38530.activeMasterManager]
util.FSTableDescriptors(222): Fetching table descriptors from the filesystem.
2015-03-21 02:11:05,772 INFO [proserpina:38530.activeMasterManager]
zookeeper.RecoverableZooKeeper(121): Process identifier=hconnection-0x28f86af6
connecting to ZooKeeper ensemble=localhost:55239
2015-03-21 02:11:05,795 DEBUG
[proserpina:38530.activeMasterManager-EventThread]
zookeeper.ZooKeeperWatcher(388): hconnection-0x28f86af60x0,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event, type=None,
state=SyncConnected, path=null
2015-03-21 02:11:05,796 DEBUG
[proserpina:38530.activeMasterManager-EventThread]
zookeeper.ZooKeeperWatcher(472): hconnection-0x28f86af6-0x14c3a1908520004
connected
2015-03-21 02:11:05,802 DEBUG [proserpina:38530.activeMasterManager]
ipc.AbstractRpcClient(105):
Codec=org.apache.hadoop.hbase.codec.KeyValueCodec@38c94d89, compressor=null,
tcpKeepAlive=true, tcpNoDelay=true, connectTO=10000, readTO=20000,
writeTO=60000, minIdleTimeBeforeClose=120000, maxRetries=0,
fallbackAllowed=true, bind address=null
2015-03-21 02:11:05,803 DEBUG [proserpina:38530.activeMasterManager]
ipc.AsyncRpcClient(152): Starting async Hbase RPC client
2015-03-21 02:11:05,804 DEBUG [proserpina:38530.activeMasterManager]
ipc.AsyncRpcClient(163): Use global event loop group NioEventLoopGroup
2015-03-21 02:11:05,826 INFO [proserpina:38530.activeMasterManager]
balancer.StochasticLoadBalancer(135): loading config
2015-03-21 02:11:05,846 DEBUG [proserpina:38530.activeMasterManager]
zookeeper.ZKUtil(488): master:38530-0x14c3a1908520000, quorum=localhost:55239,
baseZNode=/hbase Set watcher on znode that does not yet exist, /hbase/balancer
2015-03-21 02:11:05,894 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): master:38530-0x14c3a1908520000,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event,
type=NodeCreated, state=SyncConnected, path=/hbase/running
2015-03-21 02:11:05,895 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): regionserver:51019-0x14c3a1908520001,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event,
type=NodeCreated, state=SyncConnected, path=/hbase/running
2015-03-21 02:11:05,896 INFO [proserpina:38530.activeMasterManager]
master.HMaster(548): Server active/primary
master=proserpina.apache.org,38530,1426903862856, sessionid=0x14c3a1908520000,
setting cluster-up flag (Was=false)
2015-03-21 02:11:05,898 INFO [M:0;proserpina:38530]
regionserver.HRegionServer(745): ClusterId :
9500695b-0220-487d-9d12-037e9eed7bc7
2015-03-21 02:11:05,912 DEBUG [M:0;proserpina:38530]
procedure.RegionServerProcedureManagerHost(44): Procedure online-snapshot is
initializing
2015-03-21 02:11:05,899 INFO [RS:0;proserpina:51019]
regionserver.HRegionServer(745): ClusterId :
9500695b-0220-487d-9d12-037e9eed7bc7
2015-03-21 02:11:05,913 DEBUG [RS:0;proserpina:51019]
procedure.RegionServerProcedureManagerHost(44): Procedure online-snapshot is
initializing
2015-03-21 02:11:05,961 DEBUG [M:0;proserpina:38530]
zookeeper.RecoverableZooKeeper(531): Node /hbase/online-snapshot already exists
2015-03-21 02:11:05,977 DEBUG [RS:0;proserpina:51019]
zookeeper.RecoverableZooKeeper(531): Node /hbase/online-snapshot/acquired
already exists
2015-03-21 02:11:05,994 DEBUG [M:0;proserpina:38530]
zookeeper.RecoverableZooKeeper(531): Node /hbase/online-snapshot/acquired
already exists
2015-03-21 02:11:06,044 DEBUG [proserpina:38530.activeMasterManager]
zookeeper.RecoverableZooKeeper(531): Node /hbase/online-snapshot/reached
already exists
2015-03-21 02:11:06,070 INFO [proserpina:38530.activeMasterManager]
procedure.ZKProcedureUtil(271): Clearing all procedure znodes:
/hbase/online-snapshot/acquired /hbase/online-snapshot/reached
/hbase/online-snapshot/abort
2015-03-21 02:11:06,070 DEBUG [M:0;proserpina:38530]
procedure.RegionServerProcedureManagerHost(46): Procedure online-snapshot is
initialized
2015-03-21 02:11:06,070 DEBUG [RS:0;proserpina:51019]
procedure.RegionServerProcedureManagerHost(46): Procedure online-snapshot is
initialized
2015-03-21 02:11:06,071 DEBUG [M:0;proserpina:38530]
procedure.RegionServerProcedureManagerHost(44): Procedure flush-table-proc is
initializing
2015-03-21 02:11:06,071 DEBUG [RS:0;proserpina:51019]
procedure.RegionServerProcedureManagerHost(44): Procedure flush-table-proc is
initializing
2015-03-21 02:11:06,136 DEBUG [RS:0;proserpina:51019]
zookeeper.RecoverableZooKeeper(531): Node /hbase/flush-table-proc already exists
2015-03-21 02:11:06,136 DEBUG [proserpina:38530.activeMasterManager]
procedure.ZKProcedureCoordinatorRpcs(238): Starting the controller for
procedure member:proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:06,169 DEBUG [RS:0;proserpina:51019]
zookeeper.RecoverableZooKeeper(531): Node /hbase/flush-table-proc/acquired
already exists
2015-03-21 02:11:06,169 DEBUG [proserpina:38530.activeMasterManager]
zookeeper.RecoverableZooKeeper(531): Node /hbase/flush-table-proc/acquired
already exists
2015-03-21 02:11:06,181 DEBUG [RS:0;proserpina:51019]
zookeeper.RecoverableZooKeeper(531): Node /hbase/flush-table-proc/reached
already exists
2015-03-21 02:11:06,189 DEBUG [proserpina:38530.activeMasterManager]
zookeeper.RecoverableZooKeeper(531): Node /hbase/flush-table-proc/reached
already exists
2015-03-21 02:11:06,198 INFO [proserpina:38530.activeMasterManager]
procedure.ZKProcedureUtil(271): Clearing all procedure znodes:
/hbase/flush-table-proc/acquired /hbase/flush-table-proc/reached
/hbase/flush-table-proc/abort
2015-03-21 02:11:06,198 DEBUG [M:0;proserpina:38530]
zookeeper.RecoverableZooKeeper(531): Node /hbase/flush-table-proc/abort already
exists
2015-03-21 02:11:06,200 DEBUG [RS:0;proserpina:51019]
procedure.RegionServerProcedureManagerHost(46): Procedure flush-table-proc is
initialized
2015-03-21 02:11:06,200 DEBUG [M:0;proserpina:38530]
procedure.RegionServerProcedureManagerHost(46): Procedure flush-table-proc is
initialized
2015-03-21 02:11:06,204 DEBUG [proserpina:38530.activeMasterManager]
procedure.ZKProcedureCoordinatorRpcs(238): Starting the controller for
procedure member:proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:06,215 INFO [M:0;proserpina:38530]
regionserver.MemStoreFlusher(124): globalMemStoreLimit=995.6 M,
globalMemStoreLimitLowMark=945.8 M, maxHeap=2.4 G
2015-03-21 02:11:06,219 INFO [RS:0;proserpina:51019]
regionserver.MemStoreFlusher(124): globalMemStoreLimit=995.6 M,
globalMemStoreLimitLowMark=945.8 M, maxHeap=2.4 G
2015-03-21 02:11:06,229 INFO [M:0;proserpina:38530]
compactions.PressureAwareCompactionThroughputController(175): Compaction
throughput configurations, higher bound: 20.00 MB/sec, lower bound 10.00
MB/sec, off peak: unlimited, tuning period: 60000 ms
2015-03-21 02:11:06,229 INFO [RS:0;proserpina:51019]
compactions.PressureAwareCompactionThroughputController(175): Compaction
throughput configurations, higher bound: 20.00 MB/sec, lower bound 10.00
MB/sec, off peak: unlimited, tuning period: 60000 ms
2015-03-21 02:11:06,232 INFO [RS:0;proserpina:51019]
regionserver.HRegionServer$CompactionChecker(1473): CompactionChecker runs
every 1sec
2015-03-21 02:11:06,236 DEBUG [RS:0;proserpina:51019]
ipc.AbstractRpcClient(105):
Codec=org.apache.hadoop.hbase.codec.KeyValueCodec@190f51a, compressor=null,
tcpKeepAlive=true, tcpNoDelay=true, connectTO=10000, readTO=20000,
writeTO=60000, minIdleTimeBeforeClose=120000, maxRetries=0,
fallbackAllowed=true, bind address=proserpina.apache.org/67.195.81.189:0
2015-03-21 02:11:06,236 DEBUG [RS:0;proserpina:51019] ipc.AsyncRpcClient(152):
Starting async Hbase RPC client
2015-03-21 02:11:06,237 DEBUG [RS:0;proserpina:51019] ipc.AsyncRpcClient(163):
Use global event loop group NioEventLoopGroup
2015-03-21 02:11:06,241 INFO [M:0;proserpina:38530]
regionserver.HRegionServer$CompactionChecker(1473): CompactionChecker runs
every 1sec
2015-03-21 02:11:06,242 DEBUG [M:0;proserpina:38530]
ipc.AbstractRpcClient(105):
Codec=org.apache.hadoop.hbase.codec.KeyValueCodec@181dbfc, compressor=null,
tcpKeepAlive=true, tcpNoDelay=true, connectTO=10000, readTO=20000,
writeTO=60000, minIdleTimeBeforeClose=120000, maxRetries=0,
fallbackAllowed=true, bind address=proserpina.apache.org/67.195.81.189:0
2015-03-21 02:11:06,242 DEBUG [M:0;proserpina:38530] ipc.AsyncRpcClient(152):
Starting async Hbase RPC client
2015-03-21 02:11:06,242 DEBUG [M:0;proserpina:38530] ipc.AsyncRpcClient(163):
Use global event loop group NioEventLoopGroup
2015-03-21 02:11:06,243 DEBUG [RS:0;proserpina:51019]
regionserver.ShutdownHook(87): Installed shutdown hook thread:
Shutdownhook:RS:0;proserpina:51019
2015-03-21 02:11:06,247 DEBUG [M:0;proserpina:38530]
regionserver.ShutdownHook(87): Installed shutdown hook thread:
Shutdownhook:M:0;proserpina:38530
2015-03-21 02:11:06,256 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): master:38530-0x14c3a1908520000,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event,
type=NodeChildrenChanged, state=SyncConnected, path=/hbase/rs
2015-03-21 02:11:06,259 DEBUG [RS:0;proserpina:51019] zookeeper.ZKUtil(486):
regionserver:51019-0x14c3a1908520001, quorum=localhost:55239, baseZNode=/hbase
Set watcher on existing
znode=/hbase/rs/proserpina.apache.org,51019,1426903864687
2015-03-21 02:11:06,262 DEBUG [M:0;proserpina:38530] zookeeper.ZKUtil(486):
master:38530-0x14c3a1908520000, quorum=localhost:55239, baseZNode=/hbase Set
watcher on existing znode=/hbase/rs/proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:06,261 DEBUG [main-EventThread] zookeeper.ZKUtil(486):
master:38530-0x14c3a1908520000, quorum=localhost:55239, baseZNode=/hbase Set
watcher on existing znode=/hbase/rs/proserpina.apache.org,51019,1426903864687
2015-03-21 02:11:06,265 DEBUG [main-EventThread] zookeeper.ZKUtil(486):
master:38530-0x14c3a1908520000, quorum=localhost:55239, baseZNode=/hbase Set
watcher on existing znode=/hbase/rs/proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:06,267 INFO [proserpina:38530.activeMasterManager]
master.MasterCoprocessorHost(86): System coprocessor loading is enabled
2015-03-21 02:11:06,270 DEBUG [main-EventThread]
zookeeper.RegionServerTracker(93): Added tracking of RS
/hbase/rs/proserpina.apache.org,51019,1426903864687
2015-03-21 02:11:06,271 DEBUG [main-EventThread]
zookeeper.RegionServerTracker(93): Added tracking of RS
/hbase/rs/proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:06,273 INFO [RS:0;proserpina:51019]
regionserver.RegionServerCoprocessorHost(65): System coprocessor loading is
enabled
2015-03-21 02:11:06,276 INFO [RS:0;proserpina:51019]
regionserver.RegionServerCoprocessorHost(66): Table coprocessor loading is
enabled
2015-03-21 02:11:06,273 INFO [M:0;proserpina:38530]
regionserver.RegionServerCoprocessorHost(65): System coprocessor loading is
enabled
2015-03-21 02:11:06,277 INFO [M:0;proserpina:38530]
regionserver.RegionServerCoprocessorHost(66): Table coprocessor loading is
enabled
2015-03-21 02:11:06,314 DEBUG [proserpina:38530.activeMasterManager]
master.HMaster(1994): Registered master coprocessor service:
service=AccessControlService
2015-03-21 02:11:06,317 DEBUG [M:0;proserpina:38530] zookeeper.ZKUtil(488):
master:38530-0x14c3a1908520000, quorum=localhost:55239, baseZNode=/hbase Set
watcher on znode that does not yet exist, /hbase/acl
2015-03-21 02:11:06,318 INFO [M:0;proserpina:38530]
coprocessor.CoprocessorHost(156): System coprocessor
org.apache.hadoop.hbase.security.access.AccessController was loaded
successfully with priority (536870911).
2015-03-21 02:11:06,318 INFO [M:0;proserpina:38530]
regionserver.HRegionServer(2209): reportForDuty to
master=proserpina.apache.org,38530,1426903862856 with port=38530,
startcode=1426903862856
2015-03-21 02:11:06,336 DEBUG [RS:0;proserpina:51019] zookeeper.ZKUtil(488):
regionserver:51019-0x14c3a1908520001, quorum=localhost:55239, baseZNode=/hbase
Set watcher on znode that does not yet exist, /hbase/acl
2015-03-21 02:11:06,337 INFO [RS:0;proserpina:51019]
coprocessor.CoprocessorHost(156): System coprocessor
org.apache.hadoop.hbase.security.access.AccessController was loaded
successfully with priority (536870911).
2015-03-21 02:11:06,335 INFO [proserpina:38530.activeMasterManager]
coprocessor.CoprocessorHost(156): System coprocessor
org.apache.hadoop.hbase.security.access.AccessController was loaded
successfully with priority (536870911).
2015-03-21 02:11:06,338 INFO [proserpina:38530.activeMasterManager]
coprocessor.CoprocessorHost(156): System coprocessor
org.apache.hadoop.hbase.security.access.SecureTestUtil$MasterSyncObserver was
loaded successfully with priority (536870912).
2015-03-21 02:11:06,340 DEBUG [M:0;proserpina:38530]
regionserver.HRegionServer(2225): Master is not running yet
2015-03-21 02:11:06,340 WARN [M:0;proserpina:38530]
regionserver.HRegionServer(871): reportForDuty failed; sleeping and then
retrying.
2015-03-21 02:11:06,340 INFO [RS:0;proserpina:51019]
regionserver.HRegionServer(2209): reportForDuty to
master=proserpina.apache.org,38530,1426903862856 with port=51019,
startcode=1426903864687
2015-03-21 02:11:06,342 DEBUG [proserpina:38530.activeMasterManager]
executor.ExecutorService(91): Starting executor service
name=MASTER_OPEN_REGION-proserpina:38530, corePoolSize=5, maxPoolSize=5
2015-03-21 02:11:06,342 DEBUG [proserpina:38530.activeMasterManager]
executor.ExecutorService(91): Starting executor service
name=MASTER_CLOSE_REGION-proserpina:38530, corePoolSize=5, maxPoolSize=5
2015-03-21 02:11:06,343 DEBUG [proserpina:38530.activeMasterManager]
executor.ExecutorService(91): Starting executor service
name=MASTER_SERVER_OPERATIONS-proserpina:38530, corePoolSize=5, maxPoolSize=5
2015-03-21 02:11:06,343 DEBUG [proserpina:38530.activeMasterManager]
executor.ExecutorService(91): Starting executor service
name=MASTER_META_SERVER_OPERATIONS-proserpina:38530, corePoolSize=5,
maxPoolSize=5
2015-03-21 02:11:06,343 DEBUG [proserpina:38530.activeMasterManager]
executor.ExecutorService(91): Starting executor service
name=M_LOG_REPLAY_OPS-proserpina:38530, corePoolSize=10, maxPoolSize=10
2015-03-21 02:11:06,344 DEBUG [proserpina:38530.activeMasterManager]
executor.ExecutorService(91): Starting executor service
name=MASTER_TABLE_OPERATIONS-proserpina:38530, corePoolSize=1, maxPoolSize=1
2015-03-21 02:11:06,346 DEBUG [proserpina:38530.activeMasterManager]
cleaner.CleanerChore(91): initialize
cleaner=org.apache.hadoop.hbase.master.cleaner.TimeToLiveLogCleaner
2015-03-21 02:11:06,347 INFO [proserpina:38530.activeMasterManager]
zookeeper.RecoverableZooKeeper(121): Process identifier=replicationLogCleaner
connecting to ZooKeeper ensemble=localhost:55239
2015-03-21 02:11:06,361 DEBUG
[proserpina:38530.activeMasterManager-EventThread]
zookeeper.ZooKeeperWatcher(388): replicationLogCleaner0x0,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event, type=None,
state=SyncConnected, path=null
2015-03-21 02:11:06,367 DEBUG
[proserpina:38530.activeMasterManager-EventThread]
zookeeper.ZooKeeperWatcher(472): replicationLogCleaner-0x14c3a1908520005
connected
2015-03-21 02:11:06,436 DEBUG [proserpina:38530.activeMasterManager]
cleaner.CleanerChore(91): initialize
cleaner=org.apache.hadoop.hbase.replication.master.ReplicationLogCleaner
2015-03-21 02:11:06,449 DEBUG [proserpina:38530.activeMasterManager]
cleaner.CleanerChore(91): initialize
cleaner=org.apache.hadoop.hbase.master.snapshot.SnapshotLogCleaner
2015-03-21 02:11:06,452 DEBUG [proserpina:38530.activeMasterManager]
cleaner.CleanerChore(91): initialize
cleaner=org.apache.hadoop.hbase.master.cleaner.HFileLinkCleaner
2015-03-21 02:11:06,457 DEBUG [proserpina:38530.activeMasterManager]
cleaner.CleanerChore(91): initialize
cleaner=org.apache.hadoop.hbase.master.snapshot.SnapshotHFileCleaner
2015-03-21 02:11:06,459 DEBUG [proserpina:38530.activeMasterManager]
cleaner.CleanerChore(91): initialize
cleaner=org.apache.hadoop.hbase.master.cleaner.TimeToLiveHFileCleaner
2015-03-21 02:11:06,460 INFO [M:0;proserpina:38530]
regionserver.HRegionServer(2209): reportForDuty to
master=proserpina.apache.org,38530,1426903862856 with port=38530,
startcode=1426903862856
2015-03-21 02:11:06,468 INFO [proserpina:38530.activeMasterManager]
master.ServerManager(979): Waiting for region servers count to settle;
currently checked in 0, slept for 0 ms, expecting minimum of 1, maximum of 1,
timeout of 4500 ms, interval of 1500 ms.
2015-03-21 02:11:06,485 INFO [M:0;proserpina:38530] master.ServerManager(444):
Registering server=proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:06,519 INFO [proserpina:38530.activeMasterManager]
master.ServerManager(996): Finished waiting for region servers count to settle;
checked in 1, slept for 60 ms, expecting minimum of 1, maximum of 1, master is
running
2015-03-21 02:11:06,523 INFO [proserpina:38530.activeMasterManager]
master.ServerManager(444): Registering
server=proserpina.apache.org,51019,1426903864687
2015-03-21 02:11:06,524 INFO [proserpina:38530.activeMasterManager]
master.HMaster(645): Registered server found up in zk but who has not yet
reported in: proserpina.apache.org,51019,1426903864687
2015-03-21 02:11:06,526 DEBUG [RpcServer.listener,port=38530]
ipc.RpcServer$Listener(809): RpcServer.listener,port=38530: connection from
67.195.81.189:42362; # active connections: 1
2015-03-21 02:11:06,527 INFO [M:0;proserpina:38530]
regionserver.HRegionServer(1303): Config from master:
hbase.rootdir=hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6
2015-03-21 02:11:06,527 INFO [M:0;proserpina:38530]
regionserver.HRegionServer(1303): Config from master:
fs.defaultFS=hdfs://localhost:42912
2015-03-21 02:11:06,527 INFO [M:0;proserpina:38530]
regionserver.HRegionServer(1303): Config from master:
hbase.master.info.port=56508
2015-03-21 02:11:06,527 WARN [M:0;proserpina:38530] hbase.ZNodeClearer(58):
Environment variable HBASE_ZNODE_FILE not set; znodes will not be cleared on
crash by start scripts (Longer MTTR!)
2015-03-21 02:11:06,528 INFO [M:0;proserpina:38530] hfile.CacheConfig(260):
blockCache=LruBlockCache{blockCount=0, currentSize=1071760,
freeSize=1042890544, maxSize=1043962304, heapSize=1071760, minSize=991764160,
minFactor=0.95, multiSize=495882080, multiFactor=0.5, singleSize=247941040,
singleFactor=0.25}, cacheDataOnRead=true, cacheDataOnWrite=false,
cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false,
cacheDataCompressed=false, prefetchOnOpen=false
2015-03-21 02:11:06,531 DEBUG [M:0;proserpina:38530]
regionserver.HRegionServer(1570):
logdir=hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/WALs/proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:06,536 DEBUG [proserpina:38530.activeMasterManager]
zookeeper.ZKUtil(745): master:38530-0x14c3a1908520000, quorum=localhost:55239,
baseZNode=/hbase Unable to get data of znode /hbase/meta-region-server because
node does not exist (not an error)
2015-03-21 02:11:06,588 DEBUG [M:0;proserpina:38530]
regionserver.Replication(142): ReplicationStatisticsThread 300
2015-03-21 02:11:06,604 INFO [M:0;proserpina:38530] wal.WALFactory(143):
Instantiating WALProvider of type class
org.apache.hadoop.hbase.wal.DefaultWALProvider
2015-03-21 02:11:06,605 DEBUG [AsyncRpcChannel-pool2-t1]
ipc.AsyncRpcChannel(487): Use SIMPLE authentication for service
RegionServerStatusService, sasl=false
2015-03-21 02:11:06,642 INFO [M:0;proserpina:38530] wal.FSHLog(549): WAL
configuration: blocksize=128 MB, rollsize=121.60 MB,
prefix=proserpina.apache.org%2C38530%2C1426903862856.default, suffix=,
logDir=hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/WALs/proserpina.apache.org,38530,1426903862856,
archiveDir=hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/oldWALs
2015-03-21 02:11:06,679 INFO
[RpcServer.reader=1,bindAddress=proserpina.apache.org,port=38530]
ipc.RpcServer$Connection(1640): Connection from 67.195.81.189 port: 42362 with
version info: version: "2.0.0-SNAPSHOT" url:
"git://proserpina.apache.org/home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build"
revision: "09151911679a608db31cca63c25cfd52818a311c" user: "jenkins" date:
"Sat Mar 21 00:59:39 UTC 2015" src_checksum: "418b9105ad07f6f87c0e478355cabaa1"
2015-03-21 02:11:06,713 INFO [M:0;proserpina:38530] wal.FSHLog(1494): Slow
sync cost: 30 ms, current pipeline: []
2015-03-21 02:11:06,715 INFO [M:0;proserpina:38530] wal.FSHLog(971): New WAL
/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/WALs/proserpina.apache.org,38530,1426903862856/proserpina.apache.org%2C38530%2C1426903862856.default.1426903866643
2015-03-21 02:11:06,715 INFO [B.defaultRpcServer.handler=2,queue=0,port=38530]
master.ServerManager(444): Registering
server=proserpina.apache.org,51019,1426903864687
2015-03-21 02:11:06,740 INFO [RS:0;proserpina:51019]
regionserver.HRegionServer(1303): Config from master:
hbase.rootdir=hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6
2015-03-21 02:11:06,745 INFO [RS:0;proserpina:51019]
regionserver.HRegionServer(1303): Config from master:
fs.defaultFS=hdfs://localhost:42912
2015-03-21 02:11:06,745 INFO [RS:0;proserpina:51019]
regionserver.HRegionServer(1303): Config from master:
hbase.master.info.port=56508
2015-03-21 02:11:06,746 WARN [RS:0;proserpina:51019] hbase.ZNodeClearer(58):
Environment variable HBASE_ZNODE_FILE not set; znodes will not be cleared on
crash by start scripts (Longer MTTR!)
2015-03-21 02:11:06,746 INFO [RS:0;proserpina:51019] hfile.CacheConfig(260):
blockCache=LruBlockCache{blockCount=0, currentSize=1071760,
freeSize=1042890544, maxSize=1043962304, heapSize=1071760, minSize=991764160,
minFactor=0.95, multiSize=495882080, multiFactor=0.5, singleSize=247941040,
singleFactor=0.25}, cacheDataOnRead=true, cacheDataOnWrite=false,
cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false,
cacheDataCompressed=false, prefetchOnOpen=false
2015-03-21 02:11:06,747 DEBUG [RS:0;proserpina:51019]
regionserver.HRegionServer(1570):
logdir=hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/WALs/proserpina.apache.org,51019,1426903864687
2015-03-21 02:11:06,793 DEBUG [RS:0;proserpina:51019]
regionserver.Replication(142): ReplicationStatisticsThread 300
2015-03-21 02:11:06,796 INFO [RS:0;proserpina:51019] wal.WALFactory(143):
Instantiating WALProvider of type class
org.apache.hadoop.hbase.wal.DefaultWALProvider
2015-03-21 02:11:06,797 INFO [M:0;proserpina:38530]
regionserver.MetricsRegionServerWrapperImpl(110): Computing regionserver
metrics every 5000 milliseconds
2015-03-21 02:11:06,810 INFO [RS:0;proserpina:51019] wal.FSHLog(549): WAL
configuration: blocksize=128 MB, rollsize=121.60 MB,
prefix=proserpina.apache.org%2C51019%2C1426903864687.default, suffix=,
logDir=hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/WALs/proserpina.apache.org,51019,1426903864687,
archiveDir=hdfs://localhost:42912/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/oldWALs
2015-03-21 02:11:06,816 DEBUG [M:0;proserpina:38530]
executor.ExecutorService(91): Starting executor service
name=RS_OPEN_REGION-proserpina:38530, corePoolSize=3, maxPoolSize=3
2015-03-21 02:11:06,816 DEBUG [M:0;proserpina:38530]
executor.ExecutorService(91): Starting executor service
name=RS_OPEN_META-proserpina:38530, corePoolSize=1, maxPoolSize=1
2015-03-21 02:11:06,827 DEBUG [M:0;proserpina:38530]
executor.ExecutorService(91): Starting executor service
name=RS_CLOSE_REGION-proserpina:38530, corePoolSize=3, maxPoolSize=3
2015-03-21 02:11:06,830 DEBUG [M:0;proserpina:38530]
executor.ExecutorService(91): Starting executor service
name=RS_CLOSE_META-proserpina:38530, corePoolSize=1, maxPoolSize=1
2015-03-21 02:11:06,830 DEBUG [M:0;proserpina:38530]
executor.ExecutorService(91): Starting executor service
name=RS_LOG_REPLAY_OPS-proserpina:38530, corePoolSize=2, maxPoolSize=2
2015-03-21 02:11:06,831 DEBUG [M:0;proserpina:38530]
executor.ExecutorService(91): Starting executor service
name=RS_REGION_REPLICA_FLUSH_OPS-proserpina:38530, corePoolSize=3, maxPoolSize=3
2015-03-21 02:11:06,849 DEBUG [M:0;proserpina:38530] zookeeper.ZKUtil(486):
master:38530-0x14c3a1908520000, quorum=localhost:55239, baseZNode=/hbase Set
watcher on existing znode=/hbase/rs/proserpina.apache.org,51019,1426903864687
2015-03-21 02:11:06,850 DEBUG [M:0;proserpina:38530] zookeeper.ZKUtil(486):
master:38530-0x14c3a1908520000, quorum=localhost:55239, baseZNode=/hbase Set
watcher on existing znode=/hbase/rs/proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:06,850 INFO [M:0;proserpina:38530]
regionserver.ReplicationSourceManager(227): Current list of replicators:
[proserpina.apache.org,51019,1426903864687,
proserpina.apache.org,38530,1426903862856] other RSs:
[proserpina.apache.org,51019,1426903864687,
proserpina.apache.org,38530,1426903862856]
2015-03-21 02:11:06,860 INFO [RS:0;proserpina:51019] wal.FSHLog(1494): Slow
sync cost: 40 ms, current pipeline: []
2015-03-21 02:11:06,860 INFO [RS:0;proserpina:51019] wal.FSHLog(971): New WAL
/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/WALs/proserpina.apache.org,51019,1426903864687/proserpina.apache.org%2C51019%2C1426903864687.default.1426903866811
2015-03-21 02:11:06,869 INFO [RS:0;proserpina:51019]
regionserver.MetricsRegionServerWrapperImpl(110): Computing regionserver
metrics every 5000 milliseconds
2015-03-21 02:11:06,882 DEBUG [RS:0;proserpina:51019]
executor.ExecutorService(91): Starting executor service
name=RS_OPEN_REGION-proserpina:51019, corePoolSize=3, maxPoolSize=3
2015-03-21 02:11:06,884 DEBUG [RS:0;proserpina:51019]
executor.ExecutorService(91): Starting executor service
name=RS_OPEN_META-proserpina:51019, corePoolSize=1, maxPoolSize=1
2015-03-21 02:11:06,885 DEBUG [RS:0;proserpina:51019]
executor.ExecutorService(91): Starting executor service
name=RS_CLOSE_REGION-proserpina:51019, corePoolSize=3, maxPoolSize=3
2015-03-21 02:11:06,886 DEBUG [RS:0;proserpina:51019]
executor.ExecutorService(91): Starting executor service
name=RS_CLOSE_META-proserpina:51019, corePoolSize=1, maxPoolSize=1
2015-03-21 02:11:06,886 DEBUG [RS:0;proserpina:51019]
executor.ExecutorService(91): Starting executor service
name=RS_LOG_REPLAY_OPS-proserpina:51019, corePoolSize=2, maxPoolSize=2
2015-03-21 02:11:06,887 DEBUG [RS:0;proserpina:51019]
executor.ExecutorService(91): Starting executor service
name=RS_REGION_REPLICA_FLUSH_OPS-proserpina:51019, corePoolSize=3, maxPoolSize=3
2015-03-21 02:11:06,894 DEBUG [RS:0;proserpina:51019] zookeeper.ZKUtil(486):
regionserver:51019-0x14c3a1908520001, quorum=localhost:55239, baseZNode=/hbase
Set watcher on existing
znode=/hbase/rs/proserpina.apache.org,51019,1426903864687
2015-03-21 02:11:06,895 DEBUG [RS:0;proserpina:51019] zookeeper.ZKUtil(486):
regionserver:51019-0x14c3a1908520001, quorum=localhost:55239, baseZNode=/hbase
Set watcher on existing
znode=/hbase/rs/proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:06,895 INFO [RS:0;proserpina:51019]
regionserver.ReplicationSourceManager(227): Current list of replicators:
[proserpina.apache.org,51019,1426903864687,
proserpina.apache.org,38530,1426903862856] other RSs:
[proserpina.apache.org,51019,1426903864687,
proserpina.apache.org,38530,1426903862856]
2015-03-21 02:11:06,963 INFO [M:0;proserpina:38530]
zookeeper.RecoverableZooKeeper(121): Process identifier=hconnection-0x51d528bc
connecting to ZooKeeper ensemble=localhost:55239
2015-03-21 02:11:06,964 INFO [RS:0;proserpina:51019]
zookeeper.RecoverableZooKeeper(121): Process identifier=hconnection-0x2cd18c22
connecting to ZooKeeper ensemble=localhost:55239
2015-03-21 02:11:06,967 DEBUG [RS:0;proserpina:51019]
coprocessor.CoprocessorHost(269): Stop coprocessor
org.apache.hadoop.hbase.security.access.AccessController
2015-03-21 02:11:06,967 DEBUG [M:0;proserpina:38530]
coprocessor.CoprocessorHost(269): Stop coprocessor
org.apache.hadoop.hbase.security.access.AccessController
2015-03-21 02:11:06,968 INFO [M:0;proserpina:38530]
regionserver.HRegionServer(1819): STOPPED: Failed initialization
2015-03-21 02:11:06,968 INFO [RS:0;proserpina:51019]
regionserver.HRegionServer(1819): STOPPED: Failed initialization
2015-03-21 02:11:06,969 ERROR [M:0;proserpina:38530]
regionserver.HRegionServer(2863): Failed init
java.io.IOException: java.lang.reflect.InvocationTargetException
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:239)
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:217)
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:118)
at
org.apache.hadoop.hbase.replication.regionserver.ReplicationSink.<init>(ReplicationSink.java:90)
at
org.apache.hadoop.hbase.replication.regionserver.Replication.startReplicationService(Replication.java:213)
at
org.apache.hadoop.hbase.regionserver.HRegionServer.startServiceThreads(HRegionServer.java:1684)
at
org.apache.hadoop.hbase.regionserver.HRegionServer.handleReportForDutyResponse(HRegionServer.java:1323)
at
org.apache.hadoop.hbase.regionserver.HRegionServer.run(HRegionServer.java:874)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.lang.reflect.InvocationTargetException
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:237)
... 8 more
Caused by: java.lang.OutOfMemoryError: unable to create new native thread
at java.lang.Thread.start0(Native Method)
at java.lang.Thread.start(Thread.java:713)
at org.apache.zookeeper.ClientCnxn.start(ClientCnxn.java:405)
at org.apache.zookeeper.ZooKeeper.<init>(ZooKeeper.java:450)
at org.apache.zookeeper.ZooKeeper.<init>(ZooKeeper.java:380)
at
org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.checkZk(RecoverableZooKeeper.java:142)
at
org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.<init>(RecoverableZooKeeper.java:129)
at org.apache.hadoop.hbase.zookeeper.ZKUtil.connect(ZKUtil.java:155)
at
org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.<init>(ZooKeeperWatcher.java:163)
at
org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.<init>(ZooKeeperWatcher.java:131)
at
org.apache.hadoop.hbase.client.ZooKeeperKeepAliveConnection.<init>(ZooKeeperKeepAliveConnection.java:43)
at
org.apache.hadoop.hbase.client.ConnectionManager$HConnectionImplementation.getKeepAliveZooKeeperWatcher(ConnectionManager.java:1617)
at
org.apache.hadoop.hbase.client.ZooKeeperRegistry.getClusterId(ZooKeeperRegistry.java:101)
at
org.apache.hadoop.hbase.client.ConnectionManager$HConnectionImplementation.retrieveClusterId(ConnectionManager.java:844)
at
org.apache.hadoop.hbase.client.ConnectionManager$HConnectionImplementation.<init>(ConnectionManager.java:604)
... 13 more
2015-03-21 02:11:06,971 INFO [M:0;proserpina:38530]
regionserver.HRegionServer(946): Stopping infoServer
2015-03-21 02:11:06,969 ERROR [RS:0;proserpina:51019]
regionserver.HRegionServer(2863): Failed init
java.io.IOException: java.lang.reflect.InvocationTargetException
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:239)
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:217)
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:118)
at
org.apache.hadoop.hbase.replication.regionserver.ReplicationSink.<init>(ReplicationSink.java:90)
at
org.apache.hadoop.hbase.replication.regionserver.Replication.startReplicationService(Replication.java:213)
at
org.apache.hadoop.hbase.regionserver.HRegionServer.startServiceThreads(HRegionServer.java:1684)
at
org.apache.hadoop.hbase.regionserver.HRegionServer.handleReportForDutyResponse(HRegionServer.java:1323)
at
org.apache.hadoop.hbase.MiniHBaseCluster$MiniHBaseClusterRegionServer.handleReportForDutyResponse(MiniHBaseCluster.java:129)
at
org.apache.hadoop.hbase.regionserver.HRegionServer.run(HRegionServer.java:874)
at
org.apache.hadoop.hbase.MiniHBaseCluster$MiniHBaseClusterRegionServer.runRegionServer(MiniHBaseCluster.java:155)
at
org.apache.hadoop.hbase.MiniHBaseCluster$MiniHBaseClusterRegionServer.access$000(MiniHBaseCluster.java:107)
at
org.apache.hadoop.hbase.MiniHBaseCluster$MiniHBaseClusterRegionServer$1.run(MiniHBaseCluster.java:139)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:356)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1594)
at
org.apache.hadoop.hbase.security.User$SecureHadoopUser.runAs(User.java:304)
at
org.apache.hadoop.hbase.MiniHBaseCluster$MiniHBaseClusterRegionServer.run(MiniHBaseCluster.java:137)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.lang.reflect.InvocationTargetException
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:237)
... 17 more
Caused by: java.lang.OutOfMemoryError: unable to create new native thread
at java.lang.Thread.start0(Native Method)
at java.lang.Thread.start(Thread.java:713)
at org.apache.zookeeper.ClientCnxn.start(ClientCnxn.java:405)
at org.apache.zookeeper.ZooKeeper.<init>(ZooKeeper.java:450)
at org.apache.zookeeper.ZooKeeper.<init>(ZooKeeper.java:380)
at
org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.checkZk(RecoverableZooKeeper.java:142)
at
org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.<init>(RecoverableZooKeeper.java:129)
at org.apache.hadoop.hbase.zookeeper.ZKUtil.connect(ZKUtil.java:155)
at
org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.<init>(ZooKeeperWatcher.java:163)
at
org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.<init>(ZooKeeperWatcher.java:131)
at
org.apache.hadoop.hbase.client.ZooKeeperKeepAliveConnection.<init>(ZooKeeperKeepAliveConnection.java:43)
at
org.apache.hadoop.hbase.client.ConnectionManager$HConnectionImplementation.getKeepAliveZooKeeperWatcher(ConnectionManager.java:1617)
at
org.apache.hadoop.hbase.client.ZooKeeperRegistry.getClusterId(ZooKeeperRegistry.java:101)
at
org.apache.hadoop.hbase.client.ConnectionManager$HConnectionImplementation.retrieveClusterId(ConnectionManager.java:844)
at
org.apache.hadoop.hbase.client.ConnectionManager$HConnectionImplementation.<init>(ConnectionManager.java:604)
... 22 more
2015-03-21 02:11:06,980 FATAL [RS:0;proserpina:51019]
regionserver.HRegionServer(1994): ABORTING region server
proserpina.apache.org,51019,1426903864687: Unhandled:
java.lang.reflect.InvocationTargetException
java.io.IOException: java.lang.reflect.InvocationTargetException
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:239)
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:217)
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:118)
at
org.apache.hadoop.hbase.replication.regionserver.ReplicationSink.<init>(ReplicationSink.java:90)
at
org.apache.hadoop.hbase.replication.regionserver.Replication.startReplicationService(Replication.java:213)
at
org.apache.hadoop.hbase.regionserver.HRegionServer.startServiceThreads(HRegionServer.java:1684)
at
org.apache.hadoop.hbase.regionserver.HRegionServer.handleReportForDutyResponse(HRegionServer.java:1323)
at
org.apache.hadoop.hbase.MiniHBaseCluster$MiniHBaseClusterRegionServer.handleReportForDutyResponse(MiniHBaseCluster.java:129)
at
org.apache.hadoop.hbase.regionserver.HRegionServer.run(HRegionServer.java:874)
at
org.apache.hadoop.hbase.MiniHBaseCluster$MiniHBaseClusterRegionServer.runRegionServer(MiniHBaseCluster.java:155)
at
org.apache.hadoop.hbase.MiniHBaseCluster$MiniHBaseClusterRegionServer.access$000(MiniHBaseCluster.java:107)
at
org.apache.hadoop.hbase.MiniHBaseCluster$MiniHBaseClusterRegionServer$1.run(MiniHBaseCluster.java:139)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:356)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1594)
at
org.apache.hadoop.hbase.security.User$SecureHadoopUser.runAs(User.java:304)
at
org.apache.hadoop.hbase.MiniHBaseCluster$MiniHBaseClusterRegionServer.run(MiniHBaseCluster.java:137)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.lang.reflect.InvocationTargetException
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:237)
... 17 more
Caused by: java.lang.OutOfMemoryError: unable to create new native thread
at java.lang.Thread.start0(Native Method)
at java.lang.Thread.start(Thread.java:713)
at org.apache.zookeeper.ClientCnxn.start(ClientCnxn.java:405)
at org.apache.zookeeper.ZooKeeper.<init>(ZooKeeper.java:450)
at org.apache.zookeeper.ZooKeeper.<init>(ZooKeeper.java:380)
at
org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.checkZk(RecoverableZooKeeper.java:142)
at
org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.<init>(RecoverableZooKeeper.java:129)
at org.apache.hadoop.hbase.zookeeper.ZKUtil.connect(ZKUtil.java:155)
at
org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.<init>(ZooKeeperWatcher.java:163)
at
org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.<init>(ZooKeeperWatcher.java:131)
at
org.apache.hadoop.hbase.client.ZooKeeperKeepAliveConnection.<init>(ZooKeeperKeepAliveConnection.java:43)
at
org.apache.hadoop.hbase.client.ConnectionManager$HConnectionImplementation.getKeepAliveZooKeeperWatcher(ConnectionManager.java:1617)
at
org.apache.hadoop.hbase.client.ZooKeeperRegistry.getClusterId(ZooKeeperRegistry.java:101)
at
org.apache.hadoop.hbase.client.ConnectionManager$HConnectionImplementation.retrieveClusterId(ConnectionManager.java:844)
at
org.apache.hadoop.hbase.client.ConnectionManager$HConnectionImplementation.<init>(ConnectionManager.java:604)
... 22 more
2015-03-21 02:11:06,993 FATAL [RS:0;proserpina:51019]
regionserver.HRegionServer(2002): RegionServer abort: loaded coprocessors are:
[org.apache.hadoop.hbase.security.access.SecureTestUtil$MasterSyncObserver,
org.apache.hadoop.hbase.security.access.AccessController]
2015-03-21 02:11:06,996 INFO [M:0;proserpina:38530] log.Slf4jLog(67): Stopped
[email protected]:0
2015-03-21 02:11:07,000 INFO [MemStoreFlusher.0]
regionserver.MemStoreFlusher$FlushHandler(281): MemStoreFlusher.0 exiting
2015-03-21 02:11:07,001 INFO [MemStoreFlusher.1]
regionserver.MemStoreFlusher$FlushHandler(281): MemStoreFlusher.1 exiting
2015-03-21 02:11:07,000 INFO [M:0;proserpina:38530]
snapshot.RegionServerSnapshotManager(134): Stopping RegionServerSnapshotManager
gracefully.
2015-03-21 02:11:07,001 INFO [M:0;proserpina:38530]
flush.RegionServerFlushTableProcedureManager(113): Stopping region server flush
procedure manager gracefully.
2015-03-21 02:11:07,002 INFO [M:0;proserpina:38530]
regionserver.HRegionServer(991): stopping server
proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:07,002 DEBUG [M:0;proserpina:38530]
zookeeper.MetaTableLocator(617): Stopping MetaTableLocator
2015-03-21 02:11:07,002 INFO [M:0;proserpina:38530]
client.ConnectionManager$HConnectionImplementation(1637): Closing zookeeper
sessionid=0x14c3a1908520003
2015-03-21 02:11:07,028 DEBUG [M:0;proserpina:38530] ipc.AsyncRpcClient(288):
Stopping async HBase RPC client
2015-03-21 02:11:07,030 INFO [M:0;proserpina:38530]
regionserver.HRegionServer(1019): stopping server
proserpina.apache.org,38530,1426903862856; all regions closed.
2015-03-21 02:11:07,030 DEBUG [M:0;proserpina:38530] wal.FSHLog(1147): Closing
WAL writer in
/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/WALs/proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:07,041 INFO [RS:0;proserpina:51019]
regionserver.HRegionServer(2006): Dump of metrics as JSON on abort: {
"beans" : [ {
"name" : "java.lang:type=Memory",
"modelerType" : "sun.management.MemoryImpl",
"NonHeapMemoryUsage" : {
"committed" : 54984704,
"init" : 24576000,
"max" : 318767104,
"used" : 54064320
},
"ObjectPendingFinalizationCount" : 0,
"Verbose" : false,
"HeapMemoryUsage" : {
"committed" : 957349888,
"init" : 791251328,
"max" : 2609905664,
"used" : 318592544
},
"ObjectName" : "java.lang:type=Memory"
} ],
"beans" : [ {
"name" : "Hadoop:service=HBase,name=RegionServer,sub=IPC",
"modelerType" : "RegionServer,sub=IPC",
"tag.Context" : "regionserver",
"tag.Hostname" : "proserpina.apache.org",
"queueSize" : 0,
"numCallsInGeneralQueue" : 0,
"numCallsInReplicationQueue" : 0,
"numCallsInPriorityQueue" : 0,
"numOpenConnections" : 0,
"numActiveHandler" : 0,
"QueueCallTime_num_ops" : 0,
"QueueCallTime_min" : 0,
"QueueCallTime_max" : 0,
"QueueCallTime_mean" : 0.0,
"QueueCallTime_median" : 0.0,
"QueueCallTime_75th_percentile" : 0.0,
"QueueCallTime_95th_percentile" : 0.0,
"QueueCallTime_99th_percentile" : 0.0,
"authenticationFailures" : 0,
"authorizationFailures" : 0,
"authenticationSuccesses" : 0,
"authorizationSuccesses" : 0,
"ProcessCallTime_num_ops" : 0,
"ProcessCallTime_min" : 0,
"ProcessCallTime_max" : 0,
"ProcessCallTime_mean" : 0.0,
"ProcessCallTime_median" : 0.0,
"ProcessCallTime_75th_percentile" : 0.0,
"ProcessCallTime_95th_percentile" : 0.0,
"ProcessCallTime_99th_percentile" : 0.0,
"sentBytes" : 0,
"receivedBytes" : 0
} ],
"beans" : [ {
"name" : "Hadoop:service=HBase,name=RegionServer,sub=Replication",
"modelerType" : "RegionServer,sub=Replication",
"tag.Context" : "regionserver",
"tag.Hostname" : "proserpina.apache.org",
"sink.appliedOps" : 0,
"sink.appliedBatches" : 0,
"sink.ageOfLastAppliedOp" : 0
} ],
"beans" : [ {
"name" : "Hadoop:service=HBase,name=RegionServer,sub=Server",
"modelerType" : "RegionServer,sub=Server",
"tag.zookeeperQuorum" : "localhost:55239",
"tag.serverName" : "proserpina.apache.org,38530,1426903862856",
"tag.clusterId" : "9500695b-0220-487d-9d12-037e9eed7bc7",
"tag.Context" : "regionserver",
"tag.Hostname" : "proserpina.apache.org",
"regionCount" : 0,
"storeCount" : 0,
"hlogFileCount" : 0,
"hlogFileSize" : 0,
"storeFileCount" : 0,
"memStoreSize" : 0,
"storeFileSize" : 0,
"regionServerStartTime" : 1426903862856,
"totalRequestCount" : 0,
"readRequestCount" : 0,
"writeRequestCount" : 0,
"checkMutateFailedCount" : 0,
"checkMutatePassedCount" : 0,
"storeFileIndexSize" : 0,
"staticIndexSize" : 0,
"staticBloomSize" : 0,
"mutationsWithoutWALCount" : 0,
"mutationsWithoutWALSize" : 0,
"percentFilesLocal" : 0,
"splitQueueLength" : 0,
"compactionQueueLength" : 0,
"flushQueueLength" : 0,
"blockCacheFreeSize" : 1042890544,
"blockCacheCount" : 0,
"blockCacheSize" : 1071760,
"blockCacheHitCount" : 0,
"blockCacheMissCount" : 0,
"blockCacheEvictionCount" : 0,
"blockCacheCountHitPercent" : 0.0,
"blockCacheExpressHitPercent" : 0,
"updatesBlockedTime" : 0,
"flushedCellsCount" : 0,
"compactedCellsCount" : 0,
"majorCompactedCellsCount" : 0,
"flushedCellsSize" : 0,
"compactedCellsSize" : 0,
"majorCompactedCellsSize" : 0,
"hedgedReads" : 0,
"hedgedReadWins" : 0,
"blockedRequestCount" : 0,
"Append_num_ops" : 0,
"Append_min" : 0,
"Append_max" : 0,
"Append_mean" : 0.0,
"Append_median" : 0.0,
"Append_75th_percentile" : 0.0,
"Append_95th_percentile" : 0.0,
"Append_99th_percentile" : 0.0,
"splitSuccessCounnt" : 0,
"Delete_num_ops" : 0,
"Delete_min" : 0,
"Delete_max" : 0,
"Delete_mean" : 0.0,
"Delete_median" : 0.0,
"Delete_75th_percentile" : 0.0,
"Delete_95th_percentile" : 0.0,
"Delete_99th_percentile" : 0.0,
"Mutate_num_ops" : 0,
"Mutate_min" : 0,
"Mutate_max" : 0,
"Mutate_mean" : 0.0,
"Mutate_median" : 0.0,
"Mutate_75th_percentile" : 0.0,
"Mutate_95th_percentile" : 0.0,
"Mutate_99th_percentile" : 0.0,
"slowDeleteCount" : 0,
"splitRequestCount" : 0,
"slowIncrementCount" : 0,
"FlushTime_num_ops" : 0,
"FlushTime_min" : 0,
"FlushTime_max" : 0,
"FlushTime_mean" : 0.0,
"FlushTime_median" : 0.0,
"FlushTime_75th_percentile" : 0.0,
"FlushTime_95th_percentile" : 0.0,
"FlushTime_99th_percentile" : 0.0,
"Get_num_ops" : 0,
"Get_min" : 0,
"Get_max" : 0,
"Get_mean" : 0.0,
"Get_median" : 0.0,
"Get_75th_percentile" : 0.0,
"Get_95th_percentile" : 0.0,
"Get_99th_percentile" : 0.0,
"Replay_num_ops" : 0,
"Replay_min" : 0,
"Replay_max" : 0,
"Replay_mean" : 0.0,
"Replay_median" : 0.0,
"Replay_75th_percentile" : 0.0,
"Replay_95th_percentile" : 0.0,
"Replay_99th_percentile" : 0.0,
"slowGetCount" : 0,
"slowAppendCount" : 0,
"slowPutCount" : 0,
"SplitTime_num_ops" : 0,
"SplitTime_min" : 0,
"SplitTime_max" : 0,
"SplitTime_mean" : 0.0,
"SplitTime_median" : 0.0,
"SplitTime_75th_percentile" : 0.0,
"SplitTime_95th_percentile" : 0.0,
"SplitTime_99th_percentile" : 0.0,
"Increment_num_ops" : 0,
"Increment_min" : 0,
"Increment_max" : 0,
"Increment_mean" : 0.0,
"Increment_median" : 0.0,
"Increment_75th_percentile" : 0.0,
"Increment_95th_percentile" : 0.0,
"Increment_99th_percentile" : 0.0
} ]
}
2015-03-21 02:11:07,046 INFO [IPC Server handler 9 on 42912]
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated:
127.0.0.1:54374 is added to
blk_1073741829_1005{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-20704df4-ae22-40c7-8dcd-b411672f6980:NORMAL|RBW]]}
size 83
2015-03-21 02:11:07,068 ERROR [B.defaultRpcServer.handler=3,queue=0,port=38530]
master.MasterRpcServices(328): Region server
proserpina.apache.org,51019,1426903864687 reported a fatal error:
ABORTING region server proserpina.apache.org,51019,1426903864687: Unhandled:
java.lang.reflect.InvocationTargetException
Cause:
java.io.IOException: java.lang.reflect.InvocationTargetException
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:239)
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:217)
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:118)
at
org.apache.hadoop.hbase.replication.regionserver.ReplicationSink.<init>(ReplicationSink.java:90)
at
org.apache.hadoop.hbase.replication.regionserver.Replication.startReplicationService(Replication.java:213)
at
org.apache.hadoop.hbase.regionserver.HRegionServer.startServiceThreads(HRegionServer.java:1684)
at
org.apache.hadoop.hbase.regionserver.HRegionServer.handleReportForDutyResponse(HRegionServer.java:1323)
at
org.apache.hadoop.hbase.MiniHBaseCluster$MiniHBaseClusterRegionServer.handleReportForDutyResponse(MiniHBaseCluster.java:129)
at
org.apache.hadoop.hbase.regionserver.HRegionServer.run(HRegionServer.java:874)
at
org.apache.hadoop.hbase.MiniHBaseCluster$MiniHBaseClusterRegionServer.runRegionServer(MiniHBaseCluster.java:155)
at
org.apache.hadoop.hbase.MiniHBaseCluster$MiniHBaseClusterRegionServer.access$000(MiniHBaseCluster.java:107)
at
org.apache.hadoop.hbase.MiniHBaseCluster$MiniHBaseClusterRegionServer$1.run(MiniHBaseCluster.java:139)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:356)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1594)
at
org.apache.hadoop.hbase.security.User$SecureHadoopUser.runAs(User.java:304)
at
org.apache.hadoop.hbase.MiniHBaseCluster$MiniHBaseClusterRegionServer.run(MiniHBaseCluster.java:137)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.lang.reflect.InvocationTargetException
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
at
org.apache.hadoop.hbase.client.ConnectionFactory.createConnection(ConnectionFactory.java:237)
... 17 more
Caused by: java.lang.OutOfMemoryError: unable to create new native thread
at java.lang.Thread.start0(Native Method)
at java.lang.Thread.start(Thread.java:713)
at org.apache.zookeeper.ClientCnxn.start(ClientCnxn.java:405)
at org.apache.zookeeper.ZooKeeper.<init>(ZooKeeper.java:450)
at org.apache.zookeeper.ZooKeeper.<init>(ZooKeeper.java:380)
at
org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.checkZk(RecoverableZooKeeper.java:142)
at
org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.<init>(RecoverableZooKeeper.java:129)
at org.apache.hadoop.hbase.zookeeper.ZKUtil.connect(ZKUtil.java:155)
at
org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.<init>(ZooKeeperWatcher.java:163)
at
org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.<init>(ZooKeeperWatcher.java:131)
at
org.apache.hadoop.hbase.client.ZooKeeperKeepAliveConnection.<init>(ZooKeeperKeepAliveConnection.java:43)
at
org.apache.hadoop.hbase.client.ConnectionManager$HConnectionImplementation.getKeepAliveZooKeeperWatcher(ConnectionManager.java:1617)
at
org.apache.hadoop.hbase.client.ZooKeeperRegistry.getClusterId(ZooKeeperRegistry.java:101)
at
org.apache.hadoop.hbase.client.ConnectionManager$HConnectionImplementation.retrieveClusterId(ConnectionManager.java:844)
at
org.apache.hadoop.hbase.client.ConnectionManager$HConnectionImplementation.<init>(ConnectionManager.java:604)
... 22 more
2015-03-21 02:11:07,072 DEBUG [M:0;proserpina:38530] wal.FSHLog(1105): Moved 1
WAL file(s) to
/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/oldWALs
2015-03-21 02:11:07,072 INFO [RS:0;proserpina:51019]
regionserver.HRegionServer(946): Stopping infoServer
2015-03-21 02:11:07,072 INFO [M:0;proserpina:38530] wal.FSHLog(1108): Closed
WAL: FSHLog proserpina.apache.org%2C38530%2C1426903862856.default:(num
1426903866643)
2015-03-21 02:11:07,073 DEBUG [M:0;proserpina:38530] ipc.AsyncRpcClient(288):
Stopping async HBase RPC client
2015-03-21 02:11:07,078 INFO [M:0;proserpina:38530] regionserver.Leases(146):
M:0;proserpina:38530 closing leases
2015-03-21 02:11:07,079 INFO [M:0;proserpina:38530] regionserver.Leases(149):
M:0;proserpina:38530 closed leases
2015-03-21 02:11:07,083 INFO [M:0;proserpina:38530] hbase.ChoreService(303):
Chore service for: proserpina.apache.org,38530,1426903862856 had
[java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@16af619d,
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@5431960d,
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@3725aaa,
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@489e50aa,
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@11c1ee25]
on shutdown
2015-03-21 02:11:07,089 INFO [RS:0;proserpina:51019] log.Slf4jLog(67): Stopped
[email protected]:0
2015-03-21 02:11:07,195 INFO [MemStoreFlusher.1]
regionserver.MemStoreFlusher$FlushHandler(281): MemStoreFlusher.1 exiting
2015-03-21 02:11:07,195 INFO [MemStoreFlusher.0]
regionserver.MemStoreFlusher$FlushHandler(281): MemStoreFlusher.0 exiting
2015-03-21 02:11:07,195 INFO [RS:0;proserpina:51019]
snapshot.RegionServerSnapshotManager(134): Stopping RegionServerSnapshotManager
abruptly.
2015-03-21 02:11:07,196 INFO [RS:0;proserpina:51019]
flush.RegionServerFlushTableProcedureManager(113): Stopping region server flush
procedure manager abruptly.
2015-03-21 02:11:07,196 INFO [RS:0;proserpina:51019]
regionserver.HRegionServer(988): aborting server
proserpina.apache.org,51019,1426903864687
2015-03-21 02:11:07,196 DEBUG [RS:0;proserpina:51019]
zookeeper.MetaTableLocator(617): Stopping MetaTableLocator
2015-03-21 02:11:07,197 INFO [RS:0;proserpina:51019]
client.ConnectionManager$HConnectionImplementation(1637): Closing zookeeper
sessionid=0x14c3a1908520002
2015-03-21 02:11:07,247 DEBUG [RS:0;proserpina:51019] ipc.AsyncRpcClient(288):
Stopping async HBase RPC client
2015-03-21 02:11:07,248 INFO [RS:0;proserpina:51019]
regionserver.HRegionServer(1019): stopping server
proserpina.apache.org,51019,1426903864687; all regions closed.
2015-03-21 02:11:07,248 DEBUG [RS:0;proserpina:51019] wal.FSHLog(1147): Closing
WAL writer in
/user/jenkins/test-data/94a25112-a109-49f6-9edd-039180512bc6/WALs/proserpina.apache.org,51019,1426903864687
2015-03-21 02:11:07,273 INFO [IPC Server handler 4 on 42912]
blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated:
127.0.0.1:54374 is added to
blk_1073741830_1006{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1,
replicas=[ReplicaUnderConstruction[[DISK]DS-a2d75141-06d2-4e32-a0f7-999efc9c94fc:NORMAL|RBW]]}
size 83
2015-03-21 02:11:07,279 DEBUG [RS:0;proserpina:51019] ipc.AsyncRpcClient(288):
Stopping async HBase RPC client
2015-03-21 02:11:07,281 INFO [RS:0;proserpina:51019] regionserver.Leases(146):
RS:0;proserpina:51019 closing leases
2015-03-21 02:11:07,281 INFO [RS:0;proserpina:51019] regionserver.Leases(149):
RS:0;proserpina:51019 closed leases
2015-03-21 02:11:07,282 INFO [RS:0;proserpina:51019] hbase.ChoreService(303):
Chore service for: proserpina.apache.org,51019,1426903864687 had
[java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@47ce7f8f,
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@20ac9761,
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@23067209]
on shutdown
2015-03-21 02:11:07,285 DEBUG
[RpcServer.reader=1,bindAddress=proserpina.apache.org,port=38530]
ipc.RpcServer$Listener(841): RpcServer.listener,port=38530: DISCONNECTING
client 67.195.81.189:42362 because read count=-1. Number of active connections:
1
2015-03-21 02:11:07,286 DEBUG [AsyncRpcChannel-pool2-t1]
ipc.AsyncRpcChannel$8(574): IPC Client (-1955567686) connection to
proserpina.apache.org/67.195.81.189:38530 from jenkins.hfs.0: closed
2015-03-21 02:11:07,737 INFO
[proserpina.apache.org,38530,1426903862856_splitLogManager__ChoreService_1]
hbase.ScheduledChore(179): Chore: SplitLogManager Timeout Monitor was stopped
2015-03-21 02:11:07,840 INFO
[master/proserpina.apache.org/67.195.81.189:0.logRoller]
regionserver.LogRoller(159): LogRoller exiting.
2015-03-21 02:11:07,841 INFO [M:0;proserpina:38530]
regionserver.CompactSplitThread(393): Waiting for Split Thread to finish...
2015-03-21 02:11:07,841 INFO [M:0;proserpina:38530]
regionserver.CompactSplitThread(393): Waiting for Merge Thread to finish...
2015-03-21 02:11:07,841 INFO [M:0;proserpina:38530]
regionserver.CompactSplitThread(393): Waiting for Large Compaction Thread to
finish...
2015-03-21 02:11:07,841 INFO [M:0;proserpina:38530]
regionserver.CompactSplitThread(393): Waiting for Small Compaction Thread to
finish...
2015-03-21 02:11:07,847 INFO
[master/proserpina.apache.org/67.195.81.189:0.leaseChecker]
regionserver.Leases(146):
master/proserpina.apache.org/67.195.81.189:0.leaseChecker closing leases
2015-03-21 02:11:07,847 INFO
[master/proserpina.apache.org/67.195.81.189:0.leaseChecker]
regionserver.Leases(149):
master/proserpina.apache.org/67.195.81.189:0.leaseChecker closed leases
2015-03-21 02:11:07,853 DEBUG [M:0;proserpina:38530] master.HMaster(1045):
Stopping service threads
2015-03-21 02:11:07,853 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): master:38530-0x14c3a1908520000,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event,
type=NodeDeleted, state=SyncConnected,
path=/hbase/replication/rs/proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:07,864 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): regionserver:51019-0x14c3a1908520001,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event,
type=NodeDeleted, state=SyncConnected, path=/hbase/master
2015-03-21 02:11:07,866 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): master:38530-0x14c3a1908520000,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event,
type=NodeDeleted, state=SyncConnected, path=/hbase/master
2015-03-21 02:11:07,866 INFO [M:0;proserpina:38530]
client.ConnectionManager$HConnectionImplementation(1637): Closing zookeeper
sessionid=0x14c3a1908520004
2015-03-21 02:11:07,867 DEBUG [main-EventThread] zookeeper.ZKUtil(488):
regionserver:51019-0x14c3a1908520001, quorum=localhost:55239, baseZNode=/hbase
Set watcher on znode that does not yet exist, /hbase/master
2015-03-21 02:11:07,867 DEBUG [main-EventThread] zookeeper.ZKUtil(488):
master:38530-0x14c3a1908520000, quorum=localhost:55239, baseZNode=/hbase Set
watcher on znode that does not yet exist, /hbase/master
2015-03-21 02:11:07,872 DEBUG [M:0;proserpina:38530] ipc.AsyncRpcClient(288):
Stopping async HBase RPC client
2015-03-21 02:11:07,873 INFO [M:0;proserpina:38530] hbase.ChoreService(303):
Chore service for: proserpina.apache.org,38530,1426903862856_splitLogManager_
had [] on shutdown
2015-03-21 02:11:07,874 INFO [M:0;proserpina:38530]
flush.MasterFlushTableProcedureManager(78): stop: server shutting down.
2015-03-21 02:11:07,875 INFO [M:0;proserpina:38530] ipc.RpcServer(2169):
Stopping server on 38530
2015-03-21 02:11:07,876 INFO [RpcServer.listener,port=38530]
ipc.RpcServer$Listener(745): RpcServer.listener,port=38530: stopping
2015-03-21 02:11:07,876 INFO [RpcServer.responder]
ipc.RpcServer$Responder(987): RpcServer.responder: stopped
2015-03-21 02:11:07,876 INFO [RpcServer.responder]
ipc.RpcServer$Responder(890): RpcServer.responder: stopping
2015-03-21 02:11:07,891 INFO
[regionserver/proserpina.apache.org/67.195.81.189:0.leaseChecker]
regionserver.Leases(146):
regionserver/proserpina.apache.org/67.195.81.189:0.leaseChecker closing leases
2015-03-21 02:11:07,892 INFO
[regionserver/proserpina.apache.org/67.195.81.189:0.leaseChecker]
regionserver.Leases(149):
regionserver/proserpina.apache.org/67.195.81.189:0.leaseChecker closed leases
2015-03-21 02:11:07,891 INFO
[regionserver/proserpina.apache.org/67.195.81.189:0.logRoller]
regionserver.LogRoller(159): LogRoller exiting.
2015-03-21 02:11:07,893 INFO [RS:0;proserpina:51019]
regionserver.CompactSplitThread(393): Waiting for Split Thread to finish...
2015-03-21 02:11:07,893 INFO [RS:0;proserpina:51019]
regionserver.CompactSplitThread(393): Waiting for Merge Thread to finish...
2015-03-21 02:11:07,893 INFO [RS:0;proserpina:51019]
regionserver.CompactSplitThread(393): Waiting for Large Compaction Thread to
finish...
2015-03-21 02:11:07,893 INFO [RS:0;proserpina:51019]
regionserver.CompactSplitThread(393): Waiting for Small Compaction Thread to
finish...
2015-03-21 02:11:07,897 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): regionserver:51019-0x14c3a1908520001,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event,
type=NodeDeleted, state=SyncConnected,
path=/hbase/rs/proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:07,898 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): master:38530-0x14c3a1908520000,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event,
type=NodeDeleted, state=SyncConnected,
path=/hbase/rs/proserpina.apache.org,38530,1426903862856
2015-03-21 02:11:07,898 INFO [main-EventThread]
zookeeper.RegionServerTracker(118): RegionServer ephemeral node deleted,
processing expiration [proserpina.apache.org,38530,1426903862856]
2015-03-21 02:11:07,898 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): regionserver:51019-0x14c3a1908520001,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event,
type=NodeChildrenChanged, state=SyncConnected, path=/hbase/rs
2015-03-21 02:11:07,898 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): master:38530-0x14c3a1908520000,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event,
type=NodeChildrenChanged, state=SyncConnected, path=/hbase/rs
2015-03-21 02:11:07,906 INFO [M:0;proserpina:38530]
regionserver.HRegionServer(1063): stopping server
proserpina.apache.org,38530,1426903862856; zookeeper connection closed.
2015-03-21 02:11:07,906 INFO [M:0;proserpina:38530]
regionserver.HRegionServer(1066): M:0;proserpina:38530 exiting
2015-03-21 02:11:07,923 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): regionserver:51019-0x14c3a1908520001,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event,
type=NodeDeleted, state=SyncConnected,
path=/hbase/replication/rs/proserpina.apache.org,51019,1426903864687
2015-03-21 02:11:07,923 INFO [RS:0;proserpina:51019] ipc.RpcServer(2169):
Stopping server on 51019
2015-03-21 02:11:07,924 INFO [RpcServer.responder]
ipc.RpcServer$Responder(987): RpcServer.responder: stopped
2015-03-21 02:11:07,925 INFO [RpcServer.responder]
ipc.RpcServer$Responder(890): RpcServer.responder: stopping
2015-03-21 02:11:07,928 INFO [RpcServer.listener,port=51019]
ipc.RpcServer$Listener(745): RpcServer.listener,port=51019: stopping
2015-03-21 02:11:07,936 DEBUG [main-EventThread]
zookeeper.ZooKeeperWatcher(388): regionserver:51019-0x14c3a1908520001,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event,
type=NodeDeleted, state=SyncConnected,
path=/hbase/rs/proserpina.apache.org,51019,1426903864687
2015-03-21 02:11:07,952 INFO [RS:0;proserpina:51019]
regionserver.HRegionServer(1063): stopping server
proserpina.apache.org,51019,1426903864687; zookeeper connection closed.
2015-03-21 02:11:07,954 INFO [RS:0;proserpina:51019]
regionserver.HRegionServer(1066): RS:0;proserpina:51019 exiting
2015-03-21 02:14:25,110 ERROR [main] hbase.MiniHBaseCluster(229): Error
starting cluster
java.lang.RuntimeException: Master not initialized after 200000ms seconds
at
org.apache.hadoop.hbase.util.JVMClusterUtil.startup(JVMClusterUtil.java:225)
at
org.apache.hadoop.hbase.LocalHBaseCluster.startup(LocalHBaseCluster.java:437)
at
org.apache.hadoop.hbase.MiniHBaseCluster.init(MiniHBaseCluster.java:224)
at
org.apache.hadoop.hbase.MiniHBaseCluster.<init>(MiniHBaseCluster.java:93)
at
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniHBaseCluster(HBaseTestingUtility.java:1008)
at
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:968)
at
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:842)
at
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:836)
at
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:780)
at
org.apache.hadoop.hbase.security.access.TestAccessController.setupBeforeClass(TestAccessController.java:191)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:24)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
at org.junit.runners.Suite.runChild(Suite.java:127)
at org.junit.runners.Suite.runChild(Suite.java:26)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
at org.junit.runner.JUnitCore.run(JUnitCore.java:160)
at org.junit.runner.JUnitCore.run(JUnitCore.java:138)
at
org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:107)
at
org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:77)
at
org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:53)
at
org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:144)
at
org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:203)
at
org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:155)
at
org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)
2015-03-21 02:14:25,112 DEBUG [main] util.JVMClusterUtil(241): Shutting down
HBase Cluster
2015-03-21 02:14:25,113 DEBUG [main] coprocessor.CoprocessorHost(269): Stop
coprocessor org.apache.hadoop.hbase.security.access.AccessController
2015-03-21 02:14:25,113 DEBUG [main] coprocessor.CoprocessorHost(269): Stop
coprocessor
org.apache.hadoop.hbase.security.access.SecureTestUtil$MasterSyncObserver
2015-03-21 02:14:25,115 WARN [main] zookeeper.RecoverableZooKeeper(276):
Possibly transient ZooKeeper, quorum=localhost:55239,
exception=org.apache.zookeeper.KeeperException$SessionExpiredException:
KeeperErrorCode = Session expired for /hbase/running
2015-03-21 02:14:26,115 WARN [main] zookeeper.RecoverableZooKeeper(276):
Possibly transient ZooKeeper, quorum=localhost:55239,
exception=org.apache.zookeeper.KeeperException$SessionExpiredException:
KeeperErrorCode = Session expired for /hbase/running
2015-03-21 02:14:28,116 WARN [main] zookeeper.RecoverableZooKeeper(276):
Possibly transient ZooKeeper, quorum=localhost:55239,
exception=org.apache.zookeeper.KeeperException$SessionExpiredException:
KeeperErrorCode = Session expired for /hbase/running
2015-03-21 02:14:32,119 WARN [main] zookeeper.RecoverableZooKeeper(276):
Possibly transient ZooKeeper, quorum=localhost:55239,
exception=org.apache.zookeeper.KeeperException$SessionExpiredException:
KeeperErrorCode = Session expired for /hbase/running
2015-03-21 02:14:40,122 WARN [main] zookeeper.RecoverableZooKeeper(276):
Possibly transient ZooKeeper, quorum=localhost:55239,
exception=org.apache.zookeeper.KeeperException$SessionExpiredException:
KeeperErrorCode = Session expired for /hbase/running
2015-03-21 02:14:40,126 ERROR [main] zookeeper.RecoverableZooKeeper(278):
ZooKeeper delete failed after 4 attempts
2015-03-21 02:14:40,126 ERROR [main] master.HMaster(1877): ZooKeeper exception
trying to set cluster as down in ZK
org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode =
Session expired for /hbase/running
at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
at
org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.delete(RecoverableZooKeeper.java:179)
at org.apache.hadoop.hbase.zookeeper.ZKUtil.deleteNode(ZKUtil.java:1341)
at org.apache.hadoop.hbase.zookeeper.ZKUtil.deleteNode(ZKUtil.java:1330)
at
org.apache.hadoop.hbase.zookeeper.ClusterStatusTracker.setClusterDown(ClusterStatusTracker.java:82)
at org.apache.hadoop.hbase.master.HMaster.shutdown(HMaster.java:1875)
at
org.apache.hadoop.hbase.util.JVMClusterUtil.shutdown(JVMClusterUtil.java:254)
at
org.apache.hadoop.hbase.LocalHBaseCluster.shutdown(LocalHBaseCluster.java:444)
at
org.apache.hadoop.hbase.MiniHBaseCluster.shutdown(MiniHBaseCluster.java:517)
at
org.apache.hadoop.hbase.MiniHBaseCluster.init(MiniHBaseCluster.java:230)
at
org.apache.hadoop.hbase.MiniHBaseCluster.<init>(MiniHBaseCluster.java:93)
at
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniHBaseCluster(HBaseTestingUtility.java:1008)
at
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:968)
at
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:842)
at
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:836)
at
org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:780)
at
org.apache.hadoop.hbase.security.access.TestAccessController.setupBeforeClass(TestAccessController.java:191)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:24)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
at org.junit.runners.Suite.runChild(Suite.java:127)
at org.junit.runners.Suite.runChild(Suite.java:26)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
at org.junit.runner.JUnitCore.run(JUnitCore.java:160)
at org.junit.runner.JUnitCore.run(JUnitCore.java:138)
at
org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:107)
at
org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:77)
at
org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:53)
at
org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:144)
at
org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:203)
at
org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:155)
at
org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)
2015-03-21 02:14:40,129 INFO [main] util.JVMClusterUtil(317): Shutdown of 1
master(s) and 1 regionserver(s) complete
2015-03-21 02:14:40,129 INFO [main] hbase.HBaseTestingUtility(1068): Shutting
down minicluster
2015-03-21 02:14:40,135 INFO [main] zookeeper.MiniZooKeeperCluster(319):
Shutdown MiniZK cluster with all ZK servers
2015-03-21 02:14:40,136 WARN [main] datanode.DirectoryScanner(375):
DirectoryScanner: shutdown has been called
2015-03-21 02:14:40,154 INFO [main] log.Slf4jLog(67): Stopped
HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:0
2015-03-21 02:14:40,232 DEBUG
[proserpina:38530.activeMasterManager-EventThread]
zookeeper.ZooKeeperWatcher(388): replicationLogCleaner-0x14c3a1908520005,
quorum=localhost:55239, baseZNode=/hbase Received ZooKeeper Event, type=None,
state=Disconnected, path=null
2015-03-21 02:14:40,232 DEBUG
[proserpina:38530.activeMasterManager-EventThread]
zookeeper.ZooKeeperWatcher(477): replicationLogCleaner-0x14c3a1908520005,
quorum=localhost:55239, baseZNode=/hbase Received Disconnected from ZooKeeper,
ignoring
2015-03-21 02:14:40,258 WARN [DataNode:
[[[DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-server/target/test-data/5d031ef7-820c-47c8-9f14-20a54526f48a/dfscluster_d80b1d01-c629-432f-832e-eb812b7810fa/dfs/data/data1/,
[DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-server/target/test-data/5d031ef7-820c-47c8-9f14-20a54526f48a/dfscluster_d80b1d01-c629-432f-832e-eb812b7810fa/dfs/data/data2/]]
heartbeating to localhost/127.0.0.1:42912] datanode.BPServiceActor(722):
BPOfferService for Block pool BP-27234177-67.195.81.189-1426903856367 (Datanode
Uuid bf0194c5-f830-4a3c-a9e4-a3e5516d3196) service to localhost/127.0.0.1:42912
interrupted
2015-03-21 02:14:40,259 WARN [DataNode:
[[[DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-server/target/test-data/5d031ef7-820c-47c8-9f14-20a54526f48a/dfscluster_d80b1d01-c629-432f-832e-eb812b7810fa/dfs/data/data1/,
[DISK]file:/home/jenkins/jenkins-slave/workspace/PreCommit-HBASE-Build/hbase-server/target/test-data/5d031ef7-820c-47c8-9f14-20a54526f48a/dfscluster_d80b1d01-c629-432f-832e-eb812b7810fa/dfs/data/data2/]]
heartbeating to localhost/127.0.0.1:42912] datanode.BPServiceActor(845):
Ending block pool service for: Block pool
BP-27234177-67.195.81.189-1426903856367 (Datanode Uuid
bf0194c5-f830-4a3c-a9e4-a3e5516d3196) service to localhost/127.0.0.1:42912
2015-03-21 02:14:40,297 WARN
[org.apache.hadoop.hdfs.server.blockmanagement.DecommissionManager$Monitor@10c8414a]
blockmanagement.DecommissionManager$Monitor(78): Monitor interrupted:
java.lang.InterruptedException: sleep interrupted
2015-03-21 02:14:40,353 INFO [main] log.Slf4jLog(67): Stopped
HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:0
2015-03-21 02:14:40,547 INFO [main] hbase.HBaseTestingUtility(1081):
Minicluster is down
{code}
> Fix the critical ancient loopholes in security testing infrastructure.
> ----------------------------------------------------------------------
>
> Key: HBASE-13294
> URL: https://issues.apache.org/jira/browse/HBASE-13294
> Project: HBase
> Issue Type: Bug
> Reporter: Srikanth Srungarapu
> Assignee: Srikanth Srungarapu
> Attachments: HBASE-13294.patch, HBASE-13294_v2.patch,
> HBASE-13294_v3.patch, HBASE-13294_v3.patch, HBASE-13294_v4.patch
>
>
> Unfortunately, the "verifyDenied" method doesn't fail when action parameter
> returns null. The relevant code snippet
> {code}
> try {
> Object obj = user.runAs(action);
> if (requireException) {
> fail("Expected exception was not thrown for user '" +
> user.getShortName() + "'");
> }
> if (obj != null && obj instanceof List<?>) {
> List<?> results = (List<?>) obj;
> if (results != null && !results.isEmpty()) {
> fail("Unexpected results for user '" + user.getShortName() + "'");
> }
> }
> }
> {code}
> As you can see, when obj is null, it returns silently.
> Fixing this issue has uncovered another major bug. While constructing
> actions, we're using TEST_UTIL.getConnection(), which replaces the "doAs"
> user with the user who initiated the connection. I really am grateful to
> [~mbertozzi] without whom debugging this would have been a nightmare.
> Now, fixing these two issues have uncovered more issues in our tests :). The
> main one is we're allowing the table owner to truncate table in code. But, in
> test, we're not allowing him. We should either remove the code that allows
> owner or document that the table owner can truncate table.
> The other minor issues include granting permissions to namespace, but
> checking whether user was able to access tables inside other namespace.
> That's it, folks!
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
