hbase-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "nkeywal (Commented) (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (HBASE-4798) Sleeps and synchronisation improvements for tests
Date Wed, 16 Nov 2011 23:55:54 GMT

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

nkeywal commented on HBASE-4798:
--------------------------------

This said, when I look at the traces, it seems that it's something different that's going
on.
@stack; please just confirm that the cluster should be fully available even if root is corrupted.
I will then play with the debugger;

fyi, here are the logs:
{noformat}
2011-11-16 10:21:19,492 INFO  [main] client.HConnectionManager$HConnectionImplementation(1706):
Closed zookeeper sessionid=0x133ad9c76a60003
2011-11-16 10:21:19,494 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(238): master:58532-0x133ad9c76a60000
Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/master
2011-11-16 10:21:19,495 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(238): hconnection-0x133ad9c76a60003
Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/master
2011-11-16 10:21:19,497 INFO  [Master:0;localhost,58532,1321467672954] master.HMaster(336):
HMaster main thread exiting
2011-11-16 10:21:19,506 WARN  [main-EventThread] zookeeper.ZKUtil(234): hconnection-0x133ad9c76a60003
Unable to set watcher on znode /hbase/master
org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired
for /hbase/master
	at org.apache.zookeeper.KeeperException.create(KeeperException.java:118)
	at org.apache.zookeeper.KeeperException.create(KeeperException.java:42)
	at org.apache.zookeeper.ZooKeeper.exists(ZooKeeper.java:809)
	at org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.exists(RecoverableZooKeeper.java:154)
	at org.apache.hadoop.hbase.zookeeper.ZKUtil.watchAndCheckExists(ZKUtil.java:225)
	at org.apache.hadoop.hbase.zookeeper.ZooKeeperNodeTracker.nodeDeleted(ZooKeeperNodeTracker.java:182)
	at org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.process(ZooKeeperWatcher.java:262)
	at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:530)
	at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:506)
2011-11-16 10:21:19,506 ERROR [main-EventThread] zookeeper.ZooKeeperWatcher(363): hconnection-0x133ad9c76a60003
Received unexpected KeeperException, re-throwing exception
org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired
for /hbase/master
	at org.apache.zookeeper.KeeperException.create(KeeperException.java:118)
	at org.apache.zookeeper.KeeperException.create(KeeperException.java:42)
	at org.apache.zookeeper.ZooKeeper.exists(ZooKeeper.java:809)
	at org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.exists(RecoverableZooKeeper.java:154)
	at org.apache.hadoop.hbase.zookeeper.ZKUtil.watchAndCheckExists(ZKUtil.java:225)
	at org.apache.hadoop.hbase.zookeeper.ZooKeeperNodeTracker.nodeDeleted(ZooKeeperNodeTracker.java:182)
	at org.apache.hadoop.hbase.zookeeper.ZooKeeperWatcher.process(ZooKeeperWatcher.java:262)
	at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:530)
	at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:506)
