hbase-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "stack (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (HBASE-12558) TestHCM.testClusterStatus Unexpected exception, expected<org.apache.hadoop.hbase.regionserver.RegionServerStoppedException> but was<junit.framework.AssertionFailedError>
Date Thu, 27 Nov 2014 06:45:13 GMT

    [ https://issues.apache.org/jira/browse/HBASE-12558?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14227317#comment-14227317 ] 

stack commented on HBASE-12558:
-------------------------------

Here is the log:
{code}
Error Message

Unexpected exception, expected<org.apache.hadoop.hbase.regionserver.RegionServerStoppedException> but was<junit.framework.AssertionFailedError>
Stacktrace

java.lang.Exception: Unexpected exception, expected<org.apache.hadoop.hbase.regionserver.RegionServerStoppedException> but was<junit.framework.AssertionFailedError>
	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:3563)
	at org.apache.hadoop.hbase.client.TestHCM.testClusterStatus(TestHCM.java:275)
Standard Output

2014-11-27 02:52:13,379 INFO  [main] hbase.ResourceChecker(148): before: client.TestHCM#testConnection Thread=337, OpenFileDescriptor=543, MaxFileDescriptor=60000, SystemLoadAverage=357, ProcessCount=308, AvailableMemoryMB=13828, ConnectionCount=0
2014-11-27 02:52:13,404 INFO  [Thread-271] zookeeper.RecoverableZooKeeper(121): Process identifier=hconnection-0x1f579e connecting to ZooKeeper ensemble=localhost:59911
2014-11-27 02:52:13,408 DEBUG [Thread-271-EventThread] zookeeper.ZooKeeperWatcher(3
...[truncated 11872462 bytes]...
ookThread(133): Shutdown hook finished.
2014-11-27 02:55:18,380 INFO  [Thread-2] regionserver.ShutdownHook$ShutdownHookThread(111): Shutdown hook starting; hbase.shutdown.hook=true; fsShutdownHook=org.apache.hadoop.fs.FileSystem$Cache$ClientFinalizer@f21f54
2014-11-27 02:55:18,381 INFO  [Thread-2] regionserver.ShutdownHook$ShutdownHookThread(120): Starting fs shutdown hook thread.
2014-11-27 02:55:18,381 INFO  [Thread-2] regionserver.ShutdownHook$ShutdownHookThread(133): Shutdown hook finished.
Standard Error

2014-11-27 02:54:04,059 INFO  [main] hbase.ResourceChecker(172): after: client.TestHCM#testConnectionIdle Thread=360 (was 357) - Thread LEAK? -, OpenFileDescriptor=585 (was 568) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=60000 (was 60000), SystemLoadAverage=538 (was 550), ProcessCount=308 (was 308), AvailableMemoryMB=13766 (was 14098), ConnectionCount=1 (was 1)
2014-11-27 02:54:04,097 INFO  [main] hbase.ResourceChecker(148): before: client.TestHCM#testClusterStatus Thread=360, OpenFileDescriptor=585, MaxFileDescriptor=60000, SystemLoadAverage=538, ProcessCount=308, AvailableMemoryMB=13765, ConnectionCount=1
2014-11-27 02:54:04,119 INFO  [main] client.ConnectionUtils(102): regionserver/asf910.gq1.ygridcore.net/67.195.81.154:0 server-side HConnection retries=350
2014-11-27 02:54:04,120 INFO  [main] ipc.SimpleRpcScheduler(123): Using deadline as user call queue, count=1
2014-11-27 02:54:04,125 INFO  [main] ipc.RpcServer$Listener(542): regionserver/asf910.gq1.ygridcore.net/67.195.81.154:0: started 10 reader(s).
2014-11-27 02:54:04,128 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
2014-11-27 02:54:04,130 INFO  [main] zookeeper.RecoverableZooKeeper(121): Process identifier=regionserver:40070 connecting to ZooKeeper ensemble=localhost:59911
2014-11-27 02:54:04,138 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:40070, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2014-11-27 02:54:04,138 DEBUG [main] zookeeper.ZKUtil(424): regionserver:40070, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/master
2014-11-27 02:54:04,140 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(388): regionserver:40070-0x149ef29bd7d0028 connected
2014-11-27 02:54:04,140 DEBUG [main] zookeeper.ZKUtil(424): regionserver:40070-0x149ef29bd7d0028, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/running
2014-11-27 02:54:04,141 DEBUG [main] ipc.RpcExecutor(99): B.default Start Handler index=0 queue=0
2014-11-27 02:54:04,142 DEBUG [main] ipc.RpcExecutor(99): B.default Start Handler index=1 queue=0
2014-11-27 02:54:04,142 INFO  [RpcServer.responder] ipc.RpcServer$Responder(861): RpcServer.responder: starting
2014-11-27 02:54:04,142 DEBUG [main] ipc.RpcExecutor(99): B.default Start Handler index=2 queue=0
2014-11-27 02:54:04,142 DEBUG [main] ipc.RpcExecutor(99): B.default Start Handler index=3 queue=0
2014-11-27 02:54:04,143 DEBUG [main] ipc.RpcExecutor(99): B.default Start Handler index=4 queue=0
2014-11-27 02:54:04,143 DEBUG [main] ipc.RpcExecutor(99): Priority Start Handler index=0 queue=0
2014-11-27 02:54:04,143 DEBUG [main] ipc.RpcExecutor(99): Priority Start Handler index=1 queue=0
2014-11-27 02:54:04,144 DEBUG [main] ipc.RpcExecutor(99): Priority Start Handler index=2 queue=0
2014-11-27 02:54:04,142 INFO  [RpcServer.listener,port=40070] ipc.RpcServer$Listener(673): RpcServer.listener,port=40070: starting
2014-11-27 02:54:04,144 DEBUG [main] ipc.RpcExecutor(99): Priority Start Handler index=3 queue=0
2014-11-27 02:54:04,145 DEBUG [main] ipc.RpcExecutor(99): Priority Start Handler index=4 queue=0
2014-11-27 02:54:04,145 DEBUG [main] ipc.RpcExecutor(99): Priority Start Handler index=5 queue=0
2014-11-27 02:54:04,145 DEBUG [main] ipc.RpcExecutor(99): Priority Start Handler index=6 queue=0
2014-11-27 02:54:04,146 DEBUG [main] ipc.RpcExecutor(99): Priority Start Handler index=7 queue=0
2014-11-27 02:54:04,146 DEBUG [main] ipc.RpcExecutor(99): Priority Start Handler index=8 queue=0
2014-11-27 02:54:04,146 DEBUG [main] ipc.RpcExecutor(99): Priority Start Handler index=9 queue=0
2014-11-27 02:54:04,147 DEBUG [main] ipc.RpcExecutor(99): Replication Start Handler index=0 queue=0
2014-11-27 02:54:04,147 DEBUG [main] ipc.RpcExecutor(99): Replication Start Handler index=1 queue=0
2014-11-27 02:54:04,147 DEBUG [main] ipc.RpcExecutor(99): Replication Start Handler index=2 queue=0
2014-11-27 02:54:04,148 INFO  [main] http.HttpRequestLog(69): Http request log for http.requests.regionserver is not defined
2014-11-27 02:54:04,149 INFO  [main] http.HttpServer(817): Added global filter 'safety' (class=org.apache.hadoop.hbase.http.HttpServer$QuotingInputFilter)
2014-11-27 02:54:04,150 INFO  [main] http.HttpServer(795): Added filter static_user_filter (class=org.apache.hadoop.hbase.http.lib.StaticUserWebFilter$StaticUserFilter) to context regionserver
2014-11-27 02:54:04,151 INFO  [main] http.HttpServer(802): Added filter static_user_filter (class=org.apache.hadoop.hbase.http.lib.StaticUserWebFilter$StaticUserFilter) to context logs
2014-11-27 02:54:04,151 INFO  [main] http.HttpServer(802): Added filter static_user_filter (class=org.apache.hadoop.hbase.http.lib.StaticUserWebFilter$StaticUserFilter) to context static
2014-11-27 02:54:04,152 INFO  [main] http.HttpServer(1009): Jetty bound to port 40322
2014-11-27 02:54:04,153 INFO  [main] log.Slf4jLog(67): jetty-6.1.26
2014-11-27 02:54:04,170 INFO  [main] log.Slf4jLog(67): Started SelectChannelConnector@0.0.0.0:40322
2014-11-27 02:54:04,173 INFO  [RS:2;asf910:40070] zookeeper.RecoverableZooKeeper(121): Process identifier=hconnection-0xaf3e28 connecting to ZooKeeper ensemble=localhost:59911
2014-11-27 02:54:04,177 DEBUG [RS:2;asf910:40070-EventThread] zookeeper.ZooKeeperWatcher(304): hconnection-0xaf3e28, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2014-11-27 02:54:04,178 DEBUG [RS:2;asf910:40070] ipc.RpcClient(1331): Codec=org.apache.hadoop.hbase.codec.KeyValueCodec@30913f, compressor=null, tcpKeepAlive=true, tcpNoDelay=true, connectTO=10000, readTO=20000, writeTO=60000, minIdleTimeBeforeClose=120000, maxRetries=0, fallbackAllowed=true, bind address=null
2014-11-27 02:54:04,179 DEBUG [RS:2;asf910:40070-EventThread] zookeeper.ZooKeeperWatcher(388): hconnection-0xaf3e28-0x149ef29bd7d0029 connected
2014-11-27 02:54:04,184 INFO  [RS:2;asf910:40070] regionserver.HRegionServer(711): ClusterId : 55ce85f6-538a-4ed9-8ecb-ad2f3a29d396
2014-11-27 02:54:04,184 DEBUG [RS:2;asf910:40070] procedure.RegionServerProcedureManagerHost(44): Procedure online-snapshot is initializing
2014-11-27 02:54:04,196 DEBUG [RS:2;asf910:40070] zookeeper.RecoverableZooKeeper(531): Node /hbase/online-snapshot/acquired already exists
2014-11-27 02:54:04,198 DEBUG [RS:2;asf910:40070] procedure.RegionServerProcedureManagerHost(46): Procedure online-snapshot is initialized
2014-11-27 02:54:04,198 DEBUG [RS:2;asf910:40070] procedure.RegionServerProcedureManagerHost(44): Procedure flush-table-proc is initializing
2014-11-27 02:54:04,200 DEBUG [RS:2;asf910:40070] zookeeper.RecoverableZooKeeper(531): Node /hbase/flush-table-proc/acquired already exists
2014-11-27 02:54:04,201 DEBUG [RS:2;asf910:40070] procedure.RegionServerProcedureManagerHost(46): Procedure flush-table-proc is initialized
2014-11-27 02:54:04,201 INFO  [RS:2;asf910:40070] regionserver.MemStoreFlusher(117): globalMemStoreLimit=675.6 M, globalMemStoreLimitLowMark=641.8 M, maxHeap=1.6 G
2014-11-27 02:54:04,202 INFO  [RS:2;asf910:40070] regionserver.HRegionServer$CompactionChecker(1420): CompactionChecker runs every 1sec
2014-11-27 02:54:04,202 DEBUG [RS:2;asf910:40070] ipc.RpcClient(1331): Codec=org.apache.hadoop.hbase.codec.KeyValueCodec@aff031, compressor=null, tcpKeepAlive=true, tcpNoDelay=true, connectTO=10000, readTO=20000, writeTO=60000, minIdleTimeBeforeClose=120000, maxRetries=0, fallbackAllowed=true, bind address=asf910.gq1.ygridcore.net/67.195.81.154:0
2014-11-27 02:54:04,202 DEBUG [RS:2;asf910:40070] regionserver.ShutdownHook(87): Installed shutdown hook thread: Shutdownhook:RS:2;asf910:40070
2014-11-27 02:54:04,203 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/rs
2014-11-27 02:54:04,204 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:39158-0x149ef29bd7d001a, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/rs
2014-11-27 02:54:04,204 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/rs
2014-11-27 02:54:04,205 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:04,206 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:39158-0x149ef29bd7d001a, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:04,205 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:04,206 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,39158,1417056807975
2014-11-27 02:54:04,207 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:04,207 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,39158,1417056807975
2014-11-27 02:54:04,207 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:39158-0x149ef29bd7d001a, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,39158,1417056807975
2014-11-27 02:54:04,208 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,208 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:39158-0x149ef29bd7d001a, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:04,208 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:04,209 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:39158-0x149ef29bd7d001a, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,209 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,209 DEBUG [Thread-510-EventThread] zookeeper.RegionServerTracker(94): Added tracking of RS /hbase/rs/asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:04,210 DEBUG [RS:2;asf910:40070] zookeeper.ZKUtil(424): regionserver:40070-0x149ef29bd7d0028, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,218 DEBUG [Thread-510-EventThread] zookeeper.RegionServerTracker(94): Added tracking of RS /hbase/rs/asf910.gq1.ygridcore.net,39158,1417056807975
2014-11-27 02:54:04,219 INFO  [RS:2;asf910:40070] regionserver.HRegionServer(2128): reportForDuty to master=asf910.gq1.ygridcore.net,41326,1417056807779 with port=40070, startcode=1417056844127
2014-11-27 02:54:04,219 DEBUG [RS:2;asf910:40070] ipc.RpcClient$Connection(565): Use SIMPLE authentication for service RegionServerStatusService, sasl=false
2014-11-27 02:54:04,219 DEBUG [RS:2;asf910:40070] ipc.RpcClient$Connection(931): Connecting to asf910.gq1.ygridcore.net/67.195.81.154:41326
2014-11-27 02:54:04,219 DEBUG [Thread-510-EventThread] zookeeper.RegionServerTracker(94): Added tracking of RS /hbase/rs/asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:04,220 DEBUG [RpcServer.listener,port=41326] ipc.RpcServer$Listener(784): RpcServer.listener,port=41326: connection from 67.195.81.154:59287; # active connections: 7
2014-11-27 02:54:04,220 DEBUG [Thread-510-EventThread] zookeeper.RegionServerTracker(94): Added tracking of RS /hbase/rs/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,220 INFO  [B.defaultRpcServer.handler=2,queue=0,port=41326] master.ServerManager(408): Registering server=asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,221 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:04,221 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,39158,1417056807975
2014-11-27 02:54:04,221 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:04,222 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,225 INFO  [RS:2;asf910:40070] regionserver.HRegionServer(1251): Config from master: hbase.rootdir=hdfs://localhost:48748/user/jenkins/hbase
2014-11-27 02:54:04,225 INFO  [RS:2;asf910:40070] regionserver.HRegionServer(1251): Config from master: fs.defaultFS=hdfs://localhost:48748
2014-11-27 02:54:04,225 INFO  [RS:2;asf910:40070] regionserver.HRegionServer(1251): Config from master: hbase.master.info.port=37068
2014-11-27 02:54:04,225 WARN  [RS:2;asf910:40070] hbase.ZNodeClearer(58): Environment variable HBASE_ZNODE_FILE not set; znodes will not be cleared on crash by start scripts (Longer MTTR!)
2014-11-27 02:54:04,226 INFO  [RS:2;asf910:40070] hfile.CacheConfig(260): blockCache=LruBlockCache{blockCount=5, currentSize=442896, freeSize=707948848, maxSize=708391744, heapSize=442896, minSize=672972160, minFactor=0.95, multiSize=336486080, multiFactor=0.5, singleSize=168243040, singleFactor=0.25}, cacheDataOnRead=true, cacheDataOnWrite=false, cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false, cacheDataCompressed=false, prefetchOnOpen=false
2014-11-27 02:54:04,226 DEBUG [RS:2;asf910:40070] regionserver.HRegionServer(1517): logdir=hdfs://localhost:48748/user/jenkins/hbase/WALs/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,235 DEBUG [RS:2;asf910:40070] regionserver.Replication(140): ReplicationStatisticsThread 300
2014-11-27 02:54:04,240 INFO  [RS:2;asf910:40070] wal.FSHLog(543): WAL configuration: blocksize=128 MB, rollsize=121.60 MB, prefix=asf910.gq1.ygridcore.net%2C40070%2C1417056844127.default, suffix=, logDir=hdfs://localhost:48748/user/jenkins/hbase/WALs/asf910.gq1.ygridcore.net,40070,1417056844127, archiveDir=hdfs://localhost:48748/user/jenkins/hbase/oldWALs
2014-11-27 02:54:04,254 INFO  [RS:2;asf910:40070] wal.FSHLog(1460): Slow sync cost: 10 ms, current pipeline: []
2014-11-27 02:54:04,254 INFO  [RS:2;asf910:40070] wal.FSHLog(941): New WAL /user/jenkins/hbase/WALs/asf910.gq1.ygridcore.net,40070,1417056844127/asf910.gq1.ygridcore.net%2C40070%2C1417056844127.default.1417056844240
2014-11-27 02:54:04,256 INFO  [RS:2;asf910:40070] regionserver.MetricsRegionServerWrapperImpl(110): Computing regionserver metrics every 5000 milliseconds
2014-11-27 02:54:04,257 DEBUG [RS:2;asf910:40070] executor.ExecutorService(91): Starting executor service name=RS_OPEN_REGION-asf910:40070, corePoolSize=3, maxPoolSize=3
2014-11-27 02:54:04,257 DEBUG [RS:2;asf910:40070] executor.ExecutorService(91): Starting executor service name=RS_OPEN_META-asf910:40070, corePoolSize=1, maxPoolSize=1
2014-11-27 02:54:04,257 DEBUG [RS:2;asf910:40070] executor.ExecutorService(91): Starting executor service name=RS_CLOSE_REGION-asf910:40070, corePoolSize=3, maxPoolSize=3
2014-11-27 02:54:04,257 DEBUG [RS:2;asf910:40070] executor.ExecutorService(91): Starting executor service name=RS_CLOSE_META-asf910:40070, corePoolSize=1, maxPoolSize=1
2014-11-27 02:54:04,258 DEBUG [RS:2;asf910:40070] executor.ExecutorService(91): Starting executor service name=RS_LOG_REPLAY_OPS-asf910:40070, corePoolSize=2, maxPoolSize=2
2014-11-27 02:54:04,260 DEBUG [RS:2;asf910:40070] zookeeper.ZKUtil(424): regionserver:40070-0x149ef29bd7d0028, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:04,260 DEBUG [RS:2;asf910:40070] zookeeper.ZKUtil(424): regionserver:40070-0x149ef29bd7d0028, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,39158,1417056807975
2014-11-27 02:54:04,262 DEBUG [RS:2;asf910:40070] zookeeper.ZKUtil(424): regionserver:40070-0x149ef29bd7d0028, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:04,262 DEBUG [RS:2;asf910:40070] zookeeper.ZKUtil(424): regionserver:40070-0x149ef29bd7d0028, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,262 INFO  [RS:2;asf910:40070] regionserver.ReplicationSourceManager(226): Current list of replicators: [asf910.gq1.ygridcore.net,55008,1417056807855, asf910.gq1.ygridcore.net,39158,1417056807975, asf910.gq1.ygridcore.net,41326,1417056807779, asf910.gq1.ygridcore.net,40070,1417056844127] other RSs: [asf910.gq1.ygridcore.net,55008,1417056807855, asf910.gq1.ygridcore.net,39158,1417056807975, asf910.gq1.ygridcore.net,41326,1417056807779, asf910.gq1.ygridcore.net,40070,1417056844127]
2014-11-27 02:54:04,293 INFO  [RS:2;asf910:40070] zookeeper.RecoverableZooKeeper(121): Process identifier=hconnection-0x1d096d8 connecting to ZooKeeper ensemble=localhost:59911
2014-11-27 02:54:04,296 DEBUG [RS:2;asf910:40070-EventThread] zookeeper.ZooKeeperWatcher(304): hconnection-0x1d096d8, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2014-11-27 02:54:04,297 DEBUG [RS:2;asf910:40070] ipc.RpcClient(1331): Codec=org.apache.hadoop.hbase.codec.KeyValueCodecWithTags@18bc076, compressor=null, tcpKeepAlive=true, tcpNoDelay=true, connectTO=10000, readTO=20000, writeTO=60000, minIdleTimeBeforeClose=120000, maxRetries=0, fallbackAllowed=true, bind address=null
2014-11-27 02:54:04,297 DEBUG [RS:2;asf910:40070-EventThread] zookeeper.ZooKeeperWatcher(388): hconnection-0x1d096d8-0x149ef29bd7d002a connected
2014-11-27 02:54:04,326 INFO  [SplitLogWorker-asf910:40070] regionserver.SplitLogWorker(135): SplitLogWorker asf910.gq1.ygridcore.net,40070,1417056844127 starting
2014-11-27 02:54:04,326 INFO  [RS:2;asf910:40070] regionserver.HRegionServer(1273): Serving as asf910.gq1.ygridcore.net,40070,1417056844127, RpcServer on asf910.gq1.ygridcore.net/67.195.81.154:40070, sessionid=0x149ef29bd7d0028
2014-11-27 02:54:04,327 DEBUG [RS:2;asf910:40070] procedure.RegionServerProcedureManagerHost(52): Procedure online-snapshot is starting
2014-11-27 02:54:04,327 DEBUG [RS:2;asf910:40070] snapshot.RegionServerSnapshotManager(124): Start Snapshot Manager asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,327 DEBUG [RS:2;asf910:40070] procedure.ZKProcedureMemberRpcs(349): Starting procedure member 'asf910.gq1.ygridcore.net,40070,1417056844127'
2014-11-27 02:54:04,327 INFO  [B.defaultRpcServer.handler=0,queue=0,port=41326] master.HMaster(1168): Client=jenkins//67.195.81.154 create 'testClusterStatus', {NAME => 'cf', DATA_BLOCK_ENCODING => 'NONE', BLOOMFILTER => 'NONE', REPLICATION_SCOPE => '0', VERSIONS => '1', COMPRESSION => 'NONE', MIN_VERSIONS => '0', TTL => 'FOREVER', KEEP_DELETED_CELLS => 'FALSE', BLOCKSIZE => '65536', IN_MEMORY => 'false', BLOCKCACHE => 'true'}
2014-11-27 02:54:04,327 DEBUG [RS:2;asf910:40070] procedure.ZKProcedureMemberRpcs(136): Checking for aborted procedures on node: '/hbase/online-snapshot/abort'
2014-11-27 02:54:04,329 DEBUG [RS:2;asf910:40070] procedure.ZKProcedureMemberRpcs(152): Looking for new procedures under znode:'/hbase/online-snapshot/acquired'
2014-11-27 02:54:04,330 DEBUG [RS:2;asf910:40070] procedure.RegionServerProcedureManagerHost(54): Procedure online-snapshot is started
2014-11-27 02:54:04,330 DEBUG [RS:2;asf910:40070] procedure.RegionServerProcedureManagerHost(52): Procedure flush-table-proc is starting
2014-11-27 02:54:04,330 DEBUG [RS:2;asf910:40070] flush.RegionServerFlushTableProcedureManager(101): Start region server flush procedure manager asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,331 DEBUG [RS:2;asf910:40070] procedure.ZKProcedureMemberRpcs(349): Starting procedure member 'asf910.gq1.ygridcore.net,40070,1417056844127'
2014-11-27 02:54:04,331 DEBUG [RS:2;asf910:40070] procedure.ZKProcedureMemberRpcs(136): Checking for aborted procedures on node: '/hbase/flush-table-proc/abort'
2014-11-27 02:54:04,332 DEBUG [B.defaultRpcServer.handler=0,queue=0,port=41326] lock.ZKInterProcessLockBase(226): Acquired a lock for /hbase/table-lock/testClusterStatus/write-master:413260000000000
2014-11-27 02:54:04,332 DEBUG [RS:2;asf910:40070] procedure.ZKProcedureMemberRpcs(152): Looking for new procedures under znode:'/hbase/flush-table-proc/acquired'
2014-11-27 02:54:04,333 DEBUG [RS:2;asf910:40070] procedure.RegionServerProcedureManagerHost(54): Procedure flush-table-proc is started
2014-11-27 02:54:04,333 INFO  [RS:2;asf910:40070] quotas.RegionServerQuotaManager(63): Quota support disabled
2014-11-27 02:54:04,333 INFO  [MASTER_TABLE_OPERATIONS-asf910:41326-0] handler.CreateTableHandler(147): Create table testClusterStatus
2014-11-27 02:54:04,353 INFO  [IPC Server handler 2 on 48748] blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:46969 is added to blk_1073741892_1068{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-ee034427-e712-4146-bf17-8a4bf7c8f6e2:NORMAL|RBW], ReplicaUnderConstruction[[DISK]DS-61b4ee5f-784a-467f-831e-620705e0ff87:NORMAL|RBW]]} size 0
2014-11-27 02:54:04,356 INFO  [IPC Server handler 9 on 48748] blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:58365 is added to blk_1073741892_1068 size 301
2014-11-27 02:54:04,358 DEBUG [MASTER_TABLE_OPERATIONS-asf910:41326-0] util.FSTableDescriptors(722): Wrote descriptor into: hdfs://localhost:48748/user/jenkins/hbase/.tmp/data/default/testClusterStatus/.tabledesc/.tableinfo.0000000001
2014-11-27 02:54:04,359 INFO  [RegionOpenAndInitThread-testClusterStatus-1] regionserver.HRegion(4565): creating HRegion testClusterStatus HTD == 'testClusterStatus', {NAME => 'cf', DATA_BLOCK_ENCODING => 'NONE', BLOOMFILTER => 'NONE', REPLICATION_SCOPE => '0', VERSIONS => '1', COMPRESSION => 'NONE', MIN_VERSIONS => '0', TTL => 'FOREVER', KEEP_DELETED_CELLS => 'FALSE', BLOCKSIZE => '65536', IN_MEMORY => 'false', BLOCKCACHE => 'true'} RootDir = hdfs://localhost:48748/user/jenkins/hbase/.tmp Table name == testClusterStatus
2014-11-27 02:54:04,370 INFO  [IPC Server handler 9 on 48748] blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:58365 is added to blk_1073741893_1069{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-48736bec-0a55-493d-bd57-d06dff81996b:NORMAL|RBW], ReplicaUnderConstruction[[DISK]DS-b34f3e46-e307-495a-bfea-28dcd03ad0c9:NORMAL|RBW]]} size 0
2014-11-27 02:54:04,371 INFO  [IPC Server handler 4 on 48748] blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:46969 is added to blk_1073741893_1069 size 52
2014-11-27 02:54:04,372 DEBUG [RegionOpenAndInitThread-testClusterStatus-1] regionserver.HRegion(677): Instantiated testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,372 DEBUG [RegionOpenAndInitThread-testClusterStatus-1] regionserver.HRegion(1195): Closing testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.: disabling compactions & flushes
2014-11-27 02:54:04,372 DEBUG [RegionOpenAndInitThread-testClusterStatus-1] regionserver.HRegion(1222): Updates disabled for region testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,372 INFO  [RegionOpenAndInitThread-testClusterStatus-1] regionserver.HRegion(1310): Closed testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,376 INFO  [MASTER_TABLE_OPERATIONS-asf910:41326-0] hbase.MetaTableAccessor(1154): Added 1
2014-11-27 02:54:04,383 DEBUG [MASTER_TABLE_OPERATIONS-asf910:41326-0] regionserver.HRegionFileSystem(197): No StoreFiles for: hdfs://localhost:48748/user/jenkins/hbase/data/default/testClusterStatus/9d75ee5afbcbc47cfa854a6a4143afee/cf
2014-11-27 02:54:04,383 INFO  [MASTER_TABLE_OPERATIONS-asf910:41326-0] master.AssignmentManager(1473): Bulk assigning 1 region(s) across 4 server(s), round-robin=true
2014-11-27 02:54:04,384 DEBUG [MASTER_TABLE_OPERATIONS-asf910:41326-0] master.GeneralBulkAssigner(177): Timeout-on-RIT=181000
2014-11-27 02:54:04,384 INFO  [asf910.gq1.ygridcore.net,41326,1417056807779-GeneralBulkAssigner-3] master.AssignmentManager(671): Assigning 1 region(s) to asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:04,384 INFO  [asf910.gq1.ygridcore.net,41326,1417056807779-GeneralBulkAssigner-3] master.RegionStates(973): Transition {9d75ee5afbcbc47cfa854a6a4143afee state=OFFLINE, ts=1417056844377, server=null} to {9d75ee5afbcbc47cfa854a6a4143afee state=PENDING_OPEN, ts=1417056844384, server=asf910.gq1.ygridcore.net,55008,1417056807855}
2014-11-27 02:54:04,385 INFO  [asf910.gq1.ygridcore.net,41326,1417056807779-GeneralBulkAssigner-3] master.RegionStateStore(207): Updating row testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee. with state=PENDING_OPEN&sn=asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:04,386 INFO  [PriorityRpcServer.handler=2,queue=0,port=55008] regionserver.RSRpcServices(1327): Open testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,392 DEBUG [asf910.gq1.ygridcore.net,41326,1417056807779-GeneralBulkAssigner-3] master.AssignmentManager(830): Bulk assigning done for asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:04,392 DEBUG [RS_OPEN_REGION-asf910:55008-0] regionserver.HRegion(4758): Opening region: {ENCODED => 9d75ee5afbcbc47cfa854a6a4143afee, NAME => 'testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.', STARTKEY => '', ENDKEY => ''}
2014-11-27 02:54:04,392 DEBUG [MASTER_TABLE_OPERATIONS-asf910:41326-0] master.GeneralBulkAssigner(153): bulk assigning total 1 regions to 4 servers, took 8ms, with 1 regions still in transition
2014-11-27 02:54:04,392 INFO  [MASTER_TABLE_OPERATIONS-asf910:41326-0] master.AssignmentManager(1480): Bulk assigning done
2014-11-27 02:54:04,392 DEBUG [RS_OPEN_REGION-asf910:55008-0] regionserver.MetricsRegionSourceImpl(67): Creating new MetricsRegionSourceImpl for table testClusterStatus 9d75ee5afbcbc47cfa854a6a4143afee
2014-11-27 02:54:04,393 DEBUG [RS_OPEN_REGION-asf910:55008-0] regionserver.HRegion(677): Instantiated testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,397 INFO  [StoreOpener-9d75ee5afbcbc47cfa854a6a4143afee-1] hfile.CacheConfig(260): blockCache=LruBlockCache{blockCount=5, currentSize=442896, freeSize=707948848, maxSize=708391744, heapSize=442896, minSize=672972160, minFactor=0.95, multiSize=336486080, multiFactor=0.5, singleSize=168243040, singleFactor=0.25}, cacheDataOnRead=true, cacheDataOnWrite=false, cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false, cacheDataCompressed=false, prefetchOnOpen=false
2014-11-27 02:54:04,397 INFO  [StoreOpener-9d75ee5afbcbc47cfa854a6a4143afee-1] compactions.CompactionConfiguration(93): size [134217728, 9223372036854775807); files [3, 10); ratio 1.200000; off-peak ratio 5.000000; throttle point 2560; major period 604800000, major jitter 0.500000
2014-11-27 02:54:04,399 DEBUG [StoreOpener-9d75ee5afbcbc47cfa854a6a4143afee-1] regionserver.HRegionFileSystem(197): No StoreFiles for: hdfs://localhost:48748/user/jenkins/hbase/data/default/testClusterStatus/9d75ee5afbcbc47cfa854a6a4143afee/cf
2014-11-27 02:54:04,400 DEBUG [RS_OPEN_REGION-asf910:55008-0] regionserver.HRegion(3383): Found 0 recovered edits file(s) under hdfs://localhost:48748/user/jenkins/hbase/data/default/testClusterStatus/9d75ee5afbcbc47cfa854a6a4143afee
2014-11-27 02:54:04,410 INFO  [RS_OPEN_REGION-asf910:55008-0] regionserver.HRegion(787): Onlined 9d75ee5afbcbc47cfa854a6a4143afee; next sequenceid=2
2014-11-27 02:54:04,411 INFO  [IPC Server handler 0 on 48748] blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:46969 is added to blk_1073741894_1070{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-61b4ee5f-784a-467f-831e-620705e0ff87:NORMAL|RBW], ReplicaUnderConstruction[[DISK]DS-ee034427-e712-4146-bf17-8a4bf7c8f6e2:NORMAL|RBW]]} size 0
2014-11-27 02:54:04,412 INFO  [IPC Server handler 3 on 48748] blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:58365 is added to blk_1073741894_1070 size 301
2014-11-27 02:54:04,412 INFO  [PostOpenDeployTasks:9d75ee5afbcbc47cfa854a6a4143afee] regionserver.HRegionServer(1794): Post open deploy tasks for testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,413 DEBUG [B.defaultRpcServer.handler=4,queue=0,port=41326] master.AssignmentManager(2735): Got transition OPENED for {9d75ee5afbcbc47cfa854a6a4143afee state=PENDING_OPEN, ts=1417056844384, server=asf910.gq1.ygridcore.net,55008,1417056807855} from asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:04,413 INFO  [B.defaultRpcServer.handler=4,queue=0,port=41326] master.RegionStates(973): Transition {9d75ee5afbcbc47cfa854a6a4143afee state=PENDING_OPEN, ts=1417056844384, server=asf910.gq1.ygridcore.net,55008,1417056807855} to {9d75ee5afbcbc47cfa854a6a4143afee state=OPEN, ts=1417056844413, server=asf910.gq1.ygridcore.net,55008,1417056807855}
2014-11-27 02:54:04,413 INFO  [B.defaultRpcServer.handler=4,queue=0,port=41326] master.RegionStateStore(207): Updating row testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee. with state=OPEN&openSeqNum=2&server=asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:04,414 DEBUG [MASTER_TABLE_OPERATIONS-asf910:41326-0] util.FSTableDescriptors(722): Wrote descriptor into: hdfs://localhost:48748/user/jenkins/hbase/data/default/testClusterStatus/.tabledesc/.tableinfo.0000000002
2014-11-27 02:54:04,416 INFO  [B.defaultRpcServer.handler=4,queue=0,port=41326] master.RegionStates(397): Onlined 9d75ee5afbcbc47cfa854a6a4143afee on asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:04,416 INFO  [IPC Server handler 2 on 48748] blockmanagement.BlockManager(1074): BLOCK* addToInvalidates: blk_1073741892_1068 127.0.0.1:46969 127.0.0.1:58365 
2014-11-27 02:54:04,416 DEBUG [PostOpenDeployTasks:9d75ee5afbcbc47cfa854a6a4143afee] regionserver.HRegionServer(1818): Finished post open deploy task for testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,416 DEBUG [MASTER_TABLE_OPERATIONS-asf910:41326-0] util.FSTableDescriptors(668): Deleted table descriptor at hdfs://localhost:48748/user/jenkins/hbase/data/default/testClusterStatus/.tabledesc/.tableinfo.0000000001
2014-11-27 02:54:04,416 DEBUG [RS_OPEN_REGION-asf910:55008-0] handler.OpenRegionHandler(122): Opened testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee. on asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:04,416 INFO  [MASTER_TABLE_OPERATIONS-asf910:41326-0] util.FSTableDescriptors(633): Updated tableinfo=hdfs://localhost:48748/user/jenkins/hbase/data/default/testClusterStatus/.tabledesc/.tableinfo.0000000002
2014-11-27 02:54:04,417 DEBUG [MASTER_TABLE_OPERATIONS-asf910:41326-0] master.TableStateManager(197): Table testClusterStatus written descriptor for state ENABLED
2014-11-27 02:54:04,417 DEBUG [MASTER_TABLE_OPERATIONS-asf910:41326-0] master.TableStateManager(199): Table testClusterStatus updated state to ENABLED
2014-11-27 02:54:04,420 DEBUG [MASTER_TABLE_OPERATIONS-asf910:41326-0] lock.ZKInterProcessLockBase(328): Released /hbase/table-lock/testClusterStatus/write-master:413260000000000
2014-11-27 02:54:04,420 INFO  [MASTER_TABLE_OPERATIONS-asf910:41326-0] handler.CreateTableHandler(177): Table, testClusterStatus, creation successful
2014-11-27 02:54:04,445 INFO  [main] hbase.Waiter(174): Waiting up to [60,000] milli-secs(wait.for.ratio=[1])
2014-11-27 02:54:04,455 INFO  [main] hbase.Waiter(174): Waiting up to [60,000] milli-secs(wait.for.ratio=[1])
2014-11-27 02:54:04,461 INFO  [B.defaultRpcServer.handler=0,queue=0,port=41326] master.HMaster(1139): Client=jenkins//67.195.81.154 move hri=testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee., src=asf910.gq1.ygridcore.net,55008,1417056807855, dest=asf910.gq1.ygridcore.net,40070,1417056844127, running balancer
2014-11-27 02:54:04,461 DEBUG [B.defaultRpcServer.handler=0,queue=0,port=41326] master.AssignmentManager(1291): Starting unassign of testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee. (offlining), current state: {9d75ee5afbcbc47cfa854a6a4143afee state=OPEN, ts=1417056844413, server=asf910.gq1.ygridcore.net,55008,1417056807855}
2014-11-27 02:54:04,461 INFO  [B.defaultRpcServer.handler=0,queue=0,port=41326] master.RegionStates(973): Transition {9d75ee5afbcbc47cfa854a6a4143afee state=OPEN, ts=1417056844413, server=asf910.gq1.ygridcore.net,55008,1417056807855} to {9d75ee5afbcbc47cfa854a6a4143afee state=PENDING_CLOSE, ts=1417056844461, server=asf910.gq1.ygridcore.net,55008,1417056807855}
2014-11-27 02:54:04,461 INFO  [B.defaultRpcServer.handler=0,queue=0,port=41326] master.RegionStateStore(207): Updating row testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee. with state=PENDING_CLOSE
2014-11-27 02:54:04,463 INFO  [PriorityRpcServer.handler=3,queue=0,port=55008] regionserver.RSRpcServices(994): Close 9d75ee5afbcbc47cfa854a6a4143afee, moving to asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,463 DEBUG [RS_CLOSE_REGION-asf910:55008-0] handler.CloseRegionHandler(90): Processing close of testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,463 DEBUG [B.defaultRpcServer.handler=0,queue=0,port=41326] master.AssignmentManager(863): Sent CLOSE to asf910.gq1.ygridcore.net,55008,1417056807855 for region testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,464 DEBUG [RS_CLOSE_REGION-asf910:55008-0] regionserver.HRegion(1195): Closing testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.: disabling compactions & flushes
2014-11-27 02:54:04,464 DEBUG [RS_CLOSE_REGION-asf910:55008-0] regionserver.HRegion(1222): Updates disabled for region testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,464 INFO  [StoreCloserThread-testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.-1] regionserver.HStore(830): Closed cf
2014-11-27 02:54:04,466 INFO  [RS_CLOSE_REGION-asf910:55008-0] regionserver.HRegion(1310): Closed testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,466 INFO  [RS_CLOSE_REGION-asf910:55008-0] regionserver.HRegionServer(2882): Adding moved region record: 9d75ee5afbcbc47cfa854a6a4143afee to asf910.gq1.ygridcore.net,40070,1417056844127 as of 2
2014-11-27 02:54:04,466 DEBUG [B.defaultRpcServer.handler=4,queue=0,port=41326] master.AssignmentManager(2735): Got transition CLOSED for {9d75ee5afbcbc47cfa854a6a4143afee state=PENDING_CLOSE, ts=1417056844461, server=asf910.gq1.ygridcore.net,55008,1417056807855} from asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:04,466 INFO  [B.defaultRpcServer.handler=4,queue=0,port=41326] master.RegionStates(973): Transition {9d75ee5afbcbc47cfa854a6a4143afee state=PENDING_CLOSE, ts=1417056844461, server=asf910.gq1.ygridcore.net,55008,1417056807855} to {9d75ee5afbcbc47cfa854a6a4143afee state=CLOSED, ts=1417056844466, server=asf910.gq1.ygridcore.net,55008,1417056807855}
2014-11-27 02:54:04,466 INFO  [B.defaultRpcServer.handler=4,queue=0,port=41326] master.RegionStateStore(207): Updating row testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee. with state=CLOSED
2014-11-27 02:54:04,468 DEBUG [AM.-pool119-t1] master.AssignmentManager(1199): Found an existing plan for testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee. destination server is asf910.gq1.ygridcore.net,40070,1417056844127 accepted as a dest server = true
2014-11-27 02:54:04,468 DEBUG [RS_CLOSE_REGION-asf910:55008-0] handler.CloseRegionHandler(122): Closed testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,468 DEBUG [AM.-pool119-t1] master.AssignmentManager(1239): Using pre-existing plan for testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.; plan=hri=testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee., src=asf910.gq1.ygridcore.net,55008,1417056807855, dest=asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,468 INFO  [AM.-pool119-t1] master.AssignmentManager(1019): Assigning testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee. to asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,468 INFO  [AM.-pool119-t1] master.RegionStates(973): Transition {9d75ee5afbcbc47cfa854a6a4143afee state=CLOSED, ts=1417056844466, server=asf910.gq1.ygridcore.net,55008,1417056807855} to {9d75ee5afbcbc47cfa854a6a4143afee state=PENDING_OPEN, ts=1417056844468, server=asf910.gq1.ygridcore.net,40070,1417056844127}
2014-11-27 02:54:04,468 INFO  [AM.-pool119-t1] master.RegionStateStore(207): Updating row testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee. with state=PENDING_OPEN&sn=asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,470 DEBUG [AM.-pool119-t1] master.ServerManager(827): New admin connection to asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,470 DEBUG [AM.-pool119-t1] ipc.RpcClient$Connection(565): Use SIMPLE authentication for service AdminService, sasl=false
2014-11-27 02:54:04,470 DEBUG [AM.-pool119-t1] ipc.RpcClient$Connection(931): Connecting to asf910.gq1.ygridcore.net/67.195.81.154:40070
2014-11-27 02:54:04,471 DEBUG [RpcServer.listener,port=40070] ipc.RpcServer$Listener(784): RpcServer.listener,port=40070: connection from 67.195.81.154:43435; # active connections: 1
2014-11-27 02:54:04,471 INFO  [PriorityRpcServer.handler=0,queue=0,port=40070] regionserver.RSRpcServices(1327): Open testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,476 DEBUG [RS_OPEN_REGION-asf910:40070-0] regionserver.HRegion(4758): Opening region: {ENCODED => 9d75ee5afbcbc47cfa854a6a4143afee, NAME => 'testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.', STARTKEY => '', ENDKEY => ''}
2014-11-27 02:54:04,477 DEBUG [RS_OPEN_REGION-asf910:40070-0] regionserver.MetricsRegionSourceImpl(67): Creating new MetricsRegionSourceImpl for table testClusterStatus 9d75ee5afbcbc47cfa854a6a4143afee
2014-11-27 02:54:04,477 DEBUG [RS_OPEN_REGION-asf910:40070-0] regionserver.HRegion(677): Instantiated testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,479 INFO  [StoreOpener-9d75ee5afbcbc47cfa854a6a4143afee-1] hfile.CacheConfig(260): blockCache=LruBlockCache{blockCount=5, currentSize=442896, freeSize=707948848, maxSize=708391744, heapSize=442896, minSize=672972160, minFactor=0.95, multiSize=336486080, multiFactor=0.5, singleSize=168243040, singleFactor=0.25}, cacheDataOnRead=true, cacheDataOnWrite=false, cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false, cacheDataCompressed=false, prefetchOnOpen=false
2014-11-27 02:54:04,480 INFO  [StoreOpener-9d75ee5afbcbc47cfa854a6a4143afee-1] compactions.CompactionConfiguration(93): size [134217728, 9223372036854775807); files [3, 10); ratio 1.200000; off-peak ratio 5.000000; throttle point 2560; major period 604800000, major jitter 0.500000
2014-11-27 02:54:04,481 DEBUG [StoreOpener-9d75ee5afbcbc47cfa854a6a4143afee-1] regionserver.HRegionFileSystem(197): No StoreFiles for: hdfs://localhost:48748/user/jenkins/hbase/data/default/testClusterStatus/9d75ee5afbcbc47cfa854a6a4143afee/cf
2014-11-27 02:54:04,483 DEBUG [RS_OPEN_REGION-asf910:40070-0] regionserver.HRegion(3383): Found 0 recovered edits file(s) under hdfs://localhost:48748/user/jenkins/hbase/data/default/testClusterStatus/9d75ee5afbcbc47cfa854a6a4143afee
2014-11-27 02:54:04,485 INFO  [RS_OPEN_REGION-asf910:40070-0] regionserver.HRegion(787): Onlined 9d75ee5afbcbc47cfa854a6a4143afee; next sequenceid=2
2014-11-27 02:54:04,488 INFO  [PostOpenDeployTasks:9d75ee5afbcbc47cfa854a6a4143afee] regionserver.HRegionServer(1794): Post open deploy tasks for testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,489 DEBUG [B.defaultRpcServer.handler=2,queue=0,port=41326] master.AssignmentManager(2735): Got transition OPENED for {9d75ee5afbcbc47cfa854a6a4143afee state=PENDING_OPEN, ts=1417056844468, server=asf910.gq1.ygridcore.net,40070,1417056844127} from asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,489 INFO  [B.defaultRpcServer.handler=2,queue=0,port=41326] master.RegionStates(973): Transition {9d75ee5afbcbc47cfa854a6a4143afee state=PENDING_OPEN, ts=1417056844468, server=asf910.gq1.ygridcore.net,40070,1417056844127} to {9d75ee5afbcbc47cfa854a6a4143afee state=OPEN, ts=1417056844489, server=asf910.gq1.ygridcore.net,40070,1417056844127}
2014-11-27 02:54:04,489 INFO  [B.defaultRpcServer.handler=2,queue=0,port=41326] master.RegionStateStore(207): Updating row testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee. with state=OPEN&openSeqNum=2&server=asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,491 INFO  [B.defaultRpcServer.handler=2,queue=0,port=41326] master.RegionStates(397): Onlined 9d75ee5afbcbc47cfa854a6a4143afee on asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,492 INFO  [B.defaultRpcServer.handler=2,queue=0,port=41326] master.RegionStates(404): Offlined 9d75ee5afbcbc47cfa854a6a4143afee from asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:04,492 DEBUG [PostOpenDeployTasks:9d75ee5afbcbc47cfa854a6a4143afee] regionserver.HRegionServer(1818): Finished post open deploy task for testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,493 DEBUG [RS_OPEN_REGION-asf910:40070-0] handler.OpenRegionHandler(122): Opened testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee. on asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,499 DEBUG [main] ipc.RpcClient$Connection(565): Use SIMPLE authentication for service AdminService, sasl=false
2014-11-27 02:54:04,499 DEBUG [main] ipc.RpcClient$Connection(931): Connecting to asf910.gq1.ygridcore.net/67.195.81.154:40070
2014-11-27 02:54:04,500 DEBUG [RpcServer.listener,port=40070] ipc.RpcServer$Listener(784): RpcServer.listener,port=40070: connection from 67.195.81.154:43436; # active connections: 2
2014-11-27 02:54:04,509 DEBUG [hconnection-0x6655f9-shared--pool35-t12] ipc.RpcClient$Connection(565): Use SIMPLE authentication for service ClientService, sasl=false
2014-11-27 02:54:04,509 DEBUG [hconnection-0x6655f9-shared--pool35-t12] ipc.RpcClient$Connection(931): Connecting to asf910.gq1.ygridcore.net/67.195.81.154:40070
2014-11-27 02:54:04,510 DEBUG [RpcServer.listener,port=40070] ipc.RpcServer$Listener(784): RpcServer.listener,port=40070: connection from 67.195.81.154:43437; # active connections: 3
2014-11-27 02:54:04,513 FATAL [main] regionserver.HRegionServer(1918): ABORTING region server asf910.gq1.ygridcore.net,40070,1417056844127: I'm dead
2014-11-27 02:54:04,514 FATAL [main] regionserver.HRegionServer(1924): RegionServer abort: loaded coprocessors are: [org.apache.hadoop.hbase.client.TestHCM$SleepAndFailFirstTime, org.apache.hadoop.hbase.coprocessor.MultiRowMutationEndpoint]
2014-11-27 02:54:04,520 ERROR [B.defaultRpcServer.handler=1,queue=0,port=41326] master.MasterRpcServices(332): Region server asf910.gq1.ygridcore.net,40070,1417056844127 reported a fatal error:
ABORTING region server asf910.gq1.ygridcore.net,40070,1417056844127: I'm dead
2014-11-27 02:54:04,523 INFO  [main] regionserver.HRegionServer(1768): STOPPED: I'm dead
2014-11-27 02:54:04,523 INFO  [RS:2;asf910:40070] regionserver.SplitLogWorker(165): Sending interrupt to stop the worker thread
2014-11-27 02:54:04,523 INFO  [RS:2;asf910:40070] regionserver.HRegionServer(903): Stopping infoServer
2014-11-27 02:54:04,523 INFO  [SplitLogWorker-asf910:40070] regionserver.SplitLogWorker(147): SplitLogWorker interrupted. Exiting. 
2014-11-27 02:54:04,524 INFO  [SplitLogWorker-asf910:40070] regionserver.SplitLogWorker(156): SplitLogWorker asf910.gq1.ygridcore.net,40070,1417056844127 exiting
2014-11-27 02:54:04,524 INFO  [main] hbase.Waiter(174): Waiting up to [40,000] milli-secs(wait.for.ratio=[1])
2014-11-27 02:54:04,529 INFO  [RS:2;asf910:40070] log.Slf4jLog(67): Stopped SelectChannelConnector@0.0.0.0:0
2014-11-27 02:54:04,632 INFO  [RS:2;asf910:40070] snapshot.RegionServerSnapshotManager(136): Stopping RegionServerSnapshotManager abruptly.
2014-11-27 02:54:04,632 INFO  [regionserver/asf910.gq1.ygridcore.net/67.195.81.154:0.compactionChecker] hbase.Chore(100): regionserver/asf910.gq1.ygridcore.net/67.195.81.154:0.compactionChecker exiting
2014-11-27 02:54:04,632 INFO  [MemStoreFlusher.0] regionserver.MemStoreFlusher$FlushHandler(246): MemStoreFlusher.0 exiting
2014-11-27 02:54:04,632 INFO  [RS:2;asf910:40070] flush.RegionServerFlushTableProcedureManager(113): Stopping region server flush procedure manager abruptly.
2014-11-27 02:54:04,632 INFO  [regionserver/asf910.gq1.ygridcore.net/67.195.81.154:0.nonceCleaner] hbase.Chore(100): regionserver/asf910.gq1.ygridcore.net/67.195.81.154:0.nonceCleaner exiting
2014-11-27 02:54:04,632 INFO  [MemStoreFlusher.1] regionserver.MemStoreFlusher$FlushHandler(246): MemStoreFlusher.1 exiting
2014-11-27 02:54:04,633 INFO  [RS:2;asf910:40070] regionserver.HRegionServer(952): aborting server asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,633 DEBUG [RS:2;asf910:40070] zookeeper.MetaTableLocator(456): Stopping MetaTableLocator
2014-11-27 02:54:04,633 INFO  [RS:2;asf910:40070] client.ConnectionManager$HConnectionImplementation(1668): Closing zookeeper sessionid=0x149ef29bd7d0029
2014-11-27 02:54:04,634 DEBUG [RS_CLOSE_REGION-asf910:40070-0] handler.CloseRegionHandler(90): Processing close of testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,634 DEBUG [RS:2;asf910:40070] ipc.RpcClient(1436): Stopping rpc client
2014-11-27 02:54:04,634 INFO  [RS:2;asf910:40070] regionserver.HRegionServer(1162): Waiting on 1 regions to close
2014-11-27 02:54:04,635 DEBUG [RS:2;asf910:40070] regionserver.HRegionServer(1166): {9d75ee5afbcbc47cfa854a6a4143afee=testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.}
2014-11-27 02:54:04,636 DEBUG [RS_CLOSE_REGION-asf910:40070-0] regionserver.HRegion(1195): Closing testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.: disabling compactions & flushes
2014-11-27 02:54:04,638 DEBUG [RS_CLOSE_REGION-asf910:40070-0] regionserver.HRegion(1222): Updates disabled for region testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,638 INFO  [StoreCloserThread-testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.-1] regionserver.HStore(830): Closed cf
2014-11-27 02:54:04,638 ERROR [RS_CLOSE_REGION-asf910:40070-0] regionserver.HRegion(1298): Memstore size is 120
2014-11-27 02:54:04,638 INFO  [RS_CLOSE_REGION-asf910:40070-0] regionserver.HRegion(1310): Closed testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,639 DEBUG [RS_CLOSE_REGION-asf910:40070-0] handler.CloseRegionHandler(122): Closed testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:04,837 INFO  [RS:2;asf910:40070] regionserver.HRegionServer(983): stopping server asf910.gq1.ygridcore.net,40070,1417056844127; all regions closed.
2014-11-27 02:54:04,837 DEBUG [RS:2;asf910:40070] wal.FSHLog(1116): Closing WAL writer in /user/jenkins/hbase/WALs/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:04,842 INFO  [IPC Server handler 2 on 48748] blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:58365 is added to blk_1073741891_1067{blockUCState=UNDER_CONSTRUCTION, primaryNodeIndex=-1, replicas=[ReplicaUnderConstruction[[DISK]DS-48736bec-0a55-493d-bd57-d06dff81996b:NORMAL|RBW], ReplicaUnderConstruction[[DISK]DS-b34f3e46-e307-495a-bfea-28dcd03ad0c9:NORMAL|RBW]]} size 83
2014-11-27 02:54:04,843 INFO  [IPC Server handler 5 on 48748] blockmanagement.BlockManager(2383): BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:46969 is added to blk_1073741891_1067 size 417
2014-11-27 02:54:04,843 DEBUG [RS:2;asf910:40070] ipc.RpcClient(1436): Stopping rpc client
2014-11-27 02:54:04,843 DEBUG [RpcServer.reader=4,port=41326] ipc.RpcServer$Listener(816): RpcServer.listener,port=41326: DISCONNECTING client 67.195.81.154:59287 because read count=-1. Number of active connections: 7
2014-11-27 02:54:04,943 INFO  [RS:2;asf910:40070] regionserver.Leases(146): RS:2;asf910:40070 closing leases
2014-11-27 02:54:04,944 INFO  [RS:2;asf910:40070] regionserver.Leases(149): RS:2;asf910:40070 closed leases
2014-11-27 02:54:05,258 INFO  [regionserver/asf910.gq1.ygridcore.net/67.195.81.154:0.logRoller] regionserver.LogRoller(156): LogRoller exiting.
2014-11-27 02:54:05,259 INFO  [regionserver/asf910.gq1.ygridcore.net/67.195.81.154:0.periodicFlusher] hbase.Chore(100): regionserver/asf910.gq1.ygridcore.net/67.195.81.154:0.periodicFlusher exiting
2014-11-27 02:54:05,259 INFO  [RS:2;asf910:40070] regionserver.CompactSplitThread(380): Waiting for Split Thread to finish...
2014-11-27 02:54:05,259 INFO  [regionserver/asf910.gq1.ygridcore.net/67.195.81.154:0.leaseChecker] regionserver.Leases(146): regionserver/asf910.gq1.ygridcore.net/67.195.81.154:0.leaseChecker closing leases
2014-11-27 02:54:05,259 INFO  [RS:2;asf910:40070] regionserver.CompactSplitThread(380): Waiting for Merge Thread to finish...
2014-11-27 02:54:05,259 INFO  [regionserver/asf910.gq1.ygridcore.net/67.195.81.154:0.leaseChecker] regionserver.Leases(149): regionserver/asf910.gq1.ygridcore.net/67.195.81.154:0.leaseChecker closed leases
2014-11-27 02:54:05,259 INFO  [RS:2;asf910:40070] regionserver.CompactSplitThread(380): Waiting for Large Compaction Thread to finish...
2014-11-27 02:54:05,259 INFO  [RS:2;asf910:40070] regionserver.CompactSplitThread(380): Waiting for Small Compaction Thread to finish...
2014-11-27 02:54:05,262 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:40070-0x149ef29bd7d0028, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/replication/rs/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:05,262 INFO  [RS:2;asf910:40070] client.ConnectionManager$HConnectionImplementation(1668): Closing zookeeper sessionid=0x149ef29bd7d002a
2014-11-27 02:54:05,263 DEBUG [RS:2;asf910:40070] ipc.RpcClient(1436): Stopping rpc client
2014-11-27 02:54:05,264 INFO  [RS:2;asf910:40070] ipc.RpcServer(2126): Stopping server on 40070
2014-11-27 02:54:05,264 INFO  [RpcServer.listener,port=40070] ipc.RpcServer$Listener(720): RpcServer.listener,port=40070: stopping
2014-11-27 02:54:05,265 INFO  [RpcServer.responder] ipc.RpcServer$Responder(962): RpcServer.responder: stopped
2014-11-27 02:54:05,266 INFO  [RpcServer.responder] ipc.RpcServer$Responder(865): RpcServer.responder: stopping
2014-11-27 02:54:05,268 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:40070-0x149ef29bd7d0028, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/rs/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:05,268 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/rs/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:05,268 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:40070-0x149ef29bd7d0028, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/rs
2014-11-27 02:54:05,268 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:39158-0x149ef29bd7d001a, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/rs/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:05,268 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/rs/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:05,269 INFO  [Thread-510-EventThread] zookeeper.RegionServerTracker(119): RegionServer ephemeral node deleted, processing expiration [asf910.gq1.ygridcore.net,40070,1417056844127]
2014-11-27 02:54:05,270 DEBUG [Thread-510-EventThread] master.AssignmentManager(1975): based on AM, current region=hbase:meta,,1.1588230740 is on server=asf910.gq1.ygridcore.net,41326,1417056807779, server being checked: asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:05,270 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:05,271 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:39158-0x149ef29bd7d001a, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:05,271 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,39158,1417056807975
2014-11-27 02:54:05,271 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:39158-0x149ef29bd7d001a, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,39158,1417056807975
2014-11-27 02:54:05,271 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:05,272 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:39158-0x149ef29bd7d001a, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:05,272 INFO  [Thread-510-EventThread] replication.ReplicationTrackerZKImpl$OtherRegionServerWatcher(121): /hbase/rs/asf910.gq1.ygridcore.net,40070,1417056844127 znode expired, triggering replicatorRemoved event
2014-11-27 02:54:05,272 INFO  [Thread-510-EventThread] replication.ReplicationTrackerZKImpl$OtherRegionServerWatcher(121): /hbase/rs/asf910.gq1.ygridcore.net,40070,1417056844127 znode expired, triggering replicatorRemoved event
2014-11-27 02:54:05,274 INFO  [RS:2;asf910:40070] regionserver.HRegionServer(1027): stopping server asf910.gq1.ygridcore.net,40070,1417056844127; zookeeper connection closed.
2014-11-27 02:54:05,274 INFO  [RS:2;asf910:40070] regionserver.HRegionServer(1030): RS:2;asf910:40070 exiting
2014-11-27 02:54:05,274 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/rs
2014-11-27 02:54:05,274 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:39158-0x149ef29bd7d001a, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/rs
2014-11-27 02:54:05,275 INFO  [Shutdown of org.apache.hadoop.hbase.fs.HFileSystem@7d1620] hbase.MiniHBaseCluster$SingleFileSystemShutdownThread(190): Hook closing fs=org.apache.hadoop.hbase.fs.HFileSystem@7d1620
2014-11-27 02:54:05,274 DEBUG [Thread-510-EventThread] master.ServerManager(579): Added=asf910.gq1.ygridcore.net,40070,1417056844127 to dead servers, submitted shutdown handler to be executed meta=false
2014-11-27 02:54:05,279 INFO  [MASTER_SERVER_OPERATIONS-asf910:41326-0] handler.ServerShutdownHandler(185): Mark regions in recovery for crashed server asf910.gq1.ygridcore.net,40070,1417056844127 before assignment; regions=[{ENCODED => 9d75ee5afbcbc47cfa854a6a4143afee, NAME => 'testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.', STARTKEY => '', ENDKEY => ''}]
2014-11-27 02:54:05,280 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:39158-0x149ef29bd7d001a, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:05,278 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:05,281 DEBUG [MASTER_SERVER_OPERATIONS-asf910:41326-0] zookeeper.ZKUtil(683): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Unable to get data of znode /hbase/recovering-regions/9d75ee5afbcbc47cfa854a6a4143afee because node does not exist (not an error)
2014-11-27 02:54:05,281 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,39158,1417056807975
2014-11-27 02:54:05,281 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:39158-0x149ef29bd7d001a, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,39158,1417056807975
2014-11-27 02:54:05,282 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:05,282 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:05,282 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): regionserver:39158-0x149ef29bd7d001a, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:05,282 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,39158,1417056807975
2014-11-27 02:54:05,283 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:05,283 INFO  [Thread-510-EventThread] replication.ReplicationTrackerZKImpl$OtherRegionServerWatcher(121): /hbase/rs/asf910.gq1.ygridcore.net,40070,1417056844127 znode expired, triggering replicatorRemoved event
2014-11-27 02:54:05,283 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/rs
2014-11-27 02:54:05,284 DEBUG [MASTER_SERVER_OPERATIONS-asf910:41326-0] coordination.ZKSplitLogManagerCoordination(651): Marked 9d75ee5afbcbc47cfa854a6a4143afee as recovering from asf910.gq1.ygridcore.net,40070,1417056844127: /hbase/recovering-regions/9d75ee5afbcbc47cfa854a6a4143afee/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:05,285 DEBUG [MASTER_SERVER_OPERATIONS-asf910:41326-0] master.RegionStates(464): Adding to processed servers asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:05,285 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:05,285 INFO  [MASTER_SERVER_OPERATIONS-asf910:41326-0] master.RegionStates(973): Transition {9d75ee5afbcbc47cfa854a6a4143afee state=OPEN, ts=1417056844489, server=asf910.gq1.ygridcore.net,40070,1417056844127} to {9d75ee5afbcbc47cfa854a6a4143afee state=OFFLINE, ts=1417056845285, server=asf910.gq1.ygridcore.net,40070,1417056844127}
2014-11-27 02:54:05,285 INFO  [MASTER_SERVER_OPERATIONS-asf910:41326-0] master.RegionStateStore(207): Updating row testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee. with state=OFFLINE
2014-11-27 02:54:05,285 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,39158,1417056807975
2014-11-27 02:54:05,286 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:05,287 INFO  [MASTER_SERVER_OPERATIONS-asf910:41326-0] handler.ServerShutdownHandler(207): Reassigning 1 region(s) that asf910.gq1.ygridcore.net,40070,1417056844127 was carrying (and 0 regions(s) that were opening on this server)
2014-11-27 02:54:05,287 DEBUG [Thread-510-EventThread] zookeeper.RegionServerTracker(94): Added tracking of RS /hbase/rs/asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:05,287 INFO  [MASTER_SERVER_OPERATIONS-asf910:41326-0] master.AssignmentManager(1473): Bulk assigning 1 region(s) across 3 server(s), round-robin=true
2014-11-27 02:54:05,287 DEBUG [Thread-510-EventThread] zookeeper.RegionServerTracker(94): Added tracking of RS /hbase/rs/asf910.gq1.ygridcore.net,39158,1417056807975
2014-11-27 02:54:05,288 DEBUG [Thread-510-EventThread] zookeeper.RegionServerTracker(94): Added tracking of RS /hbase/rs/asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:05,288 INFO  [asf910.gq1.ygridcore.net,41326,1417056807779-GeneralBulkAssigner-2] master.AssignmentManager(671): Assigning 1 region(s) to asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:05,288 DEBUG [MASTER_SERVER_OPERATIONS-asf910:41326-0] master.GeneralBulkAssigner(177): Timeout-on-RIT=151000
2014-11-27 02:54:05,288 INFO  [asf910.gq1.ygridcore.net,41326,1417056807779-GeneralBulkAssigner-2] master.RegionStates(973): Transition {9d75ee5afbcbc47cfa854a6a4143afee state=OFFLINE, ts=1417056845285, server=asf910.gq1.ygridcore.net,40070,1417056844127} to {9d75ee5afbcbc47cfa854a6a4143afee state=PENDING_OPEN, ts=1417056845288, server=asf910.gq1.ygridcore.net,55008,1417056807855}
2014-11-27 02:54:05,289 INFO  [asf910.gq1.ygridcore.net,41326,1417056807779-GeneralBulkAssigner-2] master.RegionStateStore(207): Updating row testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee. with state=PENDING_OPEN&sn=asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:05,289 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:05,289 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,39158,1417056807975
2014-11-27 02:54:05,290 DEBUG [Thread-510-EventThread] zookeeper.ZKUtil(424): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Set watcher on existing znode=/hbase/rs/asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:05,290 INFO  [PriorityRpcServer.handler=4,queue=0,port=55008] regionserver.RSRpcServices(1327): Open testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:05,295 DEBUG [asf910.gq1.ygridcore.net,41326,1417056807779-GeneralBulkAssigner-2] master.AssignmentManager(830): Bulk assigning done for asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:05,295 DEBUG [RS_OPEN_REGION-asf910:55008-1] regionserver.HRegion(4758): Opening region: {ENCODED => 9d75ee5afbcbc47cfa854a6a4143afee, NAME => 'testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.', STARTKEY => '', ENDKEY => ''}
2014-11-27 02:54:05,296 DEBUG [MASTER_SERVER_OPERATIONS-asf910:41326-0] master.GeneralBulkAssigner(153): bulk assigning total 1 regions to 3 servers, took 7ms, with 1 regions still in transition
2014-11-27 02:54:05,296 INFO  [MASTER_SERVER_OPERATIONS-asf910:41326-0] master.AssignmentManager(1480): Bulk assigning done
2014-11-27 02:54:05,296 INFO  [MASTER_SERVER_OPERATIONS-asf910:41326-0] master.AssignmentManager(1929): Waiting for 9d75ee5afbcbc47cfa854a6a4143afee to leave regions-in-transition, timeOut=15000 ms.
2014-11-27 02:54:05,296 DEBUG [RS_OPEN_REGION-asf910:55008-1] regionserver.MetricsRegionSourceImpl(67): Creating new MetricsRegionSourceImpl for table testClusterStatus 9d75ee5afbcbc47cfa854a6a4143afee
2014-11-27 02:54:05,296 DEBUG [RS_OPEN_REGION-asf910:55008-1] regionserver.HRegion(677): Instantiated testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:05,299 INFO  [StoreOpener-9d75ee5afbcbc47cfa854a6a4143afee-1] hfile.CacheConfig(260): blockCache=LruBlockCache{blockCount=5, currentSize=442896, freeSize=707948848, maxSize=708391744, heapSize=442896, minSize=672972160, minFactor=0.95, multiSize=336486080, multiFactor=0.5, singleSize=168243040, singleFactor=0.25}, cacheDataOnRead=true, cacheDataOnWrite=false, cacheIndexesOnWrite=false, cacheBloomsOnWrite=false, cacheEvictOnClose=false, cacheDataCompressed=false, prefetchOnOpen=false
2014-11-27 02:54:05,299 INFO  [StoreOpener-9d75ee5afbcbc47cfa854a6a4143afee-1] compactions.CompactionConfiguration(93): size [134217728, 9223372036854775807); files [3, 10); ratio 1.200000; off-peak ratio 5.000000; throttle point 2560; major period 604800000, major jitter 0.500000
2014-11-27 02:54:05,300 DEBUG [StoreOpener-9d75ee5afbcbc47cfa854a6a4143afee-1] regionserver.HRegionFileSystem(197): No StoreFiles for: hdfs://localhost:48748/user/jenkins/hbase/data/default/testClusterStatus/9d75ee5afbcbc47cfa854a6a4143afee/cf
2014-11-27 02:54:05,301 DEBUG [RS_OPEN_REGION-asf910:55008-1] regionserver.HRegion(3383): Found 0 recovered edits file(s) under hdfs://localhost:48748/user/jenkins/hbase/data/default/testClusterStatus/9d75ee5afbcbc47cfa854a6a4143afee
2014-11-27 02:54:05,307 INFO  [RS_OPEN_REGION-asf910:55008-1] regionserver.HRegion(787): Onlined 9d75ee5afbcbc47cfa854a6a4143afee; next sequenceid=40000002
2014-11-27 02:54:05,309 INFO  [PostOpenDeployTasks:9d75ee5afbcbc47cfa854a6a4143afee] regionserver.HRegionServer(1794): Post open deploy tasks for testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:05,312 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/recovering-regions/9d75ee5afbcbc47cfa854a6a4143afee
2014-11-27 02:54:05,314 DEBUG [PostOpenDeployTasks:9d75ee5afbcbc47cfa854a6a4143afee] regionserver.HRegionServer(3024): Update last flushed sequence id of region 9d75ee5afbcbc47cfa854a6a4143afee for asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:05,314 DEBUG [B.defaultRpcServer.handler=4,queue=0,port=41326] master.AssignmentManager(2735): Got transition OPENED for {9d75ee5afbcbc47cfa854a6a4143afee state=PENDING_OPEN, ts=1417056845288, server=asf910.gq1.ygridcore.net,55008,1417056807855} from asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:05,314 INFO  [B.defaultRpcServer.handler=4,queue=0,port=41326] master.RegionStates(973): Transition {9d75ee5afbcbc47cfa854a6a4143afee state=PENDING_OPEN, ts=1417056845288, server=asf910.gq1.ygridcore.net,55008,1417056807855} to {9d75ee5afbcbc47cfa854a6a4143afee state=OPEN, ts=1417056845314, server=asf910.gq1.ygridcore.net,55008,1417056807855}
2014-11-27 02:54:05,314 INFO  [B.defaultRpcServer.handler=4,queue=0,port=41326] master.RegionStateStore(207): Updating row testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee. with state=OPEN&openSeqNum=40000002&server=asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:05,316 INFO  [B.defaultRpcServer.handler=4,queue=0,port=41326] master.RegionStates(397): Onlined 9d75ee5afbcbc47cfa854a6a4143afee on asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:05,316 INFO  [B.defaultRpcServer.handler=4,queue=0,port=41326] master.RegionStates(404): Offlined 9d75ee5afbcbc47cfa854a6a4143afee from asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:05,316 DEBUG [PostOpenDeployTasks:9d75ee5afbcbc47cfa854a6a4143afee] regionserver.HRegionServer(1818): Finished post open deploy task for testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee.
2014-11-27 02:54:05,317 DEBUG [MASTER_SERVER_OPERATIONS-asf910:41326-0] master.DeadServer(118): Finished processing asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:05,317 DEBUG [RS_OPEN_REGION-asf910:55008-1] handler.OpenRegionHandler(122): Opened testClusterStatus,,1417056844327.9d75ee5afbcbc47cfa854a6a4143afee. on asf910.gq1.ygridcore.net,55008,1417056807855
2014-11-27 02:54:05,320 DEBUG [M_LOG_REPLAY_OPS-asf910:41326-0] master.MasterFileSystem(327): Renamed region directory: hdfs://localhost:48748/user/jenkins/hbase/WALs/asf910.gq1.ygridcore.net,40070,1417056844127-splitting
2014-11-27 02:54:05,320 INFO  [M_LOG_REPLAY_OPS-asf910:41326-0] master.SplitLogManager(556): dead splitlog workers [asf910.gq1.ygridcore.net,40070,1417056844127]
2014-11-27 02:54:05,322 DEBUG [M_LOG_REPLAY_OPS-asf910:41326-0] master.SplitLogManager(253): Scheduling batch of logs to split
2014-11-27 02:54:05,322 INFO  [M_LOG_REPLAY_OPS-asf910:41326-0] master.SplitLogManager(255): started splitting 1 logs in [hdfs://localhost:48748/user/jenkins/hbase/WALs/asf910.gq1.ygridcore.net,40070,1417056844127-splitting] for [asf910.gq1.ygridcore.net,40070,1417056844127]
2014-11-27 02:54:05,332 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:39158-0x149ef29bd7d001a, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL
2014-11-27 02:54:05,332 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL
2014-11-27 02:54:05,333 DEBUG [Thread-510-EventThread] coordination.ZkSplitLogWorkerCoordination(107): tasks arrived or departed
2014-11-27 02:54:05,332 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL
2014-11-27 02:54:05,333 DEBUG [Thread-510-EventThread] coordination.ZkSplitLogWorkerCoordination(107): tasks arrived or departed
2014-11-27 02:54:05,333 DEBUG [Thread-510-EventThread] coordination.ZkSplitLogWorkerCoordination(107): tasks arrived or departed
2014-11-27 02:54:05,337 DEBUG [Thread-510-EventThread] coordination.ZKSplitLogManagerCoordination(433): put up splitlog task at znode /hbase/splitWAL/WALs%2Fasf910.gq1.ygridcore.net%2C40070%2C1417056844127-splitting%2Fasf910.gq1.ygridcore.net%252C40070%252C1417056844127.default.1417056844240
2014-11-27 02:54:05,337 INFO  [SplitLogWorker-asf910:41326] coordination.ZkSplitLogWorkerCoordination(263): worker asf910.gq1.ygridcore.net,41326,1417056807779 acquired task /hbase/splitWAL/WALs%2Fasf910.gq1.ygridcore.net%2C40070%2C1417056844127-splitting%2Fasf910.gq1.ygridcore.net%252C40070%252C1417056844127.default.1417056844240
2014-11-27 02:54:05,339 INFO  [Thread-510-EventThread] coordination.ZKSplitLogManagerCoordination(561): task /hbase/splitWAL/WALs%2Fasf910.gq1.ygridcore.net%2C40070%2C1417056844127-splitting%2Fasf910.gq1.ygridcore.net%252C40070%252C1417056844127.default.1417056844240 acquired by asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:05,373 INFO  [RS_LOG_REPLAY_OPS-asf910:41326-0] wal.WALSplitter(291): Splitting wal: hdfs://localhost:48748/user/jenkins/hbase/WALs/asf910.gq1.ygridcore.net,40070,1417056844127-splitting/asf910.gq1.ygridcore.net%2C40070%2C1417056844127.default.1417056844240, length=417
2014-11-27 02:54:05,373 INFO  [RS_LOG_REPLAY_OPS-asf910:41326-0] wal.WALSplitter(292): DistributedLogReplay = true
2014-11-27 02:54:05,375 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/WALs%2Fasf910.gq1.ygridcore.net%2C40070%2C1417056844127-splitting%2Fasf910.gq1.ygridcore.net%252C40070%252C1417056844127.default.1417056844240
2014-11-27 02:54:05,376 INFO  [RS_LOG_REPLAY_OPS-asf910:41326-0] util.FSHDFSUtils(173): Recovering lease on dfs file hdfs://localhost:48748/user/jenkins/hbase/WALs/asf910.gq1.ygridcore.net,40070,1417056844127-splitting/asf910.gq1.ygridcore.net%2C40070%2C1417056844127.default.1417056844240
2014-11-27 02:54:05,383 INFO  [RS_LOG_REPLAY_OPS-asf910:41326-0] util.FSHDFSUtils(260): recoverLease=true, attempt=0 on file=hdfs://localhost:48748/user/jenkins/hbase/WALs/asf910.gq1.ygridcore.net,40070,1417056844127-splitting/asf910.gq1.ygridcore.net%2C40070%2C1417056844127.default.1417056844240 after 7ms
2014-11-27 02:54:05,390 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0] ipc.RpcClient$Connection(565): Use SIMPLE authentication for service MasterService, sasl=false
2014-11-27 02:54:05,390 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0] ipc.RpcClient$Connection(931): Connecting to asf910.gq1.ygridcore.net/67.195.81.154:41326
2014-11-27 02:54:05,391 DEBUG [RpcServer.listener,port=41326] ipc.RpcServer$Listener(784): RpcServer.listener,port=41326: connection from 67.195.81.154:35686; # active connections: 7
2014-11-27 02:54:05,403 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0-Writer-0] wal.WALSplitter$WriterThread(1051): Writer thread Thread[RS_LOG_REPLAY_OPS-asf910:41326-0-Writer-0,5,main]: starting
2014-11-27 02:54:05,403 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0-Writer-1] wal.WALSplitter$WriterThread(1051): Writer thread Thread[RS_LOG_REPLAY_OPS-asf910:41326-0-Writer-1,5,main]: starting
2014-11-27 02:54:05,403 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0-Writer-2] wal.WALSplitter$WriterThread(1051): Writer thread Thread[RS_LOG_REPLAY_OPS-asf910:41326-0-Writer-2,5,main]: starting
2014-11-27 02:54:05,407 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0] wal.WALSplitter(381): Finishing writing output logs and closing down.
2014-11-27 02:54:05,407 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0] wal.WALSplitter$OutputSink(1182): Waiting for split writer threads to finish
2014-11-27 02:54:05,408 INFO  [RS_LOG_REPLAY_OPS-asf910:41326-0-Writer-1] zookeeper.RecoverableZooKeeper(121): Process identifier=hconnection-0x5f69df connecting to ZooKeeper ensemble=localhost:59911
2014-11-27 02:54:05,411 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0-Writer-1-EventThread] zookeeper.ZooKeeperWatcher(304): hconnection-0x5f69df, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2014-11-27 02:54:05,412 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0-Writer-1] ipc.RpcClient(1331): Codec=org.apache.hadoop.hbase.regionserver.wal.WALCellCodec@5e89dc, compressor=null, tcpKeepAlive=true, tcpNoDelay=true, connectTO=10000, readTO=20000, writeTO=60000, minIdleTimeBeforeClose=120000, maxRetries=0, fallbackAllowed=true, bind address=null
2014-11-27 02:54:05,413 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0-Writer-1-EventThread] zookeeper.ZooKeeperWatcher(388): hconnection-0x5f69df-0x149ef29bd7d002b connected
2014-11-27 02:54:05,416 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0-Writer-1] ipc.RpcClient$Connection(565): Use SIMPLE authentication for service MasterService, sasl=false
2014-11-27 02:54:05,416 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0-Writer-1] ipc.RpcClient$Connection(931): Connecting to asf910.gq1.ygridcore.net/67.195.81.154:41326
2014-11-27 02:54:05,417 DEBUG [RpcServer.listener,port=41326] ipc.RpcServer$Listener(784): RpcServer.listener,port=41326: connection from 67.195.81.154:35689; # active connections: 8
2014-11-27 02:54:05,420 DEBUG [hconnection-0x5f69df-shared--pool180-t1] ipc.RpcClient$Connection(565): Use SIMPLE authentication for service ClientService, sasl=false
2014-11-27 02:54:05,421 DEBUG [hconnection-0x5f69df-shared--pool180-t1] ipc.RpcClient$Connection(931): Connecting to asf910.gq1.ygridcore.net/67.195.81.154:41326
2014-11-27 02:54:05,421 DEBUG [RpcServer.listener,port=41326] ipc.RpcServer$Listener(784): RpcServer.listener,port=41326: connection from 67.195.81.154:35690; # active connections: 9
2014-11-27 02:54:05,423 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0-Writer-1] ipc.RpcClient$Connection(565): Use SIMPLE authentication for service AdminService, sasl=false
2014-11-27 02:54:05,424 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0-Writer-1] ipc.RpcClient$Connection(931): Connecting to asf910.gq1.ygridcore.net/67.195.81.154:55008
2014-11-27 02:54:05,424 DEBUG [RpcServer.listener,port=55008] ipc.RpcServer$Listener(784): RpcServer.listener,port=55008: connection from 67.195.81.154:35352; # active connections: 2
2014-11-27 02:54:05,453 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0-Writer-1] wal.WALEditsReplaySink(144): number of rows:1 are sent by batch! spent 21(ms)!
2014-11-27 02:54:05,525 INFO  [main] hbase.Waiter(174): Waiting up to [40,000] milli-secs(wait.for.ratio=[1])
2014-11-27 02:54:05,887 INFO  [asf910.gq1.ygridcore.net,41326,1417056807779.splitLogManagerTimeoutMonitor] master.SplitLogManager$TimeoutMonitor(741): total tasks = 1 unassigned = 0 tasks={/hbase/splitWAL/WALs%2Fasf910.gq1.ygridcore.net%2C40070%2C1417056844127-splitting%2Fasf910.gq1.ygridcore.net%252C40070%252C1417056844127.default.1417056844240=last_update = 1417056845375 last_version = 2 cur_worker_name = asf910.gq1.ygridcore.net,41326,1417056807779 status = in_progress incarnation = 0 resubmits = 0 batch = installed = 1 done = 0 error = 0}
2014-11-27 02:54:05,954 INFO  [RS_LOG_REPLAY_OPS-asf910:41326-0] wal.WALSplitter$OutputSink(1200): Split writers finished
2014-11-27 02:54:05,955 INFO  [RS_LOG_REPLAY_OPS-asf910:41326-0] client.ConnectionManager$HConnectionImplementation(2046): Closing master protocol: MasterService
2014-11-27 02:54:05,955 INFO  [RS_LOG_REPLAY_OPS-asf910:41326-0] client.ConnectionManager$HConnectionImplementation(1668): Closing zookeeper sessionid=0x149ef29bd7d002b
2014-11-27 02:54:05,957 DEBUG [RS_LOG_REPLAY_OPS-asf910:41326-0] ipc.RpcClient(1436): Stopping rpc client
2014-11-27 02:54:05,957 DEBUG [RpcServer.reader=0,port=55008] ipc.RpcServer$Listener(816): RpcServer.listener,port=55008: DISCONNECTING client 67.195.81.154:35352 because read count=-1. Number of active connections: 2
2014-11-27 02:54:05,958 DEBUG [RpcServer.reader=7,port=41326] ipc.RpcServer$Listener(816): RpcServer.listener,port=41326: DISCONNECTING client 67.195.81.154:35690 because read count=-1. Number of active connections: 9
2014-11-27 02:54:05,957 DEBUG [RpcServer.reader=6,port=41326] ipc.RpcServer$Listener(816): RpcServer.listener,port=41326: DISCONNECTING client 67.195.81.154:35689 because read count=-1. Number of active connections: 9
2014-11-27 02:54:06,058 INFO  [RS_LOG_REPLAY_OPS-asf910:41326-0] wal.WALSplitter(402): Processed 2 edits across 1 regions; log file=hdfs://localhost:48748/user/jenkins/hbase/WALs/asf910.gq1.ygridcore.net,40070,1417056844127-splitting/asf910.gq1.ygridcore.net%2C40070%2C1417056844127.default.1417056844240 is corrupted = false progress failed = false
2014-11-27 02:54:06,061 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/WALs%2Fasf910.gq1.ygridcore.net%2C40070%2C1417056844127-splitting%2Fasf910.gq1.ygridcore.net%252C40070%252C1417056844127.default.1417056844240
2014-11-27 02:54:06,061 INFO  [RS_LOG_REPLAY_OPS-asf910:41326-0] coordination.ZkSplitLogWorkerCoordination(599): successfully transitioned task /hbase/splitWAL/WALs%2Fasf910.gq1.ygridcore.net%2C40070%2C1417056844127-splitting%2Fasf910.gq1.ygridcore.net%252C40070%252C1417056844127.default.1417056844240 to final state DONE asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:06,062 INFO  [RS_LOG_REPLAY_OPS-asf910:41326-0] handler.WALSplitterHandler(101): worker asf910.gq1.ygridcore.net,41326,1417056807779 done with task org.apache.hadoop.hbase.coordination.ZkSplitLogWorkerCoordination$ZkSplitTaskDetails@cb3932 in 721ms
2014-11-27 02:54:06,062 INFO  [Thread-510-EventThread] coordination.ZKSplitLogManagerCoordination(474): task /hbase/splitWAL/WALs%2Fasf910.gq1.ygridcore.net%2C40070%2C1417056844127-splitting%2Fasf910.gq1.ygridcore.net%252C40070%252C1417056844127.default.1417056844240 entered state: DONE asf910.gq1.ygridcore.net,41326,1417056807779
2014-11-27 02:54:06,069 INFO  [Thread-510-EventThread] wal.WALSplitter(492): Archived processed log hdfs://localhost:48748/user/jenkins/hbase/WALs/asf910.gq1.ygridcore.net,40070,1417056844127-splitting/asf910.gq1.ygridcore.net%2C40070%2C1417056844127.default.1417056844240 to hdfs://localhost:48748/user/jenkins/hbase/oldWALs/asf910.gq1.ygridcore.net%2C40070%2C1417056844127.default.1417056844240
2014-11-27 02:54:06,071 INFO  [Thread-510-EventThread] coordination.ZKSplitLogManagerCoordination(517): Done splitting /hbase/splitWAL/WALs%2Fasf910.gq1.ygridcore.net%2C40070%2C1417056844127-splitting%2Fasf910.gq1.ygridcore.net%252C40070%252C1417056844127.default.1417056844240
2014-11-27 02:54:06,072 DEBUG [M_LOG_REPLAY_OPS-asf910:41326-0] coordination.ZKSplitLogManagerCoordination(325): Processing recovering [9d75ee5afbcbc47cfa854a6a4143afee] and servers [asf910.gq1.ygridcore.net,40070,1417056844127], isMetaRecovery=false
2014-11-27 02:54:06,072 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL
2014-11-27 02:54:06,073 DEBUG [Thread-510-EventThread] coordination.ZkSplitLogWorkerCoordination(107): tasks arrived or departed
2014-11-27 02:54:06,072 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:39158-0x149ef29bd7d001a, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL
2014-11-27 02:54:06,073 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/splitWAL/WALs%2Fasf910.gq1.ygridcore.net%2C40070%2C1417056844127-splitting%2Fasf910.gq1.ygridcore.net%252C40070%252C1417056844127.default.1417056844240
2014-11-27 02:54:06,073 DEBUG [Thread-510-EventThread] coordination.ZkSplitLogWorkerCoordination(107): tasks arrived or departed
2014-11-27 02:54:06,073 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL
2014-11-27 02:54:06,073 DEBUG [Thread-510-EventThread] coordination.ZkSplitLogWorkerCoordination(107): tasks arrived or departed
2014-11-27 02:54:06,073 DEBUG [Thread-510-EventThread] coordination.ZKSplitLogManagerCoordination$DeleteAsyncCallback(1063): deleted /hbase/splitWAL/WALs%2Fasf910.gq1.ygridcore.net%2C40070%2C1417056844127-splitting%2Fasf910.gq1.ygridcore.net%252C40070%252C1417056844127.default.1417056844240
2014-11-27 02:54:06,075 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/recovering-regions/9d75ee5afbcbc47cfa854a6a4143afee/asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:06,076 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): regionserver:55008-0x149ef29bd7d0016, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/recovering-regions/9d75ee5afbcbc47cfa854a6a4143afee
2014-11-27 02:54:06,076 DEBUG [Thread-510-EventThread] zookeeper.ZooKeeperWatcher(304): master:41326-0x149ef29bd7d0015, quorum=localhost:59911, baseZNode=/hbase Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/recovering-regions/9d75ee5afbcbc47cfa854a6a4143afee
2014-11-27 02:54:06,076 INFO  [Thread-510-EventThread] zookeeper.RecoveringRegionWatcher(66): /hbase/recovering-regions/9d75ee5afbcbc47cfa854a6a4143afee deleted; 9d75ee5afbcbc47cfa854a6a4143afee recovered.
2014-11-27 02:54:06,076 INFO  [Thread-510-EventThread] zookeeper.RecoveringRegionWatcher(66): /hbase/recovering-regions/9d75ee5afbcbc47cfa854a6a4143afee deleted; 9d75ee5afbcbc47cfa854a6a4143afee recovered.
2014-11-27 02:54:06,078 INFO  [M_LOG_REPLAY_OPS-asf910:41326-0] master.SplitLogManager(314): finished splitting (more than or equal to) 417 bytes in 1 log files in [hdfs://localhost:48748/user/jenkins/hbase/WALs/asf910.gq1.ygridcore.net,40070,1417056844127-splitting] in 756ms
2014-11-27 02:54:06,079 DEBUG [M_LOG_REPLAY_OPS-asf910:41326-0] master.DeadServer(118): Finished processing asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:06,079 INFO  [M_LOG_REPLAY_OPS-asf910:41326-0] handler.LogReplayHandler(86): Finished processing shutdown of asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:07,823 DEBUG [HBase clusterStatusPublisher for master/asf910.gq1.ygridcore.net/67.195.81.154:0] master.ClusterStatusPublisher(220): ###add dead server asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:17,823 DEBUG [HBase clusterStatusPublisher for master/asf910.gq1.ygridcore.net/67.195.81.154:0] master.ClusterStatusPublisher(220): ###add dead server asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:20,889 DEBUG [asf910.gq1.ygridcore.net,41326,1417056807779.splitLogManagerTimeoutMonitor] zookeeper.ZKSplitLog(172): Garbage collecting all recovering region znodes
2014-11-27 02:54:27,823 DEBUG [HBase clusterStatusPublisher for master/asf910.gq1.ygridcore.net/67.195.81.154:0] master.ClusterStatusPublisher(220): ###add dead server asf910.gq1.ygridcore.net,40070,1417056844127
2014-11-27 02:54:37,823 DEBUG [HBase clusterStatusPublisher for master/asf910.gq1.ygridcore.net/67.195.81.154:0] master.ClusterStatusPublisher(220): ###add dead server asf910.gq1.ygridcore.net,40070,1417056844127
{code}

> TestHCM.testClusterStatus Unexpected exception, expected<org.apache.hadoop.hbase.regionserver.RegionServerStoppedException> but was<junit.framework.AssertionFailedError>
> -------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
>                 Key: HBASE-12558
>                 URL: https://issues.apache.org/jira/browse/HBASE-12558
>             Project: HBase
>          Issue Type: Bug
>          Components: test
>            Reporter: stack
>            Assignee: stack
>            Priority: Critical
>             Fix For: 2.0.0, 0.99.2
>
>         Attachments: 12558-master.patch, 12558.ignore.txt
>
>
> Happens for me reliably on mac os x. I looked at fixing it. The listener is not noticing the publish for whatever reason.  Thats where I stopped.
> {code}
> java.lang.Exception: Unexpected exception, expected<org.apache.hadoop.hbase.regionserver.RegionServerStoppedException> but was<junit.framework.AssertionFailedError>
> 	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:3537)
> 	at org.apache.hadoop.hbase.client.TestHCM.testClusterStatus(TestHCM.java:273)
> {code}



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message