Return-Path: X-Original-To: apmail-hbase-issues-archive@www.apache.org Delivered-To: apmail-hbase-issues-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 50171100B6 for ; Mon, 14 Apr 2014 23:53:18 +0000 (UTC) Received: (qmail 47667 invoked by uid 500); 14 Apr 2014 23:53:15 -0000 Delivered-To: apmail-hbase-issues-archive@hbase.apache.org Received: (qmail 47605 invoked by uid 500); 14 Apr 2014 23:53:15 -0000 Mailing-List: contact issues-help@hbase.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Delivered-To: mailing list issues@hbase.apache.org Received: (qmail 47595 invoked by uid 99); 14 Apr 2014 23:53:14 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 14 Apr 2014 23:53:14 +0000 Date: Mon, 14 Apr 2014 23:53:14 +0000 (UTC) From: "stack (JIRA)" To: issues@hbase.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (HBASE-10978) TestSplitLogWorker.testRescan times out waiting on preempt count to go up MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/HBASE-10978?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13969020#comment-13969020 ] stack commented on HBASE-10978: ------------------------------- This is like HBASE-10543 only that was a timeout in a different TSLW test; similar looking symptom. > TestSplitLogWorker.testRescan times out waiting on preempt count to go up > ------------------------------------------------------------------------- > > Key: HBASE-10978 > URL: https://issues.apache.org/jira/browse/HBASE-10978 > Project: HBase > Issue Type: Bug > Reporter: stack > Priority: Minor > > On our internal rig we got the below. The test times out waiting on the preempted worker tasks to go up: > ZKUtil.setData(zkw, task, slt.toByteArray()); > waitForCounter(SplitLogCounters.tot_wkr_preempt_task, 1, 2, WAIT_TIME); > I see the preempt come in and get logged but at same time, the task has completed in about the timeout time: > 2014-04-13 22:38:26,868 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(87): task execution prempted task > 2014-04-13 22:38:26,868 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(107): worker svr,1,1 done with task /hbase/splitWAL/task in 1504ms > We timed out before the preempt got to up the counter. Let me keep an eye on these...... Will up timeout and add more logging if we see this again. > {code} > Regression > org.apache.hadoop.hbase.regionserver.TestSplitLogWorker.testRescan > Failing for the past 1 build (Since Failed#4 ) > Took 2 ms. > add description > Error Message > Waiting timed out after [1,500] msec > Stacktrace > junit.framework.AssertionFailedError: Waiting timed out after [1,500] msec > at junit.framework.Assert.fail(Assert.java:57) > at org.apache.hadoop.hbase.Waiter.waitFor(Waiter.java:193) > at org.apache.hadoop.hbase.HBaseTestingUtility.waitFor(HBaseTestingUtility.java:3247) > at org.apache.hadoop.hbase.regionserver.TestSplitLogWorker.waitForCounterBoolean(TestSplitLogWorker.java:82) > at org.apache.hadoop.hbase.regionserver.TestSplitLogWorker.waitForCounterBoolean(TestSplitLogWorker.java:76) > at org.apache.hadoop.hbase.regionserver.TestSplitLogWorker.waitForCounter(TestSplitLogWorker.java:69) > at org.apache.hadoop.hbase.regionserver.TestSplitLogWorker.testRescan(TestSplitLogWorker.java:320) > 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.InvokeMethod.evaluate(InvokeMethod.java:17) > at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) > at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) > at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271) > at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70) > at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50) > 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.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 java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) > at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) > at java.util.concurrent.FutureTask.run(FutureTask.java:166) > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:724) > Standard Output > 2014-04-13 22:38:12,096 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testPreemptTask Thread=5, OpenFileDescriptor=95, MaxFileDescriptor=32768, SystemLoadAverage=708, ProcessCount=459, AvailableMemoryMB=4258, ConnectionCount=0 > 2014-04-13 22:38:12,145 INFO [pool-1-thread-1] hbase.HBaseTestingUtility(375): Created new mini-cluster data directory: /var/lib/jenkins/workspace/CDH5.0.1-HBase-0.96.1.1/hbase-server/target/test-data/c8c0b7df-ee6e-4987-96f6-31450e4b21a7/dfscluster_8023fe06-5515-41e4-8ed1-dc0ef9642d55, deleteOnExit=true > 2014-04-13 22:38:12,389 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 64068 > 2014-04-13 22:38:12,456 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:64068 > 2014-04-13 22:38:13,941 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:64068, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null > 2014-04-13 22:38:13,943 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe2ab80000 connected > 2014-04-13 22:38:13,979 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created > 2014-04-13 22:38:13,985 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created > 2014-04-13 22:38:14,014 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10 > 2014-04-13 22:38:14,014 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(213): testPreemptTask > 2014-04-13 22:38:14,246 INFO [SplitLogWorker-tpt_svr,1,1] regionserver.SplitLogWorker(175): SplitLogWorker tpt_svr,1,1 starting > 2014-04-13 22:38:15,256 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [5,000] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:15,493 WARN [pool-1-thread-1] util.NativeCodeLoader(62): Unable to load native-hadoop library for your platform... using builtin-java classes where applicable > 2014-04-13 22:38:15,736 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe2ab80000, quorum=localhost:64068, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL > 2014-04-13 22:38:15,736 DEBUG [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(595): tasks arrived or departed > 2014-04-13 22:38:15,736 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [8,000] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:15,768 INFO [SplitLogWorker-tpt_svr,1,1] regionserver.SplitLogWorker(363): worker tpt_svr,1,1 acquired task /hbase/splitWAL/tpt_task > 2014-04-13 22:38:15,784 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe2ab80000, quorum=localhost:64068, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/tpt_task > 2014-04-13 22:38:15,785 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:15,786 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(522): task /hbase/splitWAL/tpt_task preempted from tpt_svr,1,1, current task state and owner=OWNED manager,1,1 > 2014-04-13 22:38:15,786 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread > 2014-04-13 22:38:15,862 WARN [SplitLogWorker-tpt_svr,1,1] regionserver.SplitLogWorker(374): Interrupted while yielding for other region servers > java.lang.InterruptedException: sleep interrupted > at java.lang.Thread.sleep(Native Method) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.grabTask(SplitLogWorker.java:372) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.taskLoop(SplitLogWorker.java:251) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.run(SplitLogWorker.java:209) > at java.lang.Thread.run(Thread.java:724) > 2014-04-13 22:38:16,868 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker(420): BADVERSION failed to assert ownership for /hbase/splitWAL/tpt_task > org.apache.zookeeper.KeeperException$BadVersionException: KeeperErrorCode = BadVersion for /hbase/splitWAL/tpt_task > at org.apache.zookeeper.KeeperException.create(KeeperException.java:115) > at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) > at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1266) > at org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.setData(RecoverableZooKeeper.java:407) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.attemptToOwnTask(SplitLogWorker.java:406) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker$2.progress(SplitLogWorker.java:474) > at org.apache.hadoop.hbase.regionserver.TestSplitLogWorker$2.exec(TestSplitLogWorker.java:135) > at org.apache.hadoop.hbase.regionserver.handler.HLogSplitterHandler.process(HLogSplitterHandler.java:79) > at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:128) > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:724) > 2014-04-13 22:38:16,868 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker$2(477): Failed to heartbeat the task/hbase/splitWAL/tpt_task > 2014-04-13 22:38:16,870 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted tpt_task > 2014-04-13 22:38:16,870 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker tpt_svr,1,1 done with task /hbase/splitWAL/tpt_task in 1011ms > 2014-04-13 22:38:16,875 INFO [pool-1-thread-1] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread > 2014-04-13 22:38:16,876 INFO [SplitLogWorker-tpt_svr,1,1] regionserver.SplitLogWorker(299): SplitLogWorker interrupted while waiting for task, exiting: java.lang.InterruptedException > 2014-04-13 22:38:16,876 INFO [SplitLogWorker-tpt_svr,1,1] regionserver.SplitLogWorker(216): SplitLogWorker tpt_svr,1,1 exiting > 2014-04-13 22:38:16,879 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers > 2014-04-13 22:38:16,914 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testPreemptTask Thread=9 (was 5) > Potentially hanging thread: pool-1-thread-1-SendThread(localhost:64068) > java.lang.Thread.sleep(Native Method) > org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(ClientCnxnSocketNIO.java:219) > org.apache.zookeeper.ClientCnxn$SendThread.cleanup(ClientCnxn.java:1164) > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1104) > Potentially hanging thread: pool-1-thread-1-EventThread > 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) > Potentially hanging thread: process reaper > 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:724) > Potentially hanging thread: SessionTracker > java.lang.Object.wait(Native Method) > org.apache.zookeeper.server.SessionTrackerImpl.run(SessionTrackerImpl.java:146) > - Thread LEAK? -, OpenFileDescriptor=103 (was 95) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=700 (was 708), ProcessCount=459 (was 459), AvailableMemoryMB=4391 (was 4258) - AvailableMemoryMB LEAK? -, ConnectionCount=0 (was 0) > 2014-04-13 22:38:16,978 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe2ab80000, quorum=localhost:64068, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null > 2014-04-13 22:38:16,979 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe2ab80000, quorum=localhost:64068, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring > 2014-04-13 22:38:16,939 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testAcquireMultiTasks Thread=9, OpenFileDescriptor=103, MaxFileDescriptor=32768, SystemLoadAverage=700, ProcessCount=459, AvailableMemoryMB=4390, ConnectionCount=0 > 2014-04-13 22:38:16,949 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 62039 > 2014-04-13 22:38:16,953 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:62039 > 2014-04-13 22:38:17,013 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:62039, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null > 2014-04-13 22:38:17,015 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe3cf10000 connected > 2014-04-13 22:38:17,025 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created > 2014-04-13 22:38:17,032 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created > 2014-04-13 22:38:17,040 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10 > 2014-04-13 22:38:17,041 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(341): testAcquireMultiTasks > 2014-04-13 22:38:17,118 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [6,000] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:17,119 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(175): SplitLogWorker rs,1,1 starting > 2014-04-13 22:38:17,131 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(363): worker rs,1,1 acquired task /hbase/splitWAL/tatas2 > 2014-04-13 22:38:17,797 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(363): worker rs,1,1 acquired task /hbase/splitWAL/tatas0 > 2014-04-13 22:38:18,139 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe3cf10000, quorum=localhost:62039, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/tatas2 > 2014-04-13 22:38:18,423 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(363): worker rs,1,1 acquired task /hbase/splitWAL/tatas1 > 2014-04-13 22:38:18,428 INFO [pool-1-thread-1] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread > 2014-04-13 22:38:18,429 WARN [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(374): Interrupted while yielding for other region servers > java.lang.InterruptedException: sleep interrupted > at java.lang.Thread.sleep(Native Method) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.grabTask(SplitLogWorker.java:372) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.taskLoop(SplitLogWorker.java:251) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.run(SplitLogWorker.java:209) > at java.lang.Thread.run(Thread.java:724) > 2014-04-13 22:38:18,430 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(216): SplitLogWorker rs,1,1 exiting > 2014-04-13 22:38:18,430 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(87): task execution prempted tatas0 > 2014-04-13 22:38:18,430 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted tatas2 > 2014-04-13 22:38:18,431 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-2] handler.HLogSplitterHandler(87): task execution prempted tatas1 > 2014-04-13 22:38:18,430 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(107): worker rs,1,1 done with task /hbase/splitWAL/tatas0 in 630ms > 2014-04-13 22:38:18,431 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-2] handler.HLogSplitterHandler(107): worker rs,1,1 done with task /hbase/splitWAL/tatas1 in 7ms > 2014-04-13 22:38:18,431 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker rs,1,1 done with task /hbase/splitWAL/tatas2 in 1297ms > 2014-04-13 22:38:18,433 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers > 2014-04-13 22:38:18,469 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testAcquireMultiTasks Thread=11 (was 9) > Potentially hanging thread: pool-1-thread-1-SendThread(localhost:62039) > java.lang.Thread.sleep(Native Method) > org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(ClientCnxnSocketNIO.java:219) > org.apache.zookeeper.ClientCnxn$SendThread.cleanup(ClientCnxn.java:1164) > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1104) > - Thread LEAK? -, OpenFileDescriptor=107 (was 103) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=644 (was 700), ProcessCount=459 (was 459), AvailableMemoryMB=4223 (was 4390), ConnectionCount=0 (was 0) > 2014-04-13 22:38:18,532 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe3cf10000, quorum=localhost:62039, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null > 2014-04-13 22:38:18,532 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe3cf10000, quorum=localhost:62039, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring > 2014-04-13 22:38:18,505 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testAcquireTaskAtStartup Thread=11, OpenFileDescriptor=107, MaxFileDescriptor=32768, SystemLoadAverage=644, ProcessCount=459, AvailableMemoryMB=4217, ConnectionCount=0 > 2014-04-13 22:38:18,512 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 49163 > 2014-04-13 22:38:18,517 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:49163 > 2014-04-13 22:38:18,608 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:49163, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null > 2014-04-13 22:38:18,610 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe430c0000 connected > 2014-04-13 22:38:18,628 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created > 2014-04-13 22:38:18,635 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created > 2014-04-13 22:38:18,645 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10 > 2014-04-13 22:38:18,645 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(145): testAcquireTaskAtStartup > 2014-04-13 22:38:18,652 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(175): SplitLogWorker rs,1,1 starting > 2014-04-13 22:38:18,652 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:18,659 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(363): worker rs,1,1 acquired task /hbase/splitWAL/tatas > 2014-04-13 22:38:18,663 INFO [pool-1-thread-1] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread > 2014-04-13 22:38:18,664 WARN [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(374): Interrupted while yielding for other region servers > java.lang.InterruptedException: sleep interrupted > at java.lang.Thread.sleep(Native Method) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.grabTask(SplitLogWorker.java:372) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.taskLoop(SplitLogWorker.java:251) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.run(SplitLogWorker.java:209) > at java.lang.Thread.run(Thread.java:724) > 2014-04-13 22:38:18,664 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(216): SplitLogWorker rs,1,1 exiting > 2014-04-13 22:38:18,672 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted tatas > 2014-04-13 22:38:18,672 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker rs,1,1 done with task /hbase/splitWAL/tatas in 10ms > 2014-04-13 22:38:18,674 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers > 2014-04-13 22:38:18,709 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testAcquireTaskAtStartup Thread=14 (was 11) > Potentially hanging thread: pool-1-thread-1-SendThread(localhost:49163) > java.lang.Thread.sleep(Native Method) > org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(ClientCnxnSocketNIO.java:219) > org.apache.zookeeper.ClientCnxn$SendThread.cleanup(ClientCnxn.java:1164) > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1104) > - Thread LEAK? -, OpenFileDescriptor=111 (was 107) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=644 (was 644), ProcessCount=459 (was 459), AvailableMemoryMB=4184 (was 4217), ConnectionCount=0 (was 0) > 2014-04-13 22:38:18,773 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe430c0000, quorum=localhost:49163, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null > 2014-04-13 22:38:18,773 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe430c0000, quorum=localhost:49163, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring > 2014-04-13 22:38:18,746 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testAcquireMultiTasksByAvgTasksPerRS Thread=14, OpenFileDescriptor=111, MaxFileDescriptor=32768, SystemLoadAverage=644, ProcessCount=459, AvailableMemoryMB=4334, ConnectionCount=0 > 2014-04-13 22:38:18,752 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 61696 > 2014-04-13 22:38:18,756 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:61696 > 2014-04-13 22:38:18,859 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:61696, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null > 2014-04-13 22:38:18,861 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe43fc0000 connected > 2014-04-13 22:38:18,874 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created > 2014-04-13 22:38:18,882 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created > 2014-04-13 22:38:18,891 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10 > 2014-04-13 22:38:18,891 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(377): testAcquireMultiTasks > 2014-04-13 22:38:19,065 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [6,000] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:19,066 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(175): SplitLogWorker rs,1,1 starting > 2014-04-13 22:38:19,081 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(363): worker rs,1,1 acquired task /hbase/splitWAL/tatas0 > 2014-04-13 22:38:19,731 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(363): worker rs,1,1 acquired task /hbase/splitWAL/tatas1 > 2014-04-13 22:38:19,744 INFO [pool-1-thread-1] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread > 2014-04-13 22:38:19,744 WARN [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(374): Interrupted while yielding for other region servers > java.lang.InterruptedException: sleep interrupted > at java.lang.Thread.sleep(Native Method) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.grabTask(SplitLogWorker.java:372) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.taskLoop(SplitLogWorker.java:251) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.run(SplitLogWorker.java:209) > at java.lang.Thread.run(Thread.java:724) > 2014-04-13 22:38:19,744 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(216): SplitLogWorker rs,1,1 exiting > 2014-04-13 22:38:19,745 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(87): task execution prempted tatas1 > 2014-04-13 22:38:19,745 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted tatas0 > 2014-04-13 22:38:19,745 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(107): worker rs,1,1 done with task /hbase/splitWAL/tatas1 in 13ms > 2014-04-13 22:38:19,745 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker rs,1,1 done with task /hbase/splitWAL/tatas0 in 661ms > 2014-04-13 22:38:19,747 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers > 2014-04-13 22:38:19,780 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testAcquireMultiTasksByAvgTasksPerRS Thread=17 (was 14) > Potentially hanging thread: pool-1-thread-1-SendThread(localhost:61696) > java.lang.Thread.sleep(Native Method) > org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(ClientCnxnSocketNIO.java:219) > org.apache.zookeeper.ClientCnxn$SendThread.cleanup(ClientCnxn.java:1164) > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1104) > - Thread LEAK? -, OpenFileDescriptor=115 (was 111) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=644 (was 644), ProcessCount=459 (was 459), AvailableMemoryMB=4241 (was 4334), ConnectionCount=0 (was 0) > 2014-04-13 22:38:19,846 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe43fc0000, quorum=localhost:61696, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null > 2014-04-13 22:38:19,846 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe43fc0000, quorum=localhost:61696, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring > 2014-04-13 22:38:19,812 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testRaceForTask Thread=17, OpenFileDescriptor=115, MaxFileDescriptor=32768, SystemLoadAverage=644, ProcessCount=459, AvailableMemoryMB=4237, ConnectionCount=0 > 2014-04-13 22:38:19,817 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 52736 > 2014-04-13 22:38:19,822 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:52736 > 2014-04-13 22:38:20,865 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:52736, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null > 2014-04-13 22:38:20,867 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe48260000 connected > 2014-04-13 22:38:20,881 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created > 2014-04-13 22:38:20,898 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created > 2014-04-13 22:38:20,914 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10 > 2014-04-13 22:38:20,914 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(180): testRaceForTask > 2014-04-13 22:38:20,924 INFO [SplitLogWorker-svr1,1,1] regionserver.SplitLogWorker(175): SplitLogWorker svr1,1,1 starting > 2014-04-13 22:38:20,925 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:20,924 INFO [SplitLogWorker-svr2,1,1] regionserver.SplitLogWorker(175): SplitLogWorker svr2,1,1 starting > 2014-04-13 22:38:21,055 INFO [SplitLogWorker-svr1,1,1] regionserver.SplitLogWorker(363): worker svr1,1,1 acquired task /hbase/splitWAL/trft > 2014-04-13 22:38:21,058 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:22,071 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe48260000, quorum=localhost:52736, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/trft > 2014-04-13 22:38:22,558 WARN [pool-1-thread-1] hbase.Waiter(195): Waiting timed out after [1,500] msec > 2014-04-13 22:38:22,560 INFO [pool-1-thread-1] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread > 2014-04-13 22:38:22,560 INFO [SplitLogWorker-svr1,1,1] regionserver.SplitLogWorker(299): SplitLogWorker interrupted while waiting for task, exiting: java.lang.InterruptedException > 2014-04-13 22:38:22,561 INFO [SplitLogWorker-svr1,1,1] regionserver.SplitLogWorker(216): SplitLogWorker svr1,1,1 exiting > 2014-04-13 22:38:22,561 INFO [pool-1-thread-1] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread > 2014-04-13 22:38:22,561 INFO [SplitLogWorker-svr2,1,1] regionserver.SplitLogWorker(299): SplitLogWorker interrupted while waiting for task, exiting: java.lang.InterruptedException > 2014-04-13 22:38:22,561 INFO [SplitLogWorker-svr2,1,1] regionserver.SplitLogWorker(216): SplitLogWorker svr2,1,1 exiting > 2014-04-13 22:38:22,561 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted trft > 2014-04-13 22:38:22,564 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker svr1,1,1 done with task /hbase/splitWAL/trft in 1507ms > 2014-04-13 22:38:22,566 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers > 2014-04-13 22:38:22,601 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testRaceForTask Thread=17 (was 17), OpenFileDescriptor=119 (was 115) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=644 (was 644), ProcessCount=459 (was 459), AvailableMemoryMB=3761 (was 4237), ConnectionCount=0 (was 0) > 2014-04-13 22:38:22,665 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe48260000, quorum=localhost:52736, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null > 2014-04-13 22:38:22,665 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe48260000, quorum=localhost:52736, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring > 2014-04-13 22:38:22,634 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testMultipleTasks Thread=17, OpenFileDescriptor=119, MaxFileDescriptor=32768, SystemLoadAverage=664, ProcessCount=459, AvailableMemoryMB=3758, ConnectionCount=0 > 2014-04-13 22:38:22,648 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 65092 > 2014-04-13 22:38:22,651 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:65092 > 2014-04-13 22:38:22,724 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:65092, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null > 2014-04-13 22:38:22,726 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe53350000 connected > 2014-04-13 22:38:22,733 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created > 2014-04-13 22:38:22,739 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created > 2014-04-13 22:38:22,748 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10 > 2014-04-13 22:38:22,749 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(246): testMultipleTasks > 2014-04-13 22:38:22,751 INFO [SplitLogWorker-tmt_svr,1,1] regionserver.SplitLogWorker(175): SplitLogWorker tmt_svr,1,1 starting > 2014-04-13 22:38:22,851 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:22,866 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe53350000, quorum=localhost:65092, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL > 2014-04-13 22:38:22,867 DEBUG [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(595): tasks arrived or departed > 2014-04-13 22:38:22,867 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:22,883 INFO [SplitLogWorker-tmt_svr,1,1] regionserver.SplitLogWorker(363): worker tmt_svr,1,1 acquired task /hbase/splitWAL/tmt_task > 2014-04-13 22:38:22,897 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe53350000, quorum=localhost:65092, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL > 2014-04-13 22:38:22,897 DEBUG [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(595): tasks arrived or departed > 2014-04-13 22:38:22,906 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe53350000, quorum=localhost:65092, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/tmt_task > 2014-04-13 22:38:22,906 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:22,907 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(522): task /hbase/splitWAL/tmt_task preempted from tmt_svr,1,1, current task state and owner=OWNED another-worker,1,1 > 2014-04-13 22:38:22,907 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread > 2014-04-13 22:38:22,907 WARN [SplitLogWorker-tmt_svr,1,1] regionserver.SplitLogWorker(374): Interrupted while yielding for other region servers > java.lang.InterruptedException: sleep interrupted > at java.lang.Thread.sleep(Native Method) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.grabTask(SplitLogWorker.java:372) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.taskLoop(SplitLogWorker.java:251) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.run(SplitLogWorker.java:209) > at java.lang.Thread.run(Thread.java:724) > 2014-04-13 22:38:22,922 INFO [SplitLogWorker-tmt_svr,1,1] regionserver.SplitLogWorker(363): worker tmt_svr,1,1 acquired task /hbase/splitWAL/tmt_task_2 > 2014-04-13 22:38:23,897 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker(420): BADVERSION failed to assert ownership for /hbase/splitWAL/tmt_task > org.apache.zookeeper.KeeperException$BadVersionException: KeeperErrorCode = BadVersion for /hbase/splitWAL/tmt_task > at org.apache.zookeeper.KeeperException.create(KeeperException.java:115) > at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) > at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1266) > at org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.setData(RecoverableZooKeeper.java:407) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.attemptToOwnTask(SplitLogWorker.java:406) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker$2.progress(SplitLogWorker.java:474) > at org.apache.hadoop.hbase.regionserver.TestSplitLogWorker$2.exec(TestSplitLogWorker.java:135) > at org.apache.hadoop.hbase.regionserver.handler.HLogSplitterHandler.process(HLogSplitterHandler.java:79) > at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:128) > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:724) > 2014-04-13 22:38:23,898 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker$2(477): Failed to heartbeat the task/hbase/splitWAL/tmt_task > 2014-04-13 22:38:23,898 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted tmt_task > 2014-04-13 22:38:23,898 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker tmt_svr,1,1 done with task /hbase/splitWAL/tmt_task in 1014ms > 2014-04-13 22:38:23,900 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:23,902 INFO [pool-1-thread-1] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread > 2014-04-13 22:38:23,902 INFO [SplitLogWorker-tmt_svr,1,1] regionserver.SplitLogWorker(299): SplitLogWorker interrupted while waiting for task, exiting: java.lang.InterruptedException > 2014-04-13 22:38:23,903 INFO [SplitLogWorker-tmt_svr,1,1] regionserver.SplitLogWorker(216): SplitLogWorker tmt_svr,1,1 exiting > 2014-04-13 22:38:23,903 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(87): task execution prempted tmt_task_2 > 2014-04-13 22:38:23,903 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(107): worker tmt_svr,1,1 done with task /hbase/splitWAL/tmt_task_2 in 977ms > 2014-04-13 22:38:23,905 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers > 2014-04-13 22:38:23,952 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testMultipleTasks Thread=20 (was 17) > Potentially hanging thread: pool-1-thread-1-SendThread(localhost:65092) > java.lang.Thread.sleep(Native Method) > org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(ClientCnxnSocketNIO.java:219) > org.apache.zookeeper.ClientCnxn$SendThread.cleanup(ClientCnxn.java:1164) > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1104) > - Thread LEAK? -, OpenFileDescriptor=123 (was 119) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=664 (was 664), ProcessCount=459 (was 459), AvailableMemoryMB=3604 (was 3758), ConnectionCount=0 (was 0) > 2014-04-13 22:38:24,004 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe53350000, quorum=localhost:65092, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null > 2014-04-13 22:38:24,004 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe53350000, quorum=localhost:65092, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring > 2014-04-13 22:38:24,010 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testRescan Thread=20, OpenFileDescriptor=125, MaxFileDescriptor=32768, SystemLoadAverage=664, ProcessCount=459, AvailableMemoryMB=3599, ConnectionCount=0 > 2014-04-13 22:38:24,031 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 55247 > 2014-04-13 22:38:24,041 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:55247 > 2014-04-13 22:38:24,100 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null > 2014-04-13 22:38:24,102 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe588d0000 connected > 2014-04-13 22:38:24,114 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created > 2014-04-13 22:38:24,135 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created > 2014-04-13 22:38:24,147 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10 > 2014-04-13 22:38:24,148 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(289): testRescan > 2014-04-13 22:38:24,150 INFO [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(175): SplitLogWorker svr,1,1 starting > 2014-04-13 22:38:24,271 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL > 2014-04-13 22:38:24,272 DEBUG [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(595): tasks arrived or departed > 2014-04-13 22:38:24,275 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:24,306 INFO [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(363): worker svr,1,1 acquired task /hbase/splitWAL/task > 2014-04-13 22:38:24,325 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/task > 2014-04-13 22:38:24,325 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:24,327 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(522): task /hbase/splitWAL/task preempted from svr,1,1, current task state and owner=UNASSIGNED manager,1,1 > 2014-04-13 22:38:24,327 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread > 2014-04-13 22:38:24,328 WARN [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(374): Interrupted while yielding for other region servers > java.lang.InterruptedException: sleep interrupted > at java.lang.Thread.sleep(Native Method) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.grabTask(SplitLogWorker.java:372) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.taskLoop(SplitLogWorker.java:251) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.run(SplitLogWorker.java:209) > at java.lang.Thread.run(Thread.java:724) > 2014-04-13 22:38:25,321 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker(420): BADVERSION failed to assert ownership for /hbase/splitWAL/task > org.apache.zookeeper.KeeperException$BadVersionException: KeeperErrorCode = BadVersion for /hbase/splitWAL/task > at org.apache.zookeeper.KeeperException.create(KeeperException.java:115) > at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) > at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1266) > at org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.setData(RecoverableZooKeeper.java:407) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.attemptToOwnTask(SplitLogWorker.java:406) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker$2.progress(SplitLogWorker.java:474) > at org.apache.hadoop.hbase.regionserver.TestSplitLogWorker$2.exec(TestSplitLogWorker.java:135) > at org.apache.hadoop.hbase.regionserver.handler.HLogSplitterHandler.process(HLogSplitterHandler.java:79) > at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:128) > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:724) > 2014-04-13 22:38:25,322 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker$2(477): Failed to heartbeat the task/hbase/splitWAL/task > 2014-04-13 22:38:25,322 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted task > 2014-04-13 22:38:25,322 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker svr,1,1 done with task /hbase/splitWAL/task in 1009ms > 2014-04-13 22:38:25,338 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL > 2014-04-13 22:38:25,338 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:25,338 DEBUG [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(595): tasks arrived or departed > 2014-04-13 22:38:25,355 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/task > 2014-04-13 22:38:25,357 INFO [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(363): worker svr,1,1 acquired task /hbase/splitWAL/task > 2014-04-13 22:38:25,363 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/task > 2014-04-13 22:38:25,363 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:25,367 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(522): task /hbase/splitWAL/task preempted from svr,1,1, current task state and owner=UNASSIGNED manager,1,1 > 2014-04-13 22:38:25,367 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread > 2014-04-13 22:38:25,368 WARN [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(374): Interrupted while yielding for other region servers > java.lang.InterruptedException: sleep interrupted > at java.lang.Thread.sleep(Native Method) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.grabTask(SplitLogWorker.java:372) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.taskLoop(SplitLogWorker.java:251) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.run(SplitLogWorker.java:209) > at java.lang.Thread.run(Thread.java:724) > 2014-04-13 22:38:25,388 INFO [SplitLogWorker-svr,1,1] handler.HLogSplitterHandler(123): successfully transitioned task /hbase/splitWAL/RESCANsplit-log-worker-tests0000000001 to final state DONE svr,1,1 > 2014-04-13 22:38:26,867 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] regionserver.SplitLogWorker(426): Interrupted while trying to assert ownership of /hbase/splitWAL/task java.lang.InterruptedException > at java.lang.Object.wait(Native Method) > at java.lang.Object.wait(Object.java:503) > at org.apache.zookeeper.ClientCnxn.submitRequest(ClientCnxn.java:1316) > at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1264) > at org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.setData(RecoverableZooKeeper.java:407) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.attemptToOwnTask(SplitLogWorker.java:406) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker$2.progress(SplitLogWorker.java:474) > at org.apache.hadoop.hbase.regionserver.TestSplitLogWorker$2.exec(TestSplitLogWorker.java:135) > at org.apache.hadoop.hbase.regionserver.handler.HLogSplitterHandler.process(HLogSplitterHandler.java:79) > at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:128) > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:724) > 2014-04-13 22:38:26,868 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] regionserver.SplitLogWorker$2(477): Failed to heartbeat the task/hbase/splitWAL/task > 2014-04-13 22:38:26,868 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(87): task execution prempted task > 2014-04-13 22:38:26,868 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(107): worker svr,1,1 done with task /hbase/splitWAL/task in 1504ms > 2014-04-13 22:38:26,968 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null > 2014-04-13 22:38:26,969 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring > 2014-04-13 22:38:27,112 ERROR [SyncThread:0] server.NIOServerCnxn(180): Unexpected Exception: > java.nio.channels.CancelledKeyException > at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:73) > at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:77) > at org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:153) > at org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1076) > at org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:404) > at org.apache.zookeeper.server.SyncRequestProcessor.flush(SyncRequestProcessor.java:167) > at org.apache.zookeeper.server.SyncRequestProcessor.run(SyncRequestProcessor.java:101) > 2014-04-13 22:38:27,114 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers > 2014-04-13 22:38:27,143 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testRescan Thread=22 (was 20) > Potentially hanging thread: pool-1-thread-1-SendThread(localhost:55247) > java.lang.Thread.sleep(Native Method) > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:991) > Potentially hanging thread: SplitLogWorker-svr,1,1 > java.lang.Object.wait(Native Method) > org.apache.hadoop.hbase.regionserver.SplitLogWorker.taskLoop(SplitLogWorker.java:265) > org.apache.hadoop.hbase.regionserver.SplitLogWorker.run(SplitLogWorker.java:209) > java.lang.Thread.run(Thread.java:724) > - Thread LEAK? -, OpenFileDescriptor=127 (was 125) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=664 (was 664), ProcessCount=459 (was 459), AvailableMemoryMB=3706 (was 3599) - AvailableMemoryMB LEAK? -, ConnectionCount=0 (was 0) > Standard Error > 2014-04-13 22:38:24,010 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testRescan Thread=20, OpenFileDescriptor=125, MaxFileDescriptor=32768, SystemLoadAverage=664, ProcessCount=459, AvailableMemoryMB=3599, ConnectionCount=0 > 2014-04-13 22:38:24,031 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 55247 > 2014-04-13 22:38:24,041 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:55247 > 2014-04-13 22:38:24,100 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null > 2014-04-13 22:38:24,102 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe588d0000 connected > 2014-04-13 22:38:24,114 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created > 2014-04-13 22:38:24,135 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created > 2014-04-13 22:38:24,147 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10 > 2014-04-13 22:38:24,148 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(289): testRescan > 2014-04-13 22:38:24,150 INFO [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(175): SplitLogWorker svr,1,1 starting > 2014-04-13 22:38:24,271 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL > 2014-04-13 22:38:24,272 DEBUG [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(595): tasks arrived or departed > 2014-04-13 22:38:24,275 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:24,306 INFO [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(363): worker svr,1,1 acquired task /hbase/splitWAL/task > 2014-04-13 22:38:24,325 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/task > 2014-04-13 22:38:24,325 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:24,327 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(522): task /hbase/splitWAL/task preempted from svr,1,1, current task state and owner=UNASSIGNED manager,1,1 > 2014-04-13 22:38:24,327 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread > 2014-04-13 22:38:24,328 WARN [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(374): Interrupted while yielding for other region servers > java.lang.InterruptedException: sleep interrupted > at java.lang.Thread.sleep(Native Method) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.grabTask(SplitLogWorker.java:372) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.taskLoop(SplitLogWorker.java:251) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.run(SplitLogWorker.java:209) > at java.lang.Thread.run(Thread.java:724) > 2014-04-13 22:38:25,321 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker(420): BADVERSION failed to assert ownership for /hbase/splitWAL/task > org.apache.zookeeper.KeeperException$BadVersionException: KeeperErrorCode = BadVersion for /hbase/splitWAL/task > at org.apache.zookeeper.KeeperException.create(KeeperException.java:115) > at org.apache.zookeeper.KeeperException.create(KeeperException.java:51) > at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1266) > at org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.setData(RecoverableZooKeeper.java:407) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.attemptToOwnTask(SplitLogWorker.java:406) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker$2.progress(SplitLogWorker.java:474) > at org.apache.hadoop.hbase.regionserver.TestSplitLogWorker$2.exec(TestSplitLogWorker.java:135) > at org.apache.hadoop.hbase.regionserver.handler.HLogSplitterHandler.process(HLogSplitterHandler.java:79) > at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:128) > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:724) > 2014-04-13 22:38:25,322 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker$2(477): Failed to heartbeat the task/hbase/splitWAL/task > 2014-04-13 22:38:25,322 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted task > 2014-04-13 22:38:25,322 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker svr,1,1 done with task /hbase/splitWAL/task in 1009ms > 2014-04-13 22:38:25,338 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL > 2014-04-13 22:38:25,338 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:25,338 DEBUG [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(595): tasks arrived or departed > 2014-04-13 22:38:25,355 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/task > 2014-04-13 22:38:25,357 INFO [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(363): worker svr,1,1 acquired task /hbase/splitWAL/task > 2014-04-13 22:38:25,363 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/task > 2014-04-13 22:38:25,363 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1]) > 2014-04-13 22:38:25,367 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(522): task /hbase/splitWAL/task preempted from svr,1,1, current task state and owner=UNASSIGNED manager,1,1 > 2014-04-13 22:38:25,367 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread > 2014-04-13 22:38:25,368 WARN [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(374): Interrupted while yielding for other region servers > java.lang.InterruptedException: sleep interrupted > at java.lang.Thread.sleep(Native Method) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.grabTask(SplitLogWorker.java:372) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.taskLoop(SplitLogWorker.java:251) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.run(SplitLogWorker.java:209) > at java.lang.Thread.run(Thread.java:724) > 2014-04-13 22:38:25,388 INFO [SplitLogWorker-svr,1,1] handler.HLogSplitterHandler(123): successfully transitioned task /hbase/splitWAL/RESCANsplit-log-worker-tests0000000001 to final state DONE svr,1,1 > 2014-04-13 22:38:26,867 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] regionserver.SplitLogWorker(426): Interrupted while trying to assert ownership of /hbase/splitWAL/task java.lang.InterruptedException > at java.lang.Object.wait(Native Method) > at java.lang.Object.wait(Object.java:503) > at org.apache.zookeeper.ClientCnxn.submitRequest(ClientCnxn.java:1316) > at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1264) > at org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.setData(RecoverableZooKeeper.java:407) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker.attemptToOwnTask(SplitLogWorker.java:406) > at org.apache.hadoop.hbase.regionserver.SplitLogWorker$2.progress(SplitLogWorker.java:474) > at org.apache.hadoop.hbase.regionserver.TestSplitLogWorker$2.exec(TestSplitLogWorker.java:135) > at org.apache.hadoop.hbase.regionserver.handler.HLogSplitterHandler.process(HLogSplitterHandler.java:79) > at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:128) > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) > at java.lang.Thread.run(Thread.java:724) > 2014-04-13 22:38:26,868 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] regionserver.SplitLogWorker$2(477): Failed to heartbeat the task/hbase/splitWAL/task > 2014-04-13 22:38:26,868 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(87): task execution prempted task > 2014-04-13 22:38:26,868 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(107): worker svr,1,1 done with task /hbase/splitWAL/task in 1504ms > 2014-04-13 22:38:26,968 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null > 2014-04-13 22:38:26,969 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring > 2014-04-13 22:38:27,112 ERROR [SyncThread:0] server.NIOServerCnxn(180): Unexpected Exception: > java.nio.channels.CancelledKeyException > at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:73) > at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:77) > at org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:153) > at org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1076) > at org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:404) > at org.apache.zookeeper.server.SyncRequestProcessor.flush(SyncRequestProcessor.java:167) > at org.apache.zookeeper.server.SyncRequestProcessor.run(SyncRequestProcessor.java:101) > 2014-04-13 22:38:27,114 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers > 2014-04-13 22:38:27,143 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testRescan Thread=22 (was 20) > Potentially hanging thread: pool-1-thread-1-SendThread(localhost:55247) > java.lang.Thread.sleep(Native Method) > org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:991) > Potentially hanging thread: SplitLogWorker-svr,1,1 > java.lang.Object.wait(Native Method) > org.apache.hadoop.hbase.regionserver.SplitLogWorker.taskLoop(SplitLogWorker.java:265) > org.apache.hadoop.hbase.regionserver.SplitLogWorker.run(SplitLogWorker.java:209) > java.lang.Thread.run(Thread.java:724) > - Thread LEAK? -, OpenFileDescriptor=127 (was 125) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=664 (was 664), ProcessCount=459 (was 459), AvailableMemoryMB=3706 (was 3599) - AvailableMemoryMB LEAK? -, ConnectionCount=0 (was 0) > {code} -- This message was sent by Atlassian JIRA (v6.2#6252)