2011-11-16 10:21:19,523 INFO  [main-EventThread] client.HConnectionManager$HConnectionImplementation(1624):
This client just lost it's session with ZooKeeper, trying to reconnect.
2011-11-16 10:21:19,523 INFO  [main-EventThread] client.HConnectionManager$HConnectionImplementation(541):
Trying to reconnect to zookeeper
2011-11-16 10:21:19,524 DEBUG [main-EventThread] zookeeper.ZKUtil(95): hconnection opening
connection to ZooKeeper with ensemble (localhost:56525)
2011-11-16 10:21:19,526 INFO  [main-EventThread] zookeeper.RecoverableZooKeeper(89): The identifier
of this process is 19557@ubuntu
2011-11-16 10:21:19,532 DEBUG [main] zookeeper.ZKUtil(95): Bad Root Location Writer opening
connection to ZooKeeper with ensemble (localhost:56525)
2011-11-16 10:21:19,533 INFO  [main] zookeeper.RecoverableZooKeeper(89): The identifier of
this process is 19557@ubuntu
2011-11-16 10:21:19,534 INFO  [main] catalog.RootLocationEditor(62): Setting ROOT region location
in ZooKeeper as example.org,1234,1321467679534
2011-11-16 10:21:19,536 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(238): hconnection
Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2011-11-16 10:21:19,537 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(238): Bad Root
Location Writer Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2011-11-16 10:21:19,537 DEBUG [main-EventThread] zookeeper.ZKUtil(230): hconnection /hbase/master
does not exist. Watcher is set.
2011-11-16 10:21:19,538 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(315): hconnection-0x133ad9c76a60004
connected
2011-11-16 10:21:19,539 ERROR [main] zookeeper.RecoverableZooKeeper(478): Node /hbase/root-region-server
already exists and this is not a retry
2011-11-16 10:21:19,539 DEBUG [main-EventThread] zookeeper.ZKUtil(228): hconnection-0x133ad9c76a60004
Set watcher on existing znode /hbase/root-region-server
2011-11-16 10:21:19,540 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(315): Bad Root
Location Writer-0x133ad9c76a60005 connected
2011-11-16 10:21:19,540 DEBUG [main] catalog.RootLocationEditor(67): ROOT region location
already existed, updated location
2011-11-16 10:21:19,540 DEBUG [main-EventThread] zookeeper.ZKUtil(1034): hconnection-0x133ad9c76a60004
Retrieved 29 byte(s) of data from znode /hbase/root-region-server and set watcher; localhost,44843,1321467673319
2011-11-16 10:21:19,540 INFO  [main-EventThread] client.HConnectionManager$HConnectionImplementation(1627):
Reconnected successfully. This disconnect could have been caused by a network partition or
a long-running GC pause, either way it's recommended that you verify your environment.
2011-11-16 10:21:19,542 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(238): hconnection-0x133ad9c76a60004
Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/root-region-server
2011-11-16 10:21:19,544 DEBUG [main-EventThread] zookeeper.ZKUtil(1034): hconnection-0x133ad9c76a60004
Retrieved 30 byte(s) of data from znode /hbase/root-region-server and set watcher; example.org,1234,1321467679534
2011-11-16 10:21:19,555 DEBUG [main] util.FSUtils(288): Created version file at hdfs://localhost:40123/user/nkeywal
set its version at:7
2011-11-16 10:21:19,568 DEBUG [main] client.HConnectionManager(1805): Set serverside HConnection
retries=100
2011-11-16 10:21:19,573 INFO  [main] ipc.HBaseRpcMetrics(59): Initializing RPC Metrics with
hostName=HMaster, port=50466
2011-11-16 10:21:19,582 DEBUG [main] zookeeper.ZKUtil(95): master:50466 opening connection
to ZooKeeper with ensemble (localhost:56525)
2011-11-16 10:21:19,584 INFO  [main] zookeeper.RecoverableZooKeeper(89): The identifier of
this process is 19557@ubuntu
2011-11-16 10:21:19,588 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(238): master:50466
Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2011-11-16 10:21:19,590 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(315): master:50466-0x133ad9c76a60006
connected
2011-11-16 10:21:19,592 INFO  [main] metrics.MetricsMBeanBase(111): new MBeanInfo
2011-11-16 10:21:19,592 INFO  [main] metrics.MasterMetrics(89): Initialized
2011-11-16 10:21:19,613 DEBUG [main] client.HConnectionManager(1805): Set serverside HConnection
retries=100
2011-11-16 10:21:19,619 INFO  [main] ipc.HBaseRpcMetrics(59): Initializing RPC Metrics with
hostName=MiniHBaseCluster$MiniHBaseClusterRegionServer, port=55575
2011-11-16 10:21:19,625 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(238): hconnection-0x133ad9c76a60004
Received ZooKeeper Event, type=NodeCreated, state=SyncConnected, path=/hbase/master
2011-11-16 10:21:19,625 INFO  [Master:0;localhost,50466,1321467679574] master.ActiveMasterManager(139):
Master=localhost,50466,1321467679574
2011-11-16 10:21:19,626 DEBUG [Master:0;localhost,50466,1321467679574] master.SplitLogManager(159):
timeout = 25000
2011-11-16 10:21:19,626 DEBUG [Master:0;localhost,50466,1321467679574] master.SplitLogManager(160):
unassigned timeout = 180000
2011-11-16 10:21:19,626 DEBUG [main-EventThread] zookeeper.ZKUtil(1034): hconnection-0x133ad9c76a60004
Retrieved 31 byte(s) of data from znode /hbase/master and set watcher; \x00\x00localhost,50466,13214...
2011-11-16 10:21:19,627 INFO  [Master:0;localhost,50466,1321467679574] master.SplitLogManager(684):
found 0 orphan tasks and 0 rescan nodes
2011-11-16 10:21:19,647 DEBUG [Master:0;localhost,50466,1321467679574] zookeeper.ZKUtil(95):
hconnection opening connection to ZooKeeper with ensemble (localhost:56525)
2011-11-16 10:21:19,648 INFO  [Master:0;localhost,50466,1321467679574] zookeeper.RecoverableZooKeeper(89):
The identifier of this process is 19557@ubuntu
2011-11-16 10:21:19,653 DEBUG [Master:0;localhost,50466,1321467679574-EventThread] zookeeper.ZooKeeperWatcher(238):
hconnection Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2011-11-16 10:21:19,653 DEBUG [Master:0;localhost,50466,1321467679574] zookeeper.ZKUtil(228):
hconnection Set watcher on existing znode /hbase/master
2011-11-16 10:21:19,654 DEBUG [Master:0;localhost,50466,1321467679574-EventThread] zookeeper.ZooKeeperWatcher(315):
hconnection-0x133ad9c76a60007 connected
2011-11-16 10:21:19,654 DEBUG [Master:0;localhost,50466,1321467679574] zookeeper.ZKUtil(1034):
hconnection-0x133ad9c76a60007 Retrieved 31 byte(s) of data from znode /hbase/master and set
watcher; \x00\x00localhost,50466,13214...
2011-11-16 10:21:19,655 DEBUG [Master:0;localhost,50466,1321467679574] zookeeper.ZKUtil(228):
hconnection-0x133ad9c76a60007 Set watcher on existing znode /hbase/root-region-server
2011-11-16 10:21:19,656 DEBUG [Master:0;localhost,50466,1321467679574] zookeeper.ZKUtil(1034):
hconnection-0x133ad9c76a60007 Retrieved 30 byte(s) of data from znode /hbase/root-region-server
and set watcher; example.org,1234,1321467679534
2011-11-16 10:21:19,656 DEBUG [Master:0;localhost,50466,1321467679574] catalog.CatalogTracker(217):
Starting catalog tracker org.apache.hadoop.hbase.catalog.CatalogTracker@2e18ff27
2011-11-16 10:21:19,657 DEBUG [Master:0;localhost,50466,1321467679574] zookeeper.ZKUtil(228):
master:50466-0x133ad9c76a60006 Set watcher on existing znode /hbase/root-region-server
2011-11-16 10:21:19,658 DEBUG [Master:0;localhost,50466,1321467679574] zookeeper.ZKUtil(1034):
master:50466-0x133ad9c76a60006 Retrieved 30 byte(s) of data from znode /hbase/root-region-server
and set watcher; example.org,1234,1321467679534
2011-11-16 10:21:19,658 DEBUG [Master:0;localhost,50466,1321467679574] zookeeper.ZKUtil(230):
master:50466-0x133ad9c76a60006 /hbase/unassigned/1028785192 does not exist. Watcher is set.
2011-11-16 10:21:19,660 DEBUG [Master:0;localhost,50466,1321467679574] zookeeper.ZKUtil(230):
master:50466-0x133ad9c76a60006 /hbase/shutdown does not exist. Watcher is set.
2011-11-16 10:21:19,663 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(238): master:50466-0x133ad9c76a60006
Received ZooKeeper Event, type=NodeCreated, state=SyncConnected, path=/hbase/shutdown
2011-11-16 10:21:19,664 INFO  [Master:0;localhost,50466,1321467679574] master.HMaster(387):
Server active/primary master; localhost,50466,1321467679574, sessionid=0x133ad9c76a60006,
cluster-up flag was=false
2011-11-16 10:21:19,664 DEBUG [Master:0;localhost,50466,1321467679574] executor.ExecutorService(190):
Starting executor service name=MASTER_OPEN_REGION-localhost,50466,1321467679574, corePoolSize=5,
maxPoolSize=5
2011-11-16 10:21:19,664 DEBUG [Master:0;localhost,50466,1321467679574] executor.ExecutorService(190):
Starting executor service name=MASTER_CLOSE_REGION-localhost,50466,1321467679574, corePoolSize=5,
maxPoolSize=5
2011-11-16 10:21:19,664 DEBUG [Master:0;localhost,50466,1321467679574] executor.ExecutorService(190):
Starting executor service name=MASTER_SERVER_OPERATIONS-localhost,50466,1321467679574, corePoolSize=3,
maxPoolSize=3
2011-11-16 10:21:19,664 DEBUG [Master:0;localhost,50466,1321467679574] executor.ExecutorService(190):
Starting executor service name=MASTER_META_SERVER_OPERATIONS-localhost,50466,1321467679574,
corePoolSize=5, maxPoolSize=5
2011-11-16 10:21:19,665 DEBUG [Master:0;localhost,50466,1321467679574] executor.ExecutorService(190):
Starting executor service name=MASTER_TABLE_OPERATIONS-localhost,50466,1321467679574, corePoolSize=1,
maxPoolSize=1
2011-11-16 10:21:19,665 DEBUG [Master:0;localhost,50466,1321467679574] master.LogCleaner(115):
Add log cleaner in chain: org.apache.hadoop.hbase.master.TimeToLiveLogCleaner
2011-11-16 10:21:19,665 DEBUG [main-EventThread] zookeeper.ZKUtil(1034): master:50466-0x133ad9c76a60006
Retrieved 28 byte(s) of data from znode /hbase/shutdown and set watcher; Wed Nov 16 10:21:19
PST 2011
2011-11-16 10:21:19,666 DEBUG [Master:0;localhost,50466,1321467679574] master.HMaster(703):
Started service threads
2011-11-16 10:21:19,723 INFO  [main] regionserver.ShutdownHook(85): Installed shutdown hook
thread: Shutdownhook:RegionServer:0;localhost,55575,1321467679622
2011-11-16 10:21:19,726 DEBUG [RegionServer:0;localhost,55575,1321467679622] zookeeper.ZKUtil(95):
regionserver:55575 opening connection to ZooKeeper with ensemble (localhost:56525)
2011-11-16 10:21:19,727 INFO  [RegionServer:0;localhost,55575,1321467679622] zookeeper.RecoverableZooKeeper(89):
The identifier of this process is 19557@ubuntu
2011-11-16 10:21:19,733 DEBUG [RegionServer:0;localhost,55575,1321467679622-EventThread] zookeeper.ZooKeeperWatcher(238):
regionserver:55575 Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2011-11-16 10:21:19,733 DEBUG [RegionServer:0;localhost,55575,1321467679622] zookeeper.ZKUtil(228):
regionserver:55575 Set watcher on existing znode /hbase/master
2011-11-16 10:21:19,734 DEBUG [RegionServer:0;localhost,55575,1321467679622] zookeeper.ZKUtil(1034):
regionserver:55575 Retrieved 31 byte(s) of data from znode /hbase/master and set watcher;
\x00\x00localhost,50466,13214...
2011-11-16 10:21:19,734 DEBUG [RegionServer:0;localhost,55575,1321467679622-EventThread] zookeeper.ZooKeeperWatcher(315):
regionserver:55575-0x133ad9c76a60008 connected
2011-11-16 10:21:19,735 DEBUG [RegionServer:0;localhost,55575,1321467679622] zookeeper.ZKUtil(228):
regionserver:55575-0x133ad9c76a60008 Set watcher on existing znode /hbase/shutdown
2011-11-16 10:21:19,736 DEBUG [RegionServer:0;localhost,55575,1321467679622] zookeeper.ZKUtil(1034):
regionserver:55575-0x133ad9c76a60008 Retrieved 28 byte(s) of data from znode /hbase/shutdown
and set watcher; Wed Nov 16 10:21:19 PST 2011
2011-11-16 10:21:19,736 DEBUG [RegionServer:0;localhost,55575,1321467679622] catalog.CatalogTracker(217):
Starting catalog tracker org.apache.hadoop.hbase.catalog.CatalogTracker@35d56bbe
2011-11-16 10:21:19,737 DEBUG [RegionServer:0;localhost,55575,1321467679622] zookeeper.ZKUtil(228):
regionserver:55575-0x133ad9c76a60008 Set watcher on existing znode /hbase/root-region-server
2011-11-16 10:21:19,738 DEBUG [RegionServer:0;localhost,55575,1321467679622] zookeeper.ZKUtil(1034):
regionserver:55575-0x133ad9c76a60008 Retrieved 30 byte(s) of data from znode /hbase/root-region-server
and set watcher; example.org,1234,1321467679534
2011-11-16 10:21:19,738 DEBUG [RegionServer:0;localhost,55575,1321467679622] zookeeper.ZKUtil(230):
regionserver:55575-0x133ad9c76a60008 /hbase/unassigned/1028785192 does not exist. Watcher
is set.
2011-11-16 10:21:19,739 INFO  [RegionServer:0;localhost,55575,1321467679622] regionserver.MemStoreFlusher(114):
globalMemStoreLimit=497.8m, globalMemStoreLimitLowMark=435.6m, maxHeap=1.2g
2011-11-16 10:21:19,739 INFO  [RegionServer:0;localhost,55575,1321467679622] regionserver.HRegionServer$CompactionChecker(1158):
Runs every 16mins, 40sec
2011-11-16 10:21:19,767 INFO  [Master:0;localhost,50466,1321467679574] master.ServerManager(530):
Waiting on regionserver(s) to checkin
2011-11-16 10:21:19,774 INFO  [RegionServer:0;localhost,55575,1321467679622] regionserver.HRegionServer(1737):
Attempting connect to Master server at localhost,50466,1321467679574
2011-11-16 10:21:19,779 INFO  [RegionServer:0;localhost,55575,1321467679622] regionserver.HRegionServer(1766):
Connected to master at localhost/127.0.0.1:50466
2011-11-16 10:21:19,779 INFO  [RegionServer:0;localhost,55575,1321467679622] regionserver.HRegionServer(1792):
Telling master at localhost,50466,1321467679574 that we are up with port=55575, startcode=1321467679622
2011-11-16 10:21:19,780 INFO  [IPC Server handler 2 on 50466] master.ServerManager(239): Registering
server=localhost,55575,1321467679622
2011-11-16 10:21:19,781 INFO  [RegionServer:0;localhost,55575,1321467679622] regionserver.HRegionServer(911):
Master passed us hostname to use. Was=localhost, Now=localhost
2011-11-16 10:21:19,781 DEBUG [RegionServer:0;localhost,55575,1321467679622] regionserver.HRegionServer(918):
Config from master: fs.default.name=hdfs://localhost:40123
2011-11-16 10:21:19,782 DEBUG [RegionServer:0;localhost,55575,1321467679622] regionserver.HRegionServer(918):
Config from master: hbase.rootdir=hdfs://localhost:40123/user/nkeywal
2011-11-16 10:21:19,783 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(238): master:50466-0x133ad9c76a60006
Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/rs
2011-11-16 10:21:19,786 DEBUG [main-EventThread] zookeeper.ZKUtil(228): master:50466-0x133ad9c76a60006
Set watcher on existing znode /hbase/rs/localhost,55575,1321467679622
2011-11-16 10:21:19,788 DEBUG [RegionServer:0;localhost,55575,1321467679622] regionserver.HRegionServer(1219):
logdir=hdfs://localhost:40123/user/nkeywal/.logs/localhost,55575,1321467679622
2011-11-16 10:21:19,805 INFO  [RegionServer:0;localhost,55575,1321467679622] wal.HLog(417):
HLog configuration: blocksize=64 MB, rollsize=60.8 MB, enabled=true, optionallogflushinternal=1000ms
2011-11-16 10:21:19,806 DEBUG [RegionServer:0;localhost,55575,1321467679622] wal.SequenceFileLogWriter(113):
new createWriter -- HADOOP-6840 -- not available
2011-11-16 10:21:19,810 DEBUG [RegionServer:0;localhost,55575,1321467679622] wal.SequenceFileLogWriter(136):
Path=hdfs://localhost:40123/user/nkeywal/.logs/localhost,55575,1321467679622/localhost%2C55575%2C1321467679622.1321467679806,
syncFs=true, hflush=false
2011-11-16 10:21:19,810 INFO  [RegionServer:0;localhost,55575,1321467679622] wal.HLog(614):
 for /user/nkeywal/.logs/localhost,55575,1321467679622/localhost%2C55575%2C1321467679622.1321467679806
