[
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
[email protected]: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
[email protected]: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)