2011-11-16 10:21:19,810 INFO  [RegionServer:0;localhost,55575,1321467679622] wal.HLog(459):
Using getNumCurrentReplicas--HDFS-826
2011-11-16 10:21:19,811 INFO  [RegionServer:0;localhost,55575,1321467679622] metrics.MetricsMBeanBase(111):
new MBeanInfo
2011-11-16 10:21:19,811 INFO  [RegionServer:0;localhost,55575,1321467679622] metrics.RegionServerMetrics(248):
Initialized
2011-11-16 10:21:19,812 DEBUG [RegionServer:0;localhost,55575,1321467679622] executor.ExecutorService(190):
Starting executor service name=RS_OPEN_REGION-localhost,55575,1321467679622, corePoolSize=3,
maxPoolSize=3
2011-11-16 10:21:19,812 DEBUG [RegionServer:0;localhost,55575,1321467679622] executor.ExecutorService(190):
Starting executor service name=RS_OPEN_ROOT-localhost,55575,1321467679622, corePoolSize=1,
maxPoolSize=1
2011-11-16 10:21:19,812 DEBUG [RegionServer:0;localhost,55575,1321467679622] executor.ExecutorService(190):
Starting executor service name=RS_OPEN_META-localhost,55575,1321467679622, corePoolSize=1,
maxPoolSize=1
2011-11-16 10:21:19,813 DEBUG [RegionServer:0;localhost,55575,1321467679622] executor.ExecutorService(190):
Starting executor service name=RS_CLOSE_REGION-localhost,55575,1321467679622, corePoolSize=3,
maxPoolSize=3
2011-11-16 10:21:19,813 DEBUG [RegionServer:0;localhost,55575,1321467679622] executor.ExecutorService(190):
Starting executor service name=RS_CLOSE_ROOT-localhost,55575,1321467679622, corePoolSize=1,
maxPoolSize=1
2011-11-16 10:21:19,813 DEBUG [RegionServer:0;localhost,55575,1321467679622] executor.ExecutorService(190):
Starting executor service name=RS_CLOSE_META-localhost,55575,1321467679622, corePoolSize=1,
maxPoolSize=1
2011-11-16 10:21:19,860 INFO  [RegionServer:0;localhost,55575,1321467679622] regionserver.HRegionServer(947):
Serving as localhost,55575,1321467679622, RPC listening on localhost/127.0.0.1:55575, sessionid=0x133ad9c76a60008
2011-11-16 10:21:19,860 INFO  [SplitLogWorker-localhost,55575,1321467679622] regionserver.SplitLogWorker(140):
SplitLogWorker localhost,55575,1321467679622 starting
2011-11-16 10:21:19,868 INFO  [Master:0;localhost,50466,1321467679574] master.ServerManager(530):
Waiting on regionserver(s) count to settle; currently=1
2011-11-16 10:21:19,973 INFO  [Master:0;localhost,50466,1321467679574] master.MasterFileSystem(212):
Log folder hdfs://localhost:40123/user/nkeywal/.logs/localhost,55575,1321467679622 belongs
to an existing region server
2011-11-16 10:21:19,973 INFO  [Master:0;localhost,50466,1321467679574] master.MasterFileSystem(266):
No logs to split
2011-11-16 10:21:19,975 DEBUG [Master:0;localhost,50466,1321467679574] zookeeper.ZKUtil(518):
master:50466-0x133ad9c76a60006 Unable to get data of znode /hbase/unassigned/70236052 because
node does not exist (not an error)
2011-11-16 10:21:19,978 DEBUG [Master:0;localhost,50466,1321467679574] zookeeper.ZKUtil(1034):
master:50466-0x133ad9c76a60006 Retrieved 30 byte(s) of data from znode /hbase/root-region-server
and set watcher; example.org,1234,1321467679534
2011-11-16 10:21:19,981 DEBUG [Master:0;localhost,50466,1321467679574] zookeeper.ZKUtil(1034):
hconnection-0x133ad9c76a60007 Retrieved 36 byte(s) of data from znode /hbase/hbaseid; data=03980100-b09a-48c1-9bf2-70f49...
2011-11-16 10:21:24,550 INFO  [Thread-133] catalog.RootLocationEditor(43): Unsetting ROOT
region location in ZooKeeper
2011-11-16 10:21:24,575 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(238): master:50466-0x133ad9c76a60006
Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/root-region-server
2011-11-16 10:21:24,575 DEBUG [Master:0;localhost,50466,1321467679574-EventThread] zookeeper.ZooKeeperWatcher(238):
hconnection-0x133ad9c76a60007 Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected,
path=/hbase/root-region-server
2011-11-16 10:21:24,576 DEBUG [main-EventThread] zookeeper.ZooKeeperWatcher(238): hconnection-0x133ad9c76a60004
Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/root-region-server
2011-11-16 10:21:24,580 DEBUG [RegionServer:0;localhost,55575,1321467679622-EventThread] zookeeper.ZooKeeperWatcher(238):
regionserver:55575-0x133ad9c76a60008 Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected,
path=/hbase/root-region-server
2011-11-16 10:21:24,581 INFO  [Thread-133] catalog.TestCatalogTrackerOnCluster$2(85): RootLocationEditor
is now clean.
2011-11-16 10:21:24,581 DEBUG [Master:0;localhost,50466,1321467679574-EventThread] zookeeper.ZKUtil(230):
hconnection-0x133ad9c76a60007 /hbase/root-region-server does not exist. Watcher is set.
2011-11-16 10:21:24,584 DEBUG [main-EventThread] zookeeper.ZKUtil(230): hconnection-0x133ad9c76a60004
/hbase/root-region-server does not exist. Watcher is set.
2011-11-16 10:21:24,584 DEBUG [main-EventThread] zookeeper.ZKUtil(230): master:50466-0x133ad9c76a60006
/hbase/root-region-server does not exist. Watcher is set.
2011-11-16 10:21:24,585 DEBUG [RegionServer:0;localhost,55575,1321467679622-EventThread] zookeeper.ZKUtil(230):
regionserver:55575-0x133ad9c76a60008 /hbase/root-region-server does not exist. Watcher is
set.
2011-11-16 10:21:49,769 ERROR [main] hbase.MiniHBaseCluster(201): Error starting cluster
java.lang.RuntimeException: Master not initialized after 30 seconds
	at org.apache.hadoop.hbase.util.JVMClusterUtil.startup(JVMClusterUtil.java:206)
	at org.apache.hadoop.hbase.LocalHBaseCluster.startup(LocalHBaseCluster.java:418)
{noformat}
                
> Sleeps and synchronisation improvements for tests
> -------------------------------------------------
>
>                 Key: HBASE-4798
>                 URL: https://issues.apache.org/jira/browse/HBASE-4798
>             Project: HBase
>          Issue Type: Improvement
>          Components: master, regionserver, test
>    Affects Versions: 0.94.0
>         Environment: all
>            Reporter: nkeywal
>            Assignee: nkeywal
>            Priority: Minor
>         Attachments: 4798_trunk_all.v2.patch
>
>
> Multiple small changes:
> @commiters: Removing some sleeps made visible a bug on JVMClusterUtil#HMaster#waitForServerOnline,
so I had to add a synchro point. You may want to review this.
> JVMClusterUtil#HMaster#waitForServerOnline: removed, the condition was never met (test
on "!c && !!c"). Added a new synchronization point.
> AssignementManager#waitForAssignment: add a timeout on the wait => not stuck if the
notification is received before the wait.
> HMaster#loop: use a notification instead of a 1s sleep
> HRegionServer#waitForServerOnline: new method used by JVMClusterUtil#waitForServerOnline()
to replace a 1s sleep by a notification
> HRegionServer#getMaster() 1s sleeps replaced by one 0,1s sleep and one 0,2s sleep
> HRegionServer#stop: use a notification on sleeper to lower shutdown by 0,5s
> ZooKeeperNodeTracker#start: replace a recursive call by a loop
> ZooKeeperNodeTracker#blockUntilAvailable: add a timeout on the wait => not stuck if
the notification is received before the wait.
> HBaseTestingUtility#expireSession: use a timeout of 1s instead of 5s
> TestZooKeeper#testClientSessionExpired: use a timeout of 1s instead of 5s, with the change
on HBaseTestingUtility we are 60s faster
> TestRegionRebalancing#waitForAllRegionsAssigned: use a sleep of 0,2s instead of 1s
> TestRestartCluster#testClusterRestart: send all the table creation together, then check
creation, should be faster
> TestHLog: shutdown the whole cluster instead of DFS only (more standard) 
> JVMClusterUtil#startup: lower the sleep from 1s to 0,1s
> HConnectionManager#close: Zookeeper name in debug message from HConnectionManager after
connection close was always null because it was set to null in the delete.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

Mime
View raw message