[HBASE-6810] TestZKPermissionsWatcher some times fails in trunk - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Closed
Priority: Major
Resolution: Cannot Reproduce
Affects Version/s: None
Fix Version/s: None
Component/s: None
Labels:
- delete

Description

In build #3348, TestZKPermissionsWatcher#testPermissionsWatcher failed:

java.lang.AssertionError
	at org.junit.Assert.fail(Assert.java:92)
	at org.junit.Assert.assertTrue(Assert.java:43)
	at org.junit.Assert.assertTrue(Assert.java:54)
	at org.apache.hadoop.hbase.security.access.TestZKPermissionsWatcher.testPermissionsWatcher(TestZKPermissionsWatcher.java:146)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
	at org.junit.runners.Suite.runChild(Suite.java:128)
	at org.junit.runners.Suite.runChild(Suite.java:24)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)

Standard Output

Starting DataNode 0 with dfs.data.dir: /x1/jenkins/jenkins-slave/workspace/HBase-TRUNK/trunk/hbase-server/target/test-data/0d33b8f6-92e9-4547-8f41-896f54a6c1f9/dfscluster_f21fe306-e20e-4a9b-9d9f-61dae4f25f3e/dfs/data/data1,/x1/jenkins/jenkins-slave/workspace/HBase-TRUNK/trunk/hbase-server/target/test-data/0d33b8f6-92e9-4547-8f41-896f54a6c1f9/dfscluster_f21fe306-e20e-4a9b-9d9f-61dae4f25f3e/dfs/data/data2
Shutting down the Mini HDFS Cluster
Shutting down DataNode 0

Standard Error

2012-09-18 20:29:59,306 INFO  [pool-1-thread-1] hbase.HBaseTestingUtility(639): Starting up minicluster with 1 master(s) and 1 regionserver(s) and 1 datanode(s)
2012-09-18 20:29:59,373 INFO  [pool-1-thread-1] hbase.HBaseTestingUtility(294): Created new mini-cluster data directory: /x1/jenkins/jenkins-slave/workspace/HBase-TRUNK/trunk/hbase-server/target/test-data/0d33b8f6-92e9-4547-8f41-896f54a6c1f9/dfscluster_f21fe306-e20e-4a9b-9d9f-61dae4f25f3e
2012-09-18 20:29:59,374 INFO  [pool-1-thread-1] hbase.HBaseTestingUtility(491): Setting test.cache.data to /x1/jenkins/jenkins-slave/workspace/HBase-TRUNK/trunk/hbase-server/target/test-data/0d33b8f6-92e9-4547-8f41-896f54a6c1f9/dfscluster_f21fe306-e20e-4a9b-9d9f-61dae4f25f3e/cache_data in system properties and HBase conf
2012-09-18 20:29:59,374 INFO  [pool-1-thread-1] hbase.HBaseTestingUtility(491): Setting hadoop.tmp.dir to /x1/jenkins/jenkins-slave/workspace/HBase-TRUNK/trunk/hbase-server/target/test-data/0d33b8f6-92e9-4547-8f41-896f54a6c1f9/dfscluster_f21fe306-e20e-4a9b-9d9f-61dae4f25f3e/hadoop_tmp in system properties and HBase conf
2012-09-18 20:29:59,374 INFO  [pool-1-thread-1] hbase.HBaseTestingUtility(491): Setting hadoop.log.dir to /x1/jenkins/jenkins-slave/workspace/HBase-TRUNK/trunk/hbase-server/target/test-data/0d33b8f6-92e9-4547-8f41-896f54a6c1f9/dfscluster_f21fe306-e20e-4a9b-9d9f-61dae4f25f3e/hadoop_logs in system properties and HBase conf
2012-09-18 20:29:59,376 INFO  [pool-1-thread-1] hbase.HBaseTestingUtility(491): Setting mapred.output.dir to /x1/jenkins/jenkins-slave/workspace/HBase-TRUNK/trunk/hbase-server/target/test-data/0d33b8f6-92e9-4547-8f41-896f54a6c1f9/dfscluster_f21fe306-e20e-4a9b-9d9f-61dae4f25f3e/mapred_output in system properties and HBase conf
2012-09-18 20:29:59,376 INFO  [pool-1-thread-1] hbase.HBaseTestingUtility(491): Setting mapred.local.dir to /x1/jenkins/jenkins-slave/workspace/HBase-TRUNK/trunk/hbase-server/target/test-data/0d33b8f6-92e9-4547-8f41-896f54a6c1f9/dfscluster_f21fe306-e20e-4a9b-9d9f-61dae4f25f3e/mapred_local in system properties and HBase conf
2012-09-18 20:29:59,377 INFO  [pool-1-thread-1] hbase.HBaseTestingUtility(491): Setting mapred.system.dir to /x1/jenkins/jenkins-slave/workspace/HBase-TRUNK/trunk/hbase-server/target/test-data/0d33b8f6-92e9-4547-8f41-896f54a6c1f9/dfscluster_f21fe306-e20e-4a9b-9d9f-61dae4f25f3e/mapred_system in system properties and HBase conf
2012-09-18 20:29:59,377 INFO  [pool-1-thread-1] hbase.HBaseTestingUtility(491): Setting mapred.temp.dir to /x1/jenkins/jenkins-slave/workspace/HBase-TRUNK/trunk/hbase-server/target/test-data/0d33b8f6-92e9-4547-8f41-896f54a6c1f9/dfscluster_f21fe306-e20e-4a9b-9d9f-61dae4f25f3e/mapred_temp in system properties and HBase conf
2012-09-18 20:29:59,740 WARN  [pool-1-thread-1] impl.MetricsSystemImpl(137): Metrics system not started: Cannot locate configuration: tried hadoop-metrics2-namenode.properties, hadoop-metrics2.properties
2012-09-18 20:29:59,933 INFO  [pool-1-thread-1] log.Slf4jLog(67): Logging to org.slf4j.impl.Log4jLoggerAdapter(org.mortbay.log) via org.mortbay.log.Slf4jLog
2012-09-18 20:30:00,005 INFO  [pool-1-thread-1] log.Slf4jLog(67): jetty-6.1.26
2012-09-18 20:30:00,038 INFO  [pool-1-thread-1] log.Slf4jLog(67): Extract jar:file:/home/jenkins/.m2/repository/org/apache/hadoop/hadoop-core/1.0.3/hadoop-core-1.0.3.jar!/webapps/hdfs to /tmp/Jetty_localhost_36636_hdfs____.l2m074/webapp
2012-09-18 20:30:00,363 INFO  [pool-1-thread-1] log.Slf4jLog(67): Started SelectChannelConnector@localhost:36636
2012-09-18 20:30:00,445 WARN  [pool-1-thread-1] impl.MetricsSystemImpl(137): Metrics system not started: Cannot locate configuration: tried hadoop-metrics2-datanode.properties, hadoop-metrics2.properties
2012-09-18 20:30:00,446 WARN  [pool-1-thread-1] util.MBeans(59): Hadoop:service=DataNode,name=MetricsSystem,sub=Control
javax.management.InstanceAlreadyExistsException: MXBean already registered with name Hadoop:service=NameNode,name=MetricsSystem,sub=Control
	at com.sun.jmx.mbeanserver.MXBeanLookup.addReference(MXBeanLookup.java:120)
	at com.sun.jmx.mbeanserver.MXBeanSupport.register(MXBeanSupport.java:143)
	at com.sun.jmx.mbeanserver.MBeanSupport.preRegister2(MBeanSupport.java:183)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:941)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:917)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:312)
	at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:482)
	at org.apache.hadoop.metrics2.util.MBeans.register(MBeans.java:56)
	at org.apache.hadoop.metrics2.impl.MetricsSystemImpl.initSystemMBean(MetricsSystemImpl.java:500)
	at org.apache.hadoop.metrics2.impl.MetricsSystemImpl.init(MetricsSystemImpl.java:140)
	at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.init(DefaultMetricsSystem.java:40)
	at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.initialize(DefaultMetricsSystem.java:50)
	at org.apache.hadoop.hdfs.server.datanode.DataNode.instantiateDataNode(DataNode.java:1520)
	at org.apache.hadoop.hdfs.server.datanode.DataNode.instantiateDataNode(DataNode.java:1496)
	at org.apache.hadoop.hdfs.MiniDFSCluster.startDataNodes(MiniDFSCluster.java:417)
	at org.apache.hadoop.hdfs.MiniDFSCluster.<init>(MiniDFSCluster.java:280)
	at org.apache.hadoop.hbase.HBaseTestingUtility.startMiniDFSCluster(HBaseTestingUtility.java:432)
	at org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:653)
	at org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:603)
	at org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:572)
	at org.apache.hadoop.hbase.security.access.TestZKPermissionsWatcher.beforeClass(TestZKPermissionsWatcher.java:74)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:27)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
	at org.junit.runners.Suite.runChild(Suite.java:128)
	at org.junit.runners.Suite.runChild(Suite.java:24)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)
2012-09-18 20:30:00,509 INFO  [pool-1-thread-1] log.Slf4jLog(67): jetty-6.1.26
2012-09-18 20:30:00,521 INFO  [pool-1-thread-1] log.Slf4jLog(67): Extract jar:file:/home/jenkins/.m2/repository/org/apache/hadoop/hadoop-core/1.0.3/hadoop-core-1.0.3.jar!/webapps/datanode to /tmp/Jetty_localhost_49745_datanode____.h2811i/webapp
2012-09-18 20:30:00,713 INFO  [pool-1-thread-1] log.Slf4jLog(67): Started SelectChannelConnector@localhost:49745
2012-09-18 20:30:00,785 INFO  [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(196): Started MiniZK Cluster and connect 1 ZK server on client port: 54880
2012-09-18 20:30:01,281 DEBUG [pool-1-thread-1] util.FSUtils(442): Created version file at hdfs://localhost:42338/user/jenkins/hbase with version=7
2012-09-18 20:30:01,352 DEBUG [pool-1-thread-1] client.HConnectionManager(2453): Set serverside HConnection retries=100
2012-09-18 20:30:01,400 INFO  [pool-1-thread-1] ipc.HBaseRpcMetrics(65): Initializing RPC Metrics with hostName=HMaster, port=57673
2012-09-18 20:30:01,460 DEBUG [pool-1-thread-1] zookeeper.ZKUtil(102): master:57673 opening connection to ZooKeeper with ensemble (localhost:54880)
2012-09-18 20:30:01,476 INFO  [pool-1-thread-1] zookeeper.RecoverableZooKeeper(101): The identifier of this process is 25567@hemera
2012-09-18 20:30:01,496 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673 Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2012-09-18 20:30:01,499 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(342): master:57673-0x139db12b83f0000 connected
2012-09-18 20:30:01,548 WARN  [pool-1-thread-1] impl.MetricsSystemImpl(137): Metrics system not started: Cannot locate configuration: tried hadoop-metrics2-hbase.properties, hadoop-metrics2.properties
2012-09-18 20:30:01,549 WARN  [pool-1-thread-1] util.MBeans(59): Hadoop:service=hbase,name=MetricsSystem,sub=Control
javax.management.InstanceAlreadyExistsException: MXBean already registered with name Hadoop:service=NameNode,name=MetricsSystem,sub=Control
	at com.sun.jmx.mbeanserver.MXBeanLookup.addReference(MXBeanLookup.java:120)
	at com.sun.jmx.mbeanserver.MXBeanSupport.register(MXBeanSupport.java:143)
	at com.sun.jmx.mbeanserver.MBeanSupport.preRegister2(MBeanSupport.java:183)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:941)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:917)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:312)
	at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:482)
	at org.apache.hadoop.metrics2.util.MBeans.register(MBeans.java:56)
	at org.apache.hadoop.metrics2.impl.MetricsSystemImpl.initSystemMBean(MetricsSystemImpl.java:500)
	at org.apache.hadoop.metrics2.impl.MetricsSystemImpl.init(MetricsSystemImpl.java:140)
	at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.init(DefaultMetricsSystem.java:40)
	at org.apache.hadoop.metrics2.lib.DefaultMetricsSystem.initialize(DefaultMetricsSystem.java:50)
	at org.apache.hadoop.hbase.metrics.BaseMetricsSourceImpl.<init>(BaseMetricsSourceImpl.java:70)
	at org.apache.hadoop.hbase.master.metrics.MasterMetricsSourceImpl.<init>(MasterMetricsSourceImpl.java:51)
	at org.apache.hadoop.hbase.master.metrics.MasterMetricsSourceImpl.<init>(MasterMetricsSourceImpl.java:43)
	at org.apache.hadoop.hbase.master.metrics.MasterMetricsSourceFactoryImpl.create(MasterMetricsSourceFactoryImpl.java:33)
	at org.apache.hadoop.hbase.master.metrics.MasterMetrics.<init>(MasterMetrics.java:40)
	at org.apache.hadoop.hbase.master.HMaster.<init>(HMaster.java:383)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
	at org.apache.hadoop.hbase.util.JVMClusterUtil.createMasterThread(JVMClusterUtil.java:132)
	at org.apache.hadoop.hbase.LocalHBaseCluster.addMaster(LocalHBaseCluster.java:200)
	at org.apache.hadoop.hbase.LocalHBaseCluster.<init>(LocalHBaseCluster.java:150)
	at org.apache.hadoop.hbase.MiniHBaseCluster.init(MiniHBaseCluster.java:209)
	at org.apache.hadoop.hbase.MiniHBaseCluster.<init>(MiniHBaseCluster.java:89)
	at org.apache.hadoop.hbase.HBaseTestingUtility.startMiniHBaseCluster(HBaseTestingUtility.java:693)
	at org.apache.hadoop.hbase.HBaseTestingUtility.startMiniHBaseCluster(HBaseTestingUtility.java:666)
	at org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:661)
	at org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:603)
	at org.apache.hadoop.hbase.HBaseTestingUtility.startMiniCluster(HBaseTestingUtility.java:572)
	at org.apache.hadoop.hbase.security.access.TestZKPermissionsWatcher.beforeClass(TestZKPermissionsWatcher.java:74)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:27)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
	at org.junit.runners.Suite.runChild(Suite.java:128)
	at org.junit.runners.Suite.runChild(Suite.java:24)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)
2012-09-18 20:30:01,614 DEBUG [pool-1-thread-1] client.HConnectionManager(2453): Set serverside HConnection retries=100
2012-09-18 20:30:01,643 INFO  [pool-1-thread-1] ipc.HBaseRpcMetrics(65): Initializing RPC Metrics with hostName=MiniHBaseCluster$MiniHBaseClusterRegionServer, port=56450
2012-09-18 20:30:01,702 INFO  [pool-1-thread-1] hfile.CacheConfig(350): Allocating LruBlockCache with maximum size 422.2m
2012-09-18 20:30:01,711 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(237): master:57673-0x139db12b83f0000 /hbase/shutdown does not exist. Watcher is set.
2012-09-18 20:30:01,714 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.ActiveMasterManager(149): Deleting ZNode for /hbase/backup-masters/hemera.apache.org,57673,1348000201449 from backup master directory
2012-09-18 20:30:01,716 WARN  [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.RecoverableZooKeeper(141): Node /hbase/backup-masters/hemera.apache.org,57673,1348000201449 already deleted, and this is not a retry
2012-09-18 20:30:01,717 WARN  [Master:0;hemera.apache.org,57673,1348000201449] hbase.ZNodeClearer(58): No filename given to save the znode used, it won't be saved (Environment variable HBASE_ZNODE_FILE is not set).
2012-09-18 20:30:01,717 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.ActiveMasterManager(158): Master=hemera.apache.org,57673,1348000201449
2012-09-18 20:30:01,722 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] master.SplitLogManager(175): timeout = 25000
2012-09-18 20:30:01,722 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] master.SplitLogManager(176): unassigned timeout = 180000
2012-09-18 20:30:01,724 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.SplitLogManager(806): found 0 orphan tasks and 0 rescan nodes
2012-09-18 20:30:01,761 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] util.FSUtils(571): Created cluster ID file at hdfs://localhost:42338/user/jenkins/hbase/hbase.id with ID: 5dbaab6f-b03b-4631-b4f3-dbaffefbe1e9
2012-09-18 20:30:01,785 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.MasterFileSystem(395): BOOTSTRAP: creating ROOT and first META regions
2012-09-18 20:30:01,785 INFO  [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(3834): creating HRegion -ROOT- HTD == '-ROOT-', {METHOD => 'table_att', IS_META => 'true', IS_ROOT => 'true'}, {NAME => 'info', DATA_BLOCK_ENCODING => 'NONE', BLOOMFILTER => 'NONE', REPLICATION_SCOPE => '0', COMPRESSION => 'NONE', VERSIONS => '10', TTL => '2147483647', MIN_VERSIONS => '0', KEEP_DELETED_CELLS => 'false', BLOCKSIZE => '8192', ENCODE_ON_DISK => 'true', IN_MEMORY => 'false', BLOCKCACHE => 'false'} RootDir = hdfs://localhost:42338/user/jenkins/hbase Table name == -ROOT-
2012-09-18 20:30:01,791 INFO  [Master:0;hemera.apache.org,57673,1348000201449] wal.HLog(458): FileSystem doesn't support getDefaultBlockSize
2012-09-18 20:30:01,794 INFO  [Master:0;hemera.apache.org,57673,1348000201449] wal.HLog(429): HLog configuration: blocksize=64 MB, rollsize=60.8 MB, enabled=true, optionallogflushinternal=1000ms
2012-09-18 20:30:01,805 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] wal.SequenceFileLogWriter(189): using new createWriter -- HADOOP-6840
2012-09-18 20:30:01,805 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] wal.SequenceFileLogWriter(193): Path=hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/.logs/hlog.1348000201794, compression=false
2012-09-18 20:30:01,805 INFO  [Master:0;hemera.apache.org,57673,1348000201449] wal.HLog(653):  for /user/jenkins/hbase/-ROOT-/70236052/.logs/hlog.1348000201794
2012-09-18 20:30:01,805 INFO  [Master:0;hemera.apache.org,57673,1348000201449] wal.HLog(501): Using getNumCurrentReplicas--HDFS-826
2012-09-18 20:30:01,813 INFO  [pool-1-thread-1] regionserver.ShutdownHook(87): Installed shutdown hook thread: Shutdownhook:RegionServer:0;hemera.apache.org,56450,1348000201701
2012-09-18 20:30:01,815 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] zookeeper.ZKUtil(102): regionserver:56450 opening connection to ZooKeeper with ensemble (localhost:54880)
2012-09-18 20:30:01,816 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] zookeeper.RecoverableZooKeeper(101): The identifier of this process is 25567@hemera
2012-09-18 20:30:01,817 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZooKeeperWatcher(265): regionserver:56450 Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2012-09-18 20:30:01,818 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] zookeeper.ZKUtil(235): regionserver:56450 Set watcher on existing znode /hbase/master
2012-09-18 20:30:01,818 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZooKeeperWatcher(342): regionserver:56450-0x139db12b83f0001 connected
2012-09-18 20:30:01,824 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 36 byte(s) of data from znode /hbase/master and set watcher; PBUF\x0A\x1E\x0A\x11hemera.ap...
2012-09-18 20:30:01,825 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] zookeeper.ZKUtil(237): regionserver:56450-0x139db12b83f0001 /hbase/shutdown does not exist. Watcher is set.
2012-09-18 20:30:01,834 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(474): Instantiated -ROOT-,,0.70236052
2012-09-18 20:30:01,840 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] util.FSUtils(167): Creating file=hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/.tmp/.regioninfo with permission=rwxrwxrwx
2012-09-18 20:30:02,283 INFO  [StoreOpenerThread--ROOT-,,0.70236052-1] regionserver.HStore(215): hbase.hstore.compaction.min = 3
2012-09-18 20:30:02,329 INFO  [StoreOpenerThread--ROOT-,,0.70236052-1] util.ChecksumType$2(77): Checksum can use java.util.zip.CRC32
2012-09-18 20:30:02,350 INFO  [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(622): Onlined -ROOT-,,0.70236052; next sequenceid=1
2012-09-18 20:30:02,351 INFO  [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(3834): creating HRegion .META. HTD == '.META.', {METHOD => 'table_att', IS_META => 'true'}, {NAME => 'info', DATA_BLOCK_ENCODING => 'NONE', BLOOMFILTER => 'NONE', REPLICATION_SCOPE => '0', COMPRESSION => 'NONE', VERSIONS => '10', TTL => '2147483647', MIN_VERSIONS => '0', KEEP_DELETED_CELLS => 'false', BLOCKSIZE => '8192', ENCODE_ON_DISK => 'true', IN_MEMORY => 'false', BLOCKCACHE => 'false'} RootDir = hdfs://localhost:42338/user/jenkins/hbase Table name == .META.
2012-09-18 20:30:02,353 INFO  [Master:0;hemera.apache.org,57673,1348000201449] wal.HLog(458): FileSystem doesn't support getDefaultBlockSize
2012-09-18 20:30:02,360 INFO  [Master:0;hemera.apache.org,57673,1348000201449] wal.HLog(429): HLog configuration: blocksize=64 MB, rollsize=60.8 MB, enabled=true, optionallogflushinternal=1000ms
2012-09-18 20:30:02,363 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] wal.SequenceFileLogWriter(189): using new createWriter -- HADOOP-6840
2012-09-18 20:30:02,364 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] wal.SequenceFileLogWriter(193): Path=hdfs://localhost:42338/user/jenkins/hbase/.META./1028785192/.logs/hlog.1348000202360, compression=false
2012-09-18 20:30:02,364 INFO  [Master:0;hemera.apache.org,57673,1348000201449] wal.HLog(653):  for /user/jenkins/hbase/.META./1028785192/.logs/hlog.1348000202360
2012-09-18 20:30:02,364 INFO  [Master:0;hemera.apache.org,57673,1348000201449] wal.HLog(501): Using getNumCurrentReplicas--HDFS-826
2012-09-18 20:30:02,365 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(474): Instantiated .META.,,1.1028785192
2012-09-18 20:30:02,368 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] util.FSUtils(167): Creating file=hdfs://localhost:42338/user/jenkins/hbase/.META./1028785192/.tmp/.regioninfo with permission=rwxrwxrwx
2012-09-18 20:30:02,785 INFO  [StoreOpenerThread-.META.,,1.1028785192-1] regionserver.HStore(215): hbase.hstore.compaction.min = 3
2012-09-18 20:30:02,790 INFO  [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(622): Onlined .META.,,1.1028785192; next sequenceid=1
2012-09-18 20:30:02,803 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(954): Closing -ROOT-,,0.70236052: disabling compactions & flushes
2012-09-18 20:30:02,804 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(975): Updates disabled for region -ROOT-,,0.70236052
2012-09-18 20:30:02,804 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(1481): Started memstore flush for -ROOT-,,0.70236052, current region memstore size 352.0
2012-09-18 20:30:02,805 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(1528): Finished snapshotting -ROOT-,,0.70236052, commencing wait for mvcc, flushsize=352
2012-09-18 20:30:02,805 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(1538): Finished snapshotting, commencing flushing stores
2012-09-18 20:30:02,826 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] util.FSUtils(167): Creating file=hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/.tmp/5971150f6ed745bda83363123504803a with permission=rwxrwxrwx
2012-09-18 20:30:02,838 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] hfile.HFileWriterV2(142): Initialized with CacheConfig:enabled [cacheDataOnRead=false] [cacheDataOnWrite=false] [cacheIndexesOnWrite=false] [cacheBloomsOnWrite=false] [cacheEvictOnClose=false] [cacheCompressed=false]
2012-09-18 20:30:02,841 INFO  [Master:0;hemera.apache.org,57673,1348000201449] regionserver.StoreFile$Writer(1021): Delete Family Bloom filter type for hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/.tmp/5971150f6ed745bda83363123504803a: CompoundBloomFilterWriter
2012-09-18 20:30:02,857 INFO  [Master:0;hemera.apache.org,57673,1348000201449] regionserver.StoreFile$Writer(1241): NO General Bloom and NO DeleteFamily was added to HFile (hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/.tmp/5971150f6ed745bda83363123504803a) 
2012-09-18 20:30:02,857 INFO  [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HStore(767): Flushed , sequenceid=2, memsize=352.0, into tmp file hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/.tmp/5971150f6ed745bda83363123504803a
2012-09-18 20:30:02,881 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HStore(792): Renaming flushed file at hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/.tmp/5971150f6ed745bda83363123504803a to hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/info/5971150f6ed745bda83363123504803a
2012-09-18 20:30:02,893 INFO  [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HStore(815): Added hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/info/5971150f6ed745bda83363123504803a, entries=2, sequenceid=2, filesize=836.0
2012-09-18 20:30:02,894 INFO  [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(1617): Finished memstore flush of ~352.0/352, currentsize=0.0/0 for region -ROOT-,,0.70236052 in 90ms, sequenceid=2, compaction requested=false
2012-09-18 20:30:02,897 INFO  [StoreCloserThread--ROOT-,,0.70236052-1] regionserver.HStore(635): Closed info
2012-09-18 20:30:02,897 INFO  [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(1023): Closed -ROOT-,,0.70236052
2012-09-18 20:30:02,898 INFO  [Master:0;hemera.apache.org,57673,1348000201449.logSyncer] wal.HLog$LogSyncer(1245): Master:0;hemera.apache.org,57673,1348000201449.logSyncer exiting
2012-09-18 20:30:02,898 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] wal.HLog(1007): closing hlog writer in hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/.logs
2012-09-18 20:30:03,309 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] wal.HLog(975): Moved 1 log files to /user/jenkins/hbase/-ROOT-/70236052/.oldlogs
2012-09-18 20:30:03,311 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(954): Closing .META.,,1.1028785192: disabling compactions & flushes
2012-09-18 20:30:03,311 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(975): Updates disabled for region .META.,,1.1028785192
2012-09-18 20:30:03,312 INFO  [StoreCloserThread-.META.,,1.1028785192-1] regionserver.HStore(635): Closed info
2012-09-18 20:30:03,312 INFO  [Master:0;hemera.apache.org,57673,1348000201449] regionserver.HRegion(1023): Closed .META.,,1.1028785192
2012-09-18 20:30:03,312 INFO  [Master:0;hemera.apache.org,57673,1348000201449.logSyncer] wal.HLog$LogSyncer(1245): Master:0;hemera.apache.org,57673,1348000201449.logSyncer exiting
2012-09-18 20:30:03,313 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] wal.HLog(1007): closing hlog writer in hdfs://localhost:42338/user/jenkins/hbase/.META./1028785192/.logs
2012-09-18 20:30:03,724 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] wal.HLog(975): Moved 1 log files to /user/jenkins/hbase/.META./1028785192/.oldlogs
2012-09-18 20:30:03,762 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] fs.HFileSystem(196): Starting addLocationsOrderInterceptor with class class org.apache.hadoop.hbase.fs.HFileSystem$ReorderWALBlocks
2012-09-18 20:30:03,763 INFO  [Master:0;hemera.apache.org,57673,1348000201449] fs.HFileSystem(243): Added intercepting call to namenode#getBlockLocations
2012-09-18 20:30:03,783 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(102): hconnection 0x2bfa91 opening connection to ZooKeeper with ensemble (localhost:54880)
2012-09-18 20:30:03,784 INFO  [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.RecoverableZooKeeper(101): The identifier of this process is 25567@hemera
2012-09-18 20:30:03,786 DEBUG [Master:0;hemera.apache.org,57673,1348000201449-EventThread] zookeeper.ZooKeeperWatcher(265): hconnection 0x2bfa91 Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2012-09-18 20:30:03,787 DEBUG [Master:0;hemera.apache.org,57673,1348000201449-EventThread] zookeeper.ZooKeeperWatcher(342): hconnection 0x2bfa91-0x139db12b83f0002 connected
2012-09-18 20:30:03,788 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 42 byte(s) of data from znode /hbase/hbaseid; data=PBUF\x0A$5dbaab6f-b03b-4631-b...
2012-09-18 20:30:03,788 INFO  [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(662): ClusterId is 5dbaab6f-b03b-4631-b4f3-dbaffefbe1e9
2012-09-18 20:30:03,791 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] catalog.CatalogTracker(240): Starting catalog tracker org.apache.hadoop.hbase.catalog.CatalogTracker@959fa1
2012-09-18 20:30:03,792 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(237): master:57673-0x139db12b83f0000 /hbase/root-region-server does not exist. Watcher is set.
2012-09-18 20:30:03,793 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(237): master:57673-0x139db12b83f0000 /hbase/unassigned/1028785192 does not exist. Watcher is set.
2012-09-18 20:30:03,798 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(237): master:57673-0x139db12b83f0000 /hbase/balancer does not exist. Watcher is set.
2012-09-18 20:30:03,820 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeCreated, state=SyncConnected, path=/hbase/shutdown
2012-09-18 20:30:03,820 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZooKeeperWatcher(265): regionserver:56450-0x139db12b83f0001 Received ZooKeeper Event, type=NodeCreated, state=SyncConnected, path=/hbase/shutdown
2012-09-18 20:30:03,821 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.HMaster(539): Server active/primary master; hemera.apache.org,57673,1348000201449, sessionid=0x139db12b83f0000, cluster-up flag was=false
2012-09-18 20:30:03,821 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 34 byte(s) of data from znode /hbase/shutdown and set watcher; PBUF\x0A\x1CTue Sep 18 20:30:...
2012-09-18 20:30:03,822 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 34 byte(s) of data from znode /hbase/shutdown and set watcher; PBUF\x0A\x1CTue Sep 18 20:30:...
2012-09-18 20:30:03,823 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] zookeeper.ZKUtil(102): hconnection 0xfa1b2d opening connection to ZooKeeper with ensemble (localhost:54880)
2012-09-18 20:30:03,824 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] zookeeper.RecoverableZooKeeper(101): The identifier of this process is 25567@hemera
2012-09-18 20:30:03,827 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZooKeeperWatcher(265): hconnection 0xfa1b2d Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2012-09-18 20:30:03,828 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] zookeeper.ZKUtil(1141): hconnection 0xfa1b2d Retrieved 42 byte(s) of data from znode /hbase/hbaseid; data=PBUF\x0A$5dbaab6f-b03b-4631-b...
2012-09-18 20:30:03,828 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZooKeeperWatcher(342): hconnection 0xfa1b2d-0x139db12b83f0003 connected
2012-09-18 20:30:03,828 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] client.HConnectionManager$HConnectionImplementation(662): ClusterId is 5dbaab6f-b03b-4631-b4f3-dbaffefbe1e9
2012-09-18 20:30:03,829 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] catalog.CatalogTracker(240): Starting catalog tracker org.apache.hadoop.hbase.catalog.CatalogTracker@9d267d
2012-09-18 20:30:03,830 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] zookeeper.ZKUtil(237): regionserver:56450-0x139db12b83f0001 /hbase/root-region-server does not exist. Watcher is set.
2012-09-18 20:30:03,831 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] zookeeper.ZKUtil(237): regionserver:56450-0x139db12b83f0001 /hbase/unassigned/1028785192 does not exist. Watcher is set.
2012-09-18 20:30:03,834 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 42 byte(s) of data from znode /hbase/hbaseid; data=PBUF\x0A$5dbaab6f-b03b-4631-b...
2012-09-18 20:30:03,834 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(777): ClusterId : 5dbaab6f-b03b-4631-b4f3-dbaffefbe1e9
2012-09-18 20:30:03,836 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.MemStoreFlusher(111): globalMemStoreLimit=675.6m, globalMemStoreLimitLowMark=591.1m, maxHeap=1.6g
2012-09-18 20:30:03,841 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer$CompactionChecker(1325): Runs every 16mins, 40sec
2012-09-18 20:30:03,875 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(1937): Attempting connect to Master server at hemera.apache.org,57673,1348000201449
2012-09-18 20:30:03,903 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(1946): Connected to master at hemera.apache.org/140.211.11.27:57673
2012-09-18 20:30:03,904 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(1992): Telling master at hemera.apache.org,57673,1348000201449 that we are up with port=56450, startcode=1348000201701
2012-09-18 20:30:03,904 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(237): master:57673-0x139db12b83f0000 /hbase/acl does not exist. Watcher is set.
2012-09-18 20:30:03,911 INFO  [Master:0;hemera.apache.org,57673,1348000201449] coprocessor.CoprocessorHost(138): System coprocessor org.apache.hadoop.hbase.security.access.AccessController was loaded successfully with priority (536870911).
2012-09-18 20:30:03,914 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] executor.ExecutorService(132): Starting executor service name=MASTER_OPEN_REGION-hemera.apache.org,57673,1348000201449, corePoolSize=5, maxPoolSize=5
2012-09-18 20:30:03,914 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] executor.ExecutorService(132): Starting executor service name=MASTER_CLOSE_REGION-hemera.apache.org,57673,1348000201449, corePoolSize=5, maxPoolSize=5
2012-09-18 20:30:03,915 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] executor.ExecutorService(132): Starting executor service name=MASTER_SERVER_OPERATIONS-hemera.apache.org,57673,1348000201449, corePoolSize=3, maxPoolSize=3
2012-09-18 20:30:03,915 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] executor.ExecutorService(132): Starting executor service name=MASTER_META_SERVER_OPERATIONS-hemera.apache.org,57673,1348000201449, corePoolSize=5, maxPoolSize=5
2012-09-18 20:30:03,915 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] executor.ExecutorService(132): Starting executor service name=MASTER_TABLE_OPERATIONS-hemera.apache.org,57673,1348000201449, corePoolSize=1, maxPoolSize=1
2012-09-18 20:30:03,937 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] master.HMaster(1053): Started service threads
2012-09-18 20:30:03,937 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.ServerManager(672): Waiting for region servers count to settle; currently checked in 0, slept for 0 ms, expecting minimum of 1, maximum of 1, timeout of 4500 ms, interval of 1500 ms.
2012-09-18 20:30:03,948 INFO  [IPC Server handler 0 on 57673] master.ServerManager(307): Registering server=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:03,954 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(1171): Config from master: hbase.rootdir=hdfs://localhost:42338/user/jenkins/hbase
2012-09-18 20:30:03,954 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(1171): Config from master: fs.default.name=hdfs://localhost:42338
2012-09-18 20:30:03,954 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(1164): Master passed us hostname to use. Was=hemera.apache.org, Now=hemera.apache.org
2012-09-18 20:30:03,956 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/rs
2012-09-18 20:30:03,956 WARN  [RegionServer:0;hemera.apache.org,56450,1348000201701] hbase.ZNodeClearer(58): No filename given to save the znode used, it won't be saved (Environment variable HBASE_ZNODE_FILE is not set).
2012-09-18 20:30:03,958 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(235): master:57673-0x139db12b83f0000 Set watcher on existing znode /hbase/rs/hemera.apache.org,56450,1348000201701
2012-09-18 20:30:03,961 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] fs.HFileSystem(196): Starting addLocationsOrderInterceptor with class class org.apache.hadoop.hbase.fs.HFileSystem$ReorderWALBlocks
2012-09-18 20:30:03,962 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] fs.HFileSystem(243): Added intercepting call to namenode#getBlockLocations
2012-09-18 20:30:03,962 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(1386): logdir=hdfs://localhost:42338/user/jenkins/hbase/.logs/hemera.apache.org,56450,1348000201701
2012-09-18 20:30:03,964 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] wal.HLog(458): FileSystem doesn't support getDefaultBlockSize
2012-09-18 20:30:03,968 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] wal.HLog(429): HLog configuration: blocksize=64 MB, rollsize=60.8 MB, enabled=true, optionallogflushinternal=1000ms
2012-09-18 20:30:03,972 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] wal.SequenceFileLogWriter(189): using new createWriter -- HADOOP-6840
2012-09-18 20:30:03,973 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] wal.SequenceFileLogWriter(193): Path=hdfs://localhost:42338/user/jenkins/hbase/.logs/hemera.apache.org,56450,1348000201701/hemera.apache.org%2C56450%2C1348000201701.1348000203968, compression=false
2012-09-18 20:30:03,973 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] wal.HLog(653):  for /user/jenkins/hbase/.logs/hemera.apache.org,56450,1348000201701/hemera.apache.org%2C56450%2C1348000201701.1348000203968
2012-09-18 20:30:03,973 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] wal.HLog(501): Using getNumCurrentReplicas--HDFS-826
2012-09-18 20:30:03,996 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.ServerManager(689): Finished waiting for region servers count to settle; checked in 1, slept for 59 ms, expecting minimum of 1, maximum of 1, master is running.
2012-09-18 20:30:04,002 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.MasterFileSystem(228): Log folder hdfs://localhost:42338/user/jenkins/hbase/.logs/hemera.apache.org,56450,1348000201701 belongs to an existing region server
2012-09-18 20:30:04,002 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.MasterFileSystem(282): No logs to split
2012-09-18 20:30:04,008 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] metrics.MetricsMBeanBase(110): MetricsString added: revision
2012-09-18 20:30:04,008 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] metrics.MetricsMBeanBase(110): MetricsString added: hdfsUser
2012-09-18 20:30:04,008 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] metrics.MetricsMBeanBase(110): MetricsString added: hdfsDate
2012-09-18 20:30:04,008 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] metrics.MetricsMBeanBase(110): MetricsString added: hdfsUrl
2012-09-18 20:30:04,008 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] metrics.MetricsMBeanBase(110): MetricsString added: date
2012-09-18 20:30:04,009 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] metrics.MetricsMBeanBase(110): MetricsString added: hdfsRevision
2012-09-18 20:30:04,009 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] metrics.MetricsMBeanBase(110): MetricsString added: user
2012-09-18 20:30:04,009 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] metrics.MetricsMBeanBase(110): MetricsString added: hdfsVersion
2012-09-18 20:30:04,009 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] metrics.MetricsMBeanBase(110): MetricsString added: url
2012-09-18 20:30:04,009 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] metrics.MetricsMBeanBase(110): MetricsString added: version
2012-09-18 20:30:04,009 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] metrics.MetricsMBeanBase(161): new MBeanInfo
2012-09-18 20:30:04,011 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] metrics.MetricsMBeanBase(161): new MBeanInfo
2012-09-18 20:30:04,011 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] metrics.RegionServerMetrics(326): Initialized
2012-09-18 20:30:04,012 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] metrics.MetricsMBeanBase(161): new MBeanInfo
2012-09-18 20:30:04,012 ERROR [RegionServer:0;hemera.apache.org,56450,1348000201701] metrics.RegionServerDynamicMetrics(91): java.lang.NoSuchMethodException: org.apache.hadoop.hbase.metrics.MetricsMBeanBase.updateMbeanInfoIfMetricsListChanged()
2012-09-18 20:30:04,013 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] executor.ExecutorService(132): Starting executor service name=RS_OPEN_REGION-hemera.apache.org,56450,1348000201701, corePoolSize=3, maxPoolSize=3
2012-09-18 20:30:04,014 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] executor.ExecutorService(132): Starting executor service name=RS_OPEN_ROOT-hemera.apache.org,56450,1348000201701, corePoolSize=1, maxPoolSize=1
2012-09-18 20:30:04,014 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] executor.ExecutorService(132): Starting executor service name=RS_OPEN_META-hemera.apache.org,56450,1348000201701, corePoolSize=1, maxPoolSize=1
2012-09-18 20:30:04,014 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] executor.ExecutorService(132): Starting executor service name=RS_CLOSE_REGION-hemera.apache.org,56450,1348000201701, corePoolSize=3, maxPoolSize=3
2012-09-18 20:30:04,014 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] executor.ExecutorService(132): Starting executor service name=RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701, corePoolSize=1, maxPoolSize=1
2012-09-18 20:30:04,014 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] executor.ExecutorService(132): Starting executor service name=RS_CLOSE_META-hemera.apache.org,56450,1348000201701, corePoolSize=1, maxPoolSize=1
2012-09-18 20:30:04,022 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(1203): Serving as hemera.apache.org,56450,1348000201701, RPC listening on hemera.apache.org/140.211.11.27:56450, sessionid=0x139db12b83f0001
2012-09-18 20:30:04,022 INFO  [SplitLogWorker-hemera.apache.org,56450,1348000201701] regionserver.SplitLogWorker(136): SplitLogWorker hemera.apache.org,56450,1348000201701 starting
2012-09-18 20:30:04,023 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(2483): Registered RegionServer MXBean
2012-09-18 20:30:05,018 INFO  [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.RootRegionTracker(157): Unsetting ROOT region location in ZooKeeper
2012-09-18 20:30:05,020 WARN  [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.RecoverableZooKeeper(141): Node /hbase/root-region-server already deleted, and this is not a retry
2012-09-18 20:30:05,022 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.RegionStates(250): Region {NAME => '-ROOT-,,0', STARTKEY => '', ENDKEY => '', ENCODED => 70236052,} transitioned from {-ROOT-,,0.70236052 state=OFFLINE, ts=1348000204004, server=null} to {-ROOT-,,0.70236052 state=OFFLINE, ts=1348000205022, server=null}
2012-09-18 20:30:05,023 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.RegionStates(250): Region {NAME => '-ROOT-,,0', STARTKEY => '', ENDKEY => '', ENCODED => 70236052,} transitioned from {-ROOT-,,0.70236052 state=OFFLINE, ts=1348000205022, server=null} to {-ROOT-,,0.70236052 state=OFFLINE, ts=1348000205023, server=null}
2012-09-18 20:30:05,023 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKAssign(271): master:57673-0x139db12b83f0000 Creating (or updating) unassigned node for 70236052 with OFFLINE state
2012-09-18 20:30:05,032 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] master.AssignmentManager(1560): Setting table -ROOT- to ENABLED state.
2012-09-18 20:30:05,038 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] master.AssignmentManager(1821): No previous transition plan was found (or we are ignoring an existing plan) for -ROOT-,,0.70236052 so generated a random one; hri=-ROOT-,,0.70236052, src=, dest=hemera.apache.org,56450,1348000201701; 1 (online=1, available=1) available servers
2012-09-18 20:30:05,039 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.AssignmentManager(1579): Assigning region -ROOT-,,0.70236052 to hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,039 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.RegionStates(250): Region {NAME => '-ROOT-,,0', STARTKEY => '', ENDKEY => '', ENCODED => 70236052,} transitioned from {-ROOT-,,0.70236052 state=OFFLINE, ts=1348000205023, server=null} to {-ROOT-,,0.70236052 state=PENDING_OPEN, ts=1348000205039, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:05,039 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] master.ServerManager(619): New connection to hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,059 INFO  [PRI IPC Server handler 0 on 56450] regionserver.HRegionServer(3585): Received request to open region: -ROOT-,,0.70236052 on hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,064 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKAssign(762): regionserver:56450-0x139db12b83f0001 Attempting to transition node 70236052/-ROOT- from M_ZK_REGION_OFFLINE to RS_ZK_REGION_OPENING
2012-09-18 20:30:05,066 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 58 byte(s) of data from znode /hbase/unassigned/70236052; data=region=-ROOT-,,0, state=M_ZK_REGION_OFFLINE, servername=hemera.apache.org,57673,1348000201449, createTime=1348000205027, payload.length=0
2012-09-18 20:30:05,068 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/unassigned/70236052
2012-09-18 20:30:05,068 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKAssign(823): regionserver:56450-0x139db12b83f0001 Successfully transitioned node 70236052 from M_ZK_REGION_OFFLINE to RS_ZK_REGION_OPENING
2012-09-18 20:30:05,069 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(3904): Opening region: {NAME => '-ROOT-,,0', STARTKEY => '', ENDKEY => '', ENCODED => 70236052,}
2012-09-18 20:30:05,069 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 56 byte(s) of data from znode /hbase/unassigned/70236052 and set watcher; region=-ROOT-,,0, state=RS_ZK_REGION_OPENING, servername=hemera.apache.org,56450,1348000201701, createTime=1348000205066, payload.length=0
2012-09-18 20:30:05,070 DEBUG [pool-1-thread-1-EventThread] master.AssignmentManager(691): Handling transition=RS_ZK_REGION_OPENING, server=hemera.apache.org,56450,1348000201701, region=70236052/-ROOT-, current state from region state map ={-ROOT-,,0.70236052 state=PENDING_OPEN, ts=1348000205039, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:05,072 INFO  [pool-1-thread-1-EventThread] master.RegionStates(250): Region {NAME => '-ROOT-,,0', STARTKEY => '', ENDKEY => '', ENCODED => 70236052,} transitioned from {-ROOT-,,0.70236052 state=PENDING_OPEN, ts=1348000205039, server=hemera.apache.org,56450,1348000201701} to {-ROOT-,,0.70236052 state=OPENING, ts=1348000205066, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:05,080 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(5113): Registered protocol handler: region=-ROOT-,,0 protocol=org.apache.hadoop.hbase.security.access.AccessControllerProtocol
2012-09-18 20:30:05,218 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(5148): Registered coprocessor service: region=-ROOT-,,0 service=AccessControlService
2012-09-18 20:30:05,219 INFO  [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] coprocessor.CoprocessorHost(138): System coprocessor org.apache.hadoop.hbase.security.access.AccessController was loaded successfully with priority (536870911).
2012-09-18 20:30:05,219 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(474): Instantiated -ROOT-,,0.70236052
2012-09-18 20:30:05,225 INFO  [StoreOpenerThread--ROOT-,,0.70236052-1] regionserver.HStore(215): hbase.hstore.compaction.min = 3
2012-09-18 20:30:05,240 DEBUG [StoreOpenerThread--ROOT-,,0.70236052-1] regionserver.HStore(415): loaded hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/info/5971150f6ed745bda83363123504803a, isReference=false, isBulkLoadResult=false, seqid=2, majorCompaction=false
2012-09-18 20:30:05,244 INFO  [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(622): Onlined -ROOT-,,0.70236052; next sequenceid=3
2012-09-18 20:30:05,245 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKUtil(237): regionserver:56450-0x139db12b83f0001 /hbase/acl does not exist. Watcher is set.
2012-09-18 20:30:05,246 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKAssign(762): regionserver:56450-0x139db12b83f0001 Attempting to transition node 70236052/-ROOT- from RS_ZK_REGION_OPENING to RS_ZK_REGION_OPENING
2012-09-18 20:30:05,247 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 56 byte(s) of data from znode /hbase/unassigned/70236052; data=region=-ROOT-,,0, state=RS_ZK_REGION_OPENING, servername=hemera.apache.org,56450,1348000201701, createTime=1348000205066, payload.length=0
2012-09-18 20:30:05,249 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/unassigned/70236052
2012-09-18 20:30:05,249 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKAssign(823): regionserver:56450-0x139db12b83f0001 Successfully transitioned node 70236052 from RS_ZK_REGION_OPENING to RS_ZK_REGION_OPENING
2012-09-18 20:30:05,250 INFO  [PostOpenDeployTasks:70236052] regionserver.HRegionServer(1753): Post open deploy tasks for region=-ROOT-,,0.70236052, daughter=false
2012-09-18 20:30:05,250 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 56 byte(s) of data from znode /hbase/unassigned/70236052 and set watcher; region=-ROOT-,,0, state=RS_ZK_REGION_OPENING, servername=hemera.apache.org,56450,1348000201701, createTime=1348000205247, payload.length=0
2012-09-18 20:30:05,250 INFO  [PostOpenDeployTasks:70236052] zookeeper.RootRegionTracker(123): Setting ROOT region location in ZooKeeper as hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,250 DEBUG [pool-1-thread-1-EventThread] master.AssignmentManager(691): Handling transition=RS_ZK_REGION_OPENING, server=hemera.apache.org,56450,1348000201701, region=70236052/-ROOT-, current state from region state map ={-ROOT-,,0.70236052 state=OPENING, ts=1348000205066, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:05,251 INFO  [pool-1-thread-1-EventThread] master.RegionStates(250): Region {NAME => '-ROOT-,,0', STARTKEY => '', ENDKEY => '', ENCODED => 70236052,} transitioned from {-ROOT-,,0.70236052 state=OPENING, ts=1348000205066, server=hemera.apache.org,56450,1348000201701} to {-ROOT-,,0.70236052 state=OPENING, ts=1348000205247, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:05,252 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeCreated, state=SyncConnected, path=/hbase/root-region-server
2012-09-18 20:30:05,252 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZooKeeperWatcher(265): regionserver:56450-0x139db12b83f0001 Received ZooKeeper Event, type=NodeCreated, state=SyncConnected, path=/hbase/root-region-server
2012-09-18 20:30:05,253 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 36 byte(s) of data from znode /hbase/root-region-server and set watcher; hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,253 INFO  [PostOpenDeployTasks:70236052] regionserver.HRegionServer(1778): Done with post open deploy task for region=-ROOT-,,0.70236052, daughter=false
2012-09-18 20:30:05,254 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKAssign(762): regionserver:56450-0x139db12b83f0001 Attempting to transition node 70236052/-ROOT- from RS_ZK_REGION_OPENING to RS_ZK_REGION_OPENED
2012-09-18 20:30:05,254 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 36 byte(s) of data from znode /hbase/root-region-server and set watcher; hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,255 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 56 byte(s) of data from znode /hbase/unassigned/70236052; data=region=-ROOT-,,0, state=RS_ZK_REGION_OPENING, servername=hemera.apache.org,56450,1348000201701, createTime=1348000205247, payload.length=0
2012-09-18 20:30:05,256 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/unassigned/70236052
2012-09-18 20:30:05,256 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKAssign(823): regionserver:56450-0x139db12b83f0001 Successfully transitioned node 70236052 from RS_ZK_REGION_OPENING to RS_ZK_REGION_OPENED
2012-09-18 20:30:05,257 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] handler.OpenRegionHandler(285): region transitioned to opened in zookeeper: {NAME => '-ROOT-,,0', STARTKEY => '', ENDKEY => '', ENCODED => 70236052,}, server: hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,257 DEBUG [RS_OPEN_REGION-hemera.apache.org,56450,1348000201701-0] handler.OpenRegionHandler(141): Opened -ROOT-,,0.70236052 on server:hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,257 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 56 byte(s) of data from znode /hbase/unassigned/70236052 and set watcher; region=-ROOT-,,0, state=RS_ZK_REGION_OPENED, servername=hemera.apache.org,56450,1348000201701, createTime=1348000205255, payload.length=0
2012-09-18 20:30:05,258 DEBUG [pool-1-thread-1-EventThread] master.AssignmentManager(691): Handling transition=RS_ZK_REGION_OPENED, server=hemera.apache.org,56450,1348000201701, region=70236052/-ROOT-, current state from region state map ={-ROOT-,,0.70236052 state=OPENING, ts=1348000205247, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:05,258 INFO  [pool-1-thread-1-EventThread] master.RegionStates(250): Region {NAME => '-ROOT-,,0', STARTKEY => '', ENDKEY => '', ENCODED => 70236052,} transitioned from {-ROOT-,,0.70236052 state=OPENING, ts=1348000205247, server=hemera.apache.org,56450,1348000201701} to {-ROOT-,,0.70236052 state=OPEN, ts=1348000205255, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:05,260 INFO  [MASTER_OPEN_REGION-hemera.apache.org,57673,1348000201449-0] handler.OpenedRegionHandler(147): Handling OPENED event for -ROOT-,,0.70236052 from hemera.apache.org,56450,1348000201701; deleting unassigned node
2012-09-18 20:30:05,260 DEBUG [MASTER_OPEN_REGION-hemera.apache.org,57673,1348000201449-0] zookeeper.ZKAssign(491): master:57673-0x139db12b83f0000 Deleting existing unassigned node for 70236052 that is in expected state RS_ZK_REGION_OPENED
2012-09-18 20:30:05,261 DEBUG [MASTER_OPEN_REGION-hemera.apache.org,57673,1348000201449-0] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 56 byte(s) of data from znode /hbase/unassigned/70236052; data=region=-ROOT-,,0, state=RS_ZK_REGION_OPENED, servername=hemera.apache.org,56450,1348000201701, createTime=1348000205255, payload.length=0
2012-09-18 20:30:05,263 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/unassigned/70236052
2012-09-18 20:30:05,263 DEBUG [MASTER_OPEN_REGION-hemera.apache.org,57673,1348000201449-0] zookeeper.ZKAssign(520): master:57673-0x139db12b83f0000 Successfully deleted unassigned node for region 70236052 in expected state RS_ZK_REGION_OPENED
2012-09-18 20:30:05,263 DEBUG [pool-1-thread-1-EventThread] master.AssignmentManager(1053): The znode of region -ROOT-,,0.70236052 has been deleted.
2012-09-18 20:30:05,263 INFO  [pool-1-thread-1-EventThread] master.RegionStates(250): Region {NAME => '-ROOT-,,0', STARTKEY => '', ENDKEY => '', ENCODED => 70236052,} transitioned from {-ROOT-,,0.70236052 state=OPEN, ts=1348000205255, server=hemera.apache.org,56450,1348000201701} to {-ROOT-,,0.70236052 state=OPEN, ts=1348000205263, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:05,263 INFO  [pool-1-thread-1-EventThread] master.RegionStates(285): Onlined region {NAME => '-ROOT-,,0', STARTKEY => '', ENDKEY => '', ENCODED => 70236052,} on hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,264 INFO  [pool-1-thread-1-EventThread] master.AssignmentManager(1058): The master has opened the region -ROOT-,,0.70236052 that was online on hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,265 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 36 byte(s) of data from znode /hbase/root-region-server and set watcher; hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,265 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.HMaster(818): -ROOT- assigned=1, rit=false, location=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,278 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,279 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,279 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,282 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,283 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,284 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,382 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,383 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,383 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,383 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,384 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,384 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,437 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,438 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,438 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,438 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,439 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,439 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,492 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,493 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,493 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,494 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,495 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,495 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,548 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,549 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,549 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,549 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,550 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,550 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,603 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,604 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,604 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,604 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,605 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,605 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,657 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,658 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,659 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,659 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,660 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,660 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,712 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,713 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,714 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,714 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,715 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,715 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,767 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,768 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,768 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,768 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,769 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,770 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,822 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,823 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,823 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,823 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,824 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,824 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,875 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,877 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,877 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,877 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,878 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,878 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,930 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,932 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,932 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,932 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,933 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,933 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,986 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,987 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,987 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,987 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:05,988 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:05,989 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,041 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,042 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,042 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,042 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,043 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,043 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,094 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,095 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,096 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,096 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,096 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,096 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,149 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,150 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,151 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,151 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,152 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,152 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,205 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,206 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,206 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,207 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,208 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,208 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,260 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,262 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,262 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,263 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,263 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,264 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,316 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,317 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,318 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,318 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,319 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,319 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,321 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,322 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,322 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,323 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,323 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,324 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,325 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.RegionStates(250): Region {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,} transitioned from {.META.,,1.1028785192 state=OFFLINE, ts=1348000205265, server=null} to {.META.,,1.1028785192 state=OFFLINE, ts=1348000206325, server=null}
2012-09-18 20:30:06,326 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.RegionStates(250): Region {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,} transitioned from {.META.,,1.1028785192 state=OFFLINE, ts=1348000206325, server=null} to {.META.,,1.1028785192 state=OFFLINE, ts=1348000206326, server=null}
2012-09-18 20:30:06,326 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKAssign(271): master:57673-0x139db12b83f0000 Creating (or updating) unassigned node for 1028785192 with OFFLINE state
2012-09-18 20:30:06,328 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZooKeeperWatcher(265): regionserver:56450-0x139db12b83f0001 Received ZooKeeper Event, type=NodeCreated, state=SyncConnected, path=/hbase/unassigned/1028785192
2012-09-18 20:30:06,328 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeCreated, state=SyncConnected, path=/hbase/unassigned/1028785192
2012-09-18 20:30:06,329 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 58 byte(s) of data from znode /hbase/unassigned/1028785192 and set watcher; region=.META.,,1, state=M_ZK_REGION_OFFLINE, servername=hemera.apache.org,57673,1348000201449, createTime=1348000206326, payload.length=0
2012-09-18 20:30:06,329 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] master.AssignmentManager(1560): Setting table .META. to ENABLED state.
2012-09-18 20:30:06,330 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 58 byte(s) of data from znode /hbase/unassigned/1028785192 and set watcher; region=.META.,,1, state=M_ZK_REGION_OFFLINE, servername=hemera.apache.org,57673,1348000201449, createTime=1348000206326, payload.length=0
2012-09-18 20:30:06,330 DEBUG [pool-1-thread-1-EventThread] master.AssignmentManager(691): Handling transition=M_ZK_REGION_OFFLINE, server=hemera.apache.org,57673,1348000201449, region=1028785192/.META., current state from region state map ={.META.,,1.1028785192 state=OFFLINE, ts=1348000206326, server=null}
2012-09-18 20:30:06,331 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 58 byte(s) of data from znode /hbase/unassigned/1028785192 and set watcher; region=.META.,,1, state=M_ZK_REGION_OFFLINE, servername=hemera.apache.org,57673,1348000201449, createTime=1348000206326, payload.length=0
2012-09-18 20:30:06,333 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] master.AssignmentManager(1821): No previous transition plan was found (or we are ignoring an existing plan) for .META.,,1.1028785192 so generated a random one; hri=.META.,,1.1028785192, src=, dest=hemera.apache.org,56450,1348000201701; 1 (online=1, available=1) available servers
2012-09-18 20:30:06,333 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.AssignmentManager(1579): Assigning region .META.,,1.1028785192 to hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,333 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.RegionStates(250): Region {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,} transitioned from {.META.,,1.1028785192 state=OFFLINE, ts=1348000206326, server=null} to {.META.,,1.1028785192 state=PENDING_OPEN, ts=1348000206333, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:06,333 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] master.ServerManager(619): New connection to hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,334 INFO  [PRI IPC Server handler 1 on 56450] regionserver.HRegionServer(3585): Received request to open region: .META.,,1.1028785192 on hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,335 DEBUG [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKAssign(762): regionserver:56450-0x139db12b83f0001 Attempting to transition node 1028785192/.META. from M_ZK_REGION_OFFLINE to RS_ZK_REGION_OPENING
2012-09-18 20:30:06,335 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,336 DEBUG [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 58 byte(s) of data from znode /hbase/unassigned/1028785192; data=region=.META.,,1, state=M_ZK_REGION_OFFLINE, servername=hemera.apache.org,57673,1348000201449, createTime=1348000206326, payload.length=0
2012-09-18 20:30:06,336 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,337 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,337 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,338 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZooKeeperWatcher(265): regionserver:56450-0x139db12b83f0001 Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/unassigned/1028785192
2012-09-18 20:30:06,338 DEBUG [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKAssign(823): regionserver:56450-0x139db12b83f0001 Successfully transitioned node 1028785192 from M_ZK_REGION_OFFLINE to RS_ZK_REGION_OPENING
2012-09-18 20:30:06,338 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,338 DEBUG [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(3904): Opening region: {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,}
2012-09-18 20:30:06,338 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/unassigned/1028785192
2012-09-18 20:30:06,338 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,339 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 56 byte(s) of data from znode /hbase/unassigned/1028785192 and set watcher; region=.META.,,1, state=RS_ZK_REGION_OPENING, servername=hemera.apache.org,56450,1348000201701, createTime=1348000206336, payload.length=0
2012-09-18 20:30:06,339 DEBUG [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(5113): Registered protocol handler: region=.META.,,1 protocol=org.apache.hadoop.hbase.security.access.AccessControllerProtocol
2012-09-18 20:30:06,339 DEBUG [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(5148): Registered coprocessor service: region=.META.,,1 service=AccessControlService
2012-09-18 20:30:06,340 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 56 byte(s) of data from znode /hbase/unassigned/1028785192 and set watcher; region=.META.,,1, state=RS_ZK_REGION_OPENING, servername=hemera.apache.org,56450,1348000201701, createTime=1348000206336, payload.length=0
2012-09-18 20:30:06,340 INFO  [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] coprocessor.CoprocessorHost(138): System coprocessor org.apache.hadoop.hbase.security.access.AccessController was loaded successfully with priority (536870911).
2012-09-18 20:30:06,340 DEBUG [pool-1-thread-1-EventThread] master.AssignmentManager(691): Handling transition=RS_ZK_REGION_OPENING, server=hemera.apache.org,56450,1348000201701, region=1028785192/.META., current state from region state map ={.META.,,1.1028785192 state=PENDING_OPEN, ts=1348000206333, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:06,340 DEBUG [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(474): Instantiated .META.,,1.1028785192
2012-09-18 20:30:06,341 INFO  [pool-1-thread-1-EventThread] master.RegionStates(250): Region {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,} transitioned from {.META.,,1.1028785192 state=PENDING_OPEN, ts=1348000206333, server=hemera.apache.org,56450,1348000201701} to {.META.,,1.1028785192 state=OPENING, ts=1348000206336, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:06,342 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 56 byte(s) of data from znode /hbase/unassigned/1028785192 and set watcher; region=.META.,,1, state=RS_ZK_REGION_OPENING, servername=hemera.apache.org,56450,1348000201701, createTime=1348000206336, payload.length=0
2012-09-18 20:30:06,345 INFO  [StoreOpenerThread-.META.,,1.1028785192-1] regionserver.HStore(215): hbase.hstore.compaction.min = 3
2012-09-18 20:30:06,350 INFO  [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(622): Onlined .META.,,1.1028785192; next sequenceid=1
2012-09-18 20:30:06,350 DEBUG [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKAssign(762): regionserver:56450-0x139db12b83f0001 Attempting to transition node 1028785192/.META. from RS_ZK_REGION_OPENING to RS_ZK_REGION_OPENING
2012-09-18 20:30:06,351 DEBUG [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 56 byte(s) of data from znode /hbase/unassigned/1028785192; data=region=.META.,,1, state=RS_ZK_REGION_OPENING, servername=hemera.apache.org,56450,1348000201701, createTime=1348000206336, payload.length=0
2012-09-18 20:30:06,353 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZooKeeperWatcher(265): regionserver:56450-0x139db12b83f0001 Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/unassigned/1028785192
2012-09-18 20:30:06,353 DEBUG [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKAssign(823): regionserver:56450-0x139db12b83f0001 Successfully transitioned node 1028785192 from RS_ZK_REGION_OPENING to RS_ZK_REGION_OPENING
2012-09-18 20:30:06,353 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/unassigned/1028785192
2012-09-18 20:30:06,353 INFO  [PostOpenDeployTasks:1028785192] regionserver.HRegionServer(1753): Post open deploy tasks for region=.META.,,1.1028785192, daughter=false
2012-09-18 20:30:06,354 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 56 byte(s) of data from znode /hbase/unassigned/1028785192 and set watcher; region=.META.,,1, state=RS_ZK_REGION_OPENING, servername=hemera.apache.org,56450,1348000201701, createTime=1348000206352, payload.length=0
2012-09-18 20:30:06,354 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 56 byte(s) of data from znode /hbase/unassigned/1028785192 and set watcher; region=.META.,,1, state=RS_ZK_REGION_OPENING, servername=hemera.apache.org,56450,1348000201701, createTime=1348000206352, payload.length=0
2012-09-18 20:30:06,354 DEBUG [pool-1-thread-1-EventThread] master.AssignmentManager(691): Handling transition=RS_ZK_REGION_OPENING, server=hemera.apache.org,56450,1348000201701, region=1028785192/.META., current state from region state map ={.META.,,1.1028785192 state=OPENING, ts=1348000206336, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:06,355 INFO  [pool-1-thread-1-EventThread] master.RegionStates(250): Region {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,} transitioned from {.META.,,1.1028785192 state=OPENING, ts=1348000206336, server=hemera.apache.org,56450,1348000201701} to {.META.,,1.1028785192 state=OPENING, ts=1348000206352, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:06,355 DEBUG [PostOpenDeployTasks:1028785192] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0xfa1b2d
2012-09-18 20:30:06,356 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 56 byte(s) of data from znode /hbase/unassigned/1028785192 and set watcher; region=.META.,,1, state=RS_ZK_REGION_OPENING, servername=hemera.apache.org,56450,1348000201701, createTime=1348000206352, payload.length=0
2012-09-18 20:30:06,356 DEBUG [PostOpenDeployTasks:1028785192] zookeeper.ZKUtil(1141): hconnection 0xfa1b2d-0x139db12b83f0003 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,357 DEBUG [PostOpenDeployTasks:1028785192] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0xfa1b2d; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,358 DEBUG [PostOpenDeployTasks:1028785192] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0xfa1b2d
2012-09-18 20:30:06,359 DEBUG [PostOpenDeployTasks:1028785192] zookeeper.ZKUtil(1141): hconnection 0xfa1b2d-0x139db12b83f0003 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,359 DEBUG [PostOpenDeployTasks:1028785192] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0xfa1b2d; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,391 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,392 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,392 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,392 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,393 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,393 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,411 INFO  [PostOpenDeployTasks:1028785192] catalog.MetaEditor(307): Updated row .META.,,1.1028785192 with server=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,412 INFO  [PostOpenDeployTasks:1028785192] regionserver.HRegionServer(1778): Done with post open deploy task for region=.META.,,1.1028785192, daughter=false
2012-09-18 20:30:06,412 DEBUG [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKAssign(762): regionserver:56450-0x139db12b83f0001 Attempting to transition node 1028785192/.META. from RS_ZK_REGION_OPENING to RS_ZK_REGION_OPENED
2012-09-18 20:30:06,413 DEBUG [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 56 byte(s) of data from znode /hbase/unassigned/1028785192; data=region=.META.,,1, state=RS_ZK_REGION_OPENING, servername=hemera.apache.org,56450,1348000201701, createTime=1348000206352, payload.length=0
2012-09-18 20:30:06,415 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZooKeeperWatcher(265): regionserver:56450-0x139db12b83f0001 Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/unassigned/1028785192
2012-09-18 20:30:06,415 DEBUG [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] zookeeper.ZKAssign(823): regionserver:56450-0x139db12b83f0001 Successfully transitioned node 1028785192 from RS_ZK_REGION_OPENING to RS_ZK_REGION_OPENED
2012-09-18 20:30:06,415 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/unassigned/1028785192
2012-09-18 20:30:06,416 DEBUG [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] handler.OpenRegionHandler(285): region transitioned to opened in zookeeper: {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,}, server: hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,416 DEBUG [RS_OPEN_META-hemera.apache.org,56450,1348000201701-0] handler.OpenRegionHandler(141): Opened .META.,,1.1028785192 on server:hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,416 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 56 byte(s) of data from znode /hbase/unassigned/1028785192 and set watcher; region=.META.,,1, state=RS_ZK_REGION_OPENED, servername=hemera.apache.org,56450,1348000201701, createTime=1348000206414, payload.length=0
2012-09-18 20:30:06,417 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 56 byte(s) of data from znode /hbase/unassigned/1028785192 and set watcher; region=.META.,,1, state=RS_ZK_REGION_OPENED, servername=hemera.apache.org,56450,1348000201701, createTime=1348000206414, payload.length=0
2012-09-18 20:30:06,417 DEBUG [pool-1-thread-1-EventThread] master.AssignmentManager(691): Handling transition=RS_ZK_REGION_OPENED, server=hemera.apache.org,56450,1348000201701, region=1028785192/.META., current state from region state map ={.META.,,1.1028785192 state=OPENING, ts=1348000206352, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:06,417 INFO  [pool-1-thread-1-EventThread] master.RegionStates(250): Region {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,} transitioned from {.META.,,1.1028785192 state=OPENING, ts=1348000206352, server=hemera.apache.org,56450,1348000201701} to {.META.,,1.1028785192 state=OPEN, ts=1348000206414, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:06,418 INFO  [MASTER_OPEN_REGION-hemera.apache.org,57673,1348000201449-1] handler.OpenedRegionHandler(147): Handling OPENED event for .META.,,1.1028785192 from hemera.apache.org,56450,1348000201701; deleting unassigned node
2012-09-18 20:30:06,418 DEBUG [MASTER_OPEN_REGION-hemera.apache.org,57673,1348000201449-1] zookeeper.ZKAssign(491): master:57673-0x139db12b83f0000 Deleting existing unassigned node for 1028785192 that is in expected state RS_ZK_REGION_OPENED
2012-09-18 20:30:06,419 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 56 byte(s) of data from znode /hbase/unassigned/1028785192 and set watcher; region=.META.,,1, state=RS_ZK_REGION_OPENED, servername=hemera.apache.org,56450,1348000201701, createTime=1348000206414, payload.length=0
2012-09-18 20:30:06,419 DEBUG [MASTER_OPEN_REGION-hemera.apache.org,57673,1348000201449-1] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 56 byte(s) of data from znode /hbase/unassigned/1028785192; data=region=.META.,,1, state=RS_ZK_REGION_OPENED, servername=hemera.apache.org,56450,1348000201701, createTime=1348000206414, payload.length=0
2012-09-18 20:30:06,421 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZooKeeperWatcher(265): regionserver:56450-0x139db12b83f0001 Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/unassigned/1028785192
2012-09-18 20:30:06,421 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/unassigned/1028785192
2012-09-18 20:30:06,421 DEBUG [MASTER_OPEN_REGION-hemera.apache.org,57673,1348000201449-1] zookeeper.ZKAssign(520): master:57673-0x139db12b83f0000 Successfully deleted unassigned node for region 1028785192 in expected state RS_ZK_REGION_OPENED
2012-09-18 20:30:06,421 DEBUG [pool-1-thread-1-EventThread] master.AssignmentManager(1053): The znode of region .META.,,1.1028785192 has been deleted.
2012-09-18 20:30:06,421 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] catalog.CatalogTracker(528): Current cached META location, null, is not valid, resetting
2012-09-18 20:30:06,421 INFO  [pool-1-thread-1-EventThread] master.RegionStates(250): Region {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,} transitioned from {.META.,,1.1028785192 state=OPEN, ts=1348000206414, server=hemera.apache.org,56450,1348000201701} to {.META.,,1.1028785192 state=OPEN, ts=1348000206421, server=hemera.apache.org,56450,1348000201701}
2012-09-18 20:30:06,421 INFO  [pool-1-thread-1-EventThread] master.RegionStates(285): Onlined region {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,} on hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,421 INFO  [pool-1-thread-1-EventThread] master.AssignmentManager(1058): The master has opened the region .META.,,1.1028785192 that was online on hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,422 DEBUG [pool-1-thread-1-EventThread] catalog.CatalogTracker(528): Current cached META location, null, is not valid, resetting
2012-09-18 20:30:06,422 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,423 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,423 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,423 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,424 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,425 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,434 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] catalog.CatalogTracker(540): Set new cached META location: hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,434 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.HMaster(848): .META. assigned=2, rit=false, location=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,435 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,436 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,437 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,439 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(94): Creating scanner over -ROOT- starting at key ''
2012-09-18 20:30:06,439 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(205): Advancing internal scanner to startKey at ''
2012-09-18 20:30:06,440 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,441 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,441 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,459 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(192): Finished with scanning at {NAME => '-ROOT-,,0', STARTKEY => '', ENDKEY => '', ENCODED => 70236052,}
2012-09-18 20:30:06,460 INFO  [Master:0;hemera.apache.org,57673,1348000201449] catalog.MetaMigrationConvertingToPB(217): Meta version=1; migrated=true
2012-09-18 20:30:06,460 INFO  [Master:0;hemera.apache.org,57673,1348000201449] catalog.MetaMigrationConvertingToPB(133): ROOT/META already up-to date with PB serialization
2012-09-18 20:30:06,461 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,462 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,462 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,471 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.MetaScanner(252): Current INFO from scan results = {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,}
2012-09-18 20:30:06,472 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.HConnectionManager$HConnectionImplementation(1314): Cached location for .META.,,1.1028785192 is hemera.apache.org:56450
2012-09-18 20:30:06,472 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(94): Creating scanner over .META. starting at key ''
2012-09-18 20:30:06,473 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(205): Advancing internal scanner to startKey at ''
2012-09-18 20:30:06,476 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(192): Finished with scanning at {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,}
2012-09-18 20:30:06,478 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.AssignmentManager(405): Clean cluster startup. Assigning userregions
2012-09-18 20:30:06,478 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKAssign(538): master:57673-0x139db12b83f0000 Deleting any existing unassigned nodes
2012-09-18 20:30:06,480 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(94): Creating scanner over .META. starting at key ''
2012-09-18 20:30:06,480 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(205): Advancing internal scanner to startKey at ''
2012-09-18 20:30:06,484 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(192): Finished with scanning at {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,}
2012-09-18 20:30:06,486 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(94): Creating scanner over .META. starting at key ''
2012-09-18 20:30:06,487 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(205): Advancing internal scanner to startKey at ''
2012-09-18 20:30:06,490 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(192): Finished with scanning at {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,}
2012-09-18 20:30:06,492 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.HMaster(709): Master has completed initialization
2012-09-18 20:30:06,493 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(94): Creating scanner over .META. starting at key '_acl_,,'
2012-09-18 20:30:06,493 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(205): Advancing internal scanner to startKey at '_acl_,,'
2012-09-18 20:30:06,494 DEBUG [hemera.apache.org,57673,1348000201449-CatalogJanitor] client.ClientScanner(94): Creating scanner over .META. starting at key ''
2012-09-18 20:30:06,494 DEBUG [hemera.apache.org,57673,1348000201449-CatalogJanitor] client.ClientScanner(205): Advancing internal scanner to startKey at ''
2012-09-18 20:30:06,498 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(192): Finished with scanning at {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,}
2012-09-18 20:30:06,499 DEBUG [hemera.apache.org,57673,1348000201449-CatalogJanitor] client.ClientScanner(192): Finished with scanning at {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,}
2012-09-18 20:30:06,499 DEBUG [hemera.apache.org,57673,1348000201449-CatalogJanitor] master.CatalogJanitor(171): Scanned 0 catalog row(s) and gc'd 0 unreferenced parent region(s)
2012-09-18 20:30:06,505 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(94): Creating scanner over .META. starting at key '_acl_,,'
2012-09-18 20:30:06,506 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(205): Advancing internal scanner to startKey at '_acl_,,'
2012-09-18 20:30:06,509 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] client.ClientScanner(192): Finished with scanning at {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,}
2012-09-18 20:30:06,513 INFO  [MASTER_TABLE_OPERATIONS-hemera.apache.org,57673,1348000201449-0] handler.CreateTableHandler(127): Attempting to create the table _acl_
2012-09-18 20:30:06,527 DEBUG [pool-1-thread-1] zookeeper.ZKUtil(102): hconnection 0xb125bd opening connection to ZooKeeper with ensemble (localhost:54880)
2012-09-18 20:30:06,528 INFO  [pool-1-thread-1] zookeeper.RecoverableZooKeeper(101): The identifier of this process is 25567@hemera
2012-09-18 20:30:06,530 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): hconnection 0xb125bd Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2012-09-18 20:30:06,531 DEBUG [pool-1-thread-1] zookeeper.ZKUtil(1141): hconnection 0xb125bd Retrieved 42 byte(s) of data from znode /hbase/hbaseid; data=PBUF\x0A$5dbaab6f-b03b-4631-b...
2012-09-18 20:30:06,531 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(342): hconnection 0xb125bd-0x139db12b83f0004 connected
2012-09-18 20:30:06,531 INFO  [pool-1-thread-1] client.HConnectionManager$HConnectionImplementation(662): ClusterId is 5dbaab6f-b03b-4631-b4f3-dbaffefbe1e9
2012-09-18 20:30:06,532 DEBUG [pool-1-thread-1] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0xb125bd
2012-09-18 20:30:06,533 DEBUG [pool-1-thread-1] zookeeper.ZKUtil(1141): hconnection 0xb125bd-0x139db12b83f0004 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,533 DEBUG [pool-1-thread-1] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0xb125bd; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,536 DEBUG [pool-1-thread-1] client.MetaScanner(252): Current INFO from scan results = {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,}
2012-09-18 20:30:06,537 DEBUG [pool-1-thread-1] client.HConnectionManager$HConnectionImplementation(1314): Cached location for .META.,,1.1028785192 is hemera.apache.org:56450
2012-09-18 20:30:06,537 DEBUG [pool-1-thread-1] client.ClientScanner(94): Creating scanner over .META. starting at key ''
2012-09-18 20:30:06,537 DEBUG [pool-1-thread-1] client.ClientScanner(205): Advancing internal scanner to startKey at ''
2012-09-18 20:30:06,542 DEBUG [pool-1-thread-1] client.ClientScanner(192): Finished with scanning at {NAME => '.META.,,1', STARTKEY => '', ENDKEY => '', ENCODED => 1028785192,}
2012-09-18 20:30:06,542 INFO  [pool-1-thread-1] client.HConnectionManager$HConnectionImplementation(1523): Closing zookeeper sessionid=0x139db12b83f0004
2012-09-18 20:30:06,555 DEBUG [pool-1-thread-1] zookeeper.ZKUtil(102): hconnection 0x15c9f9d opening connection to ZooKeeper with ensemble (localhost:54880)
2012-09-18 20:30:06,556 INFO  [pool-1-thread-1] zookeeper.RecoverableZooKeeper(101): The identifier of this process is 25567@hemera
2012-09-18 20:30:06,558 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): hconnection 0x15c9f9d Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2012-09-18 20:30:06,560 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(342): hconnection 0x15c9f9d-0x139db12b83f0005 connected
2012-09-18 20:30:06,560 DEBUG [pool-1-thread-1] zookeeper.ZKUtil(1141): hconnection 0x15c9f9d-0x139db12b83f0005 Retrieved 42 byte(s) of data from znode /hbase/hbaseid; data=PBUF\x0A$5dbaab6f-b03b-4631-b...
2012-09-18 20:30:06,560 INFO  [pool-1-thread-1] client.HConnectionManager$HConnectionImplementation(662): ClusterId is 5dbaab6f-b03b-4631-b4f3-dbaffefbe1e9
2012-09-18 20:30:06,560 INFO  [pool-1-thread-1] hbase.HBaseTestingUtility(705): Minicluster is up
2012-09-18 20:30:06,561 DEBUG [pool-1-thread-1] zookeeper.ZKUtil(102): TestZKPermissionsWatcher_1 opening connection to ZooKeeper with ensemble (localhost:54880)
2012-09-18 20:30:06,562 INFO  [pool-1-thread-1] zookeeper.RecoverableZooKeeper(101): The identifier of this process is 25567@hemera
2012-09-18 20:30:06,564 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): TestZKPermissionsWatcher_1 Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2012-09-18 20:30:06,564 DEBUG [pool-1-thread-1] zookeeper.ZKUtil(237): TestZKPermissionsWatcher_1 /hbase/acl does not exist. Watcher is set.
2012-09-18 20:30:06,565 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(342): TestZKPermissionsWatcher_1-0x139db12b83f0006 connected
2012-09-18 20:30:06,566 DEBUG [pool-1-thread-1] zookeeper.ZKUtil(102): TestZKPermissionsWatcher_2 opening connection to ZooKeeper with ensemble (localhost:54880)
2012-09-18 20:30:06,567 INFO  [pool-1-thread-1] zookeeper.RecoverableZooKeeper(101): The identifier of this process is 25567@hemera
2012-09-18 20:30:06,569 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): TestZKPermissionsWatcher_2 Received ZooKeeper Event, type=None, state=SyncConnected, path=null
2012-09-18 20:30:06,569 DEBUG [pool-1-thread-1] zookeeper.ZKUtil(237): TestZKPermissionsWatcher_2 /hbase/acl does not exist. Watcher is set.
2012-09-18 20:30:06,570 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(342): TestZKPermissionsWatcher_2-0x139db12b83f0007 connected
2012-09-18 20:30:06,573 DEBUG [pool-1-thread-1] access.TableAuthManager(253): No permissions found for table=perms_test
2012-09-18 20:30:06,574 DEBUG [pool-1-thread-1] access.TableAuthManager(253): No permissions found for table=perms_test
2012-09-18 20:30:06,574 DEBUG [pool-1-thread-1] access.TableAuthManager(253): No permissions found for table=perms_test
2012-09-18 20:30:06,574 DEBUG [pool-1-thread-1] access.TableAuthManager(253): No permissions found for table=perms_test
2012-09-18 20:30:06,574 DEBUG [pool-1-thread-1] access.TableAuthManager(253): No permissions found for table=perms_test
2012-09-18 20:30:06,574 DEBUG [pool-1-thread-1] access.TableAuthManager(253): No permissions found for table=perms_test
2012-09-18 20:30:06,575 DEBUG [pool-1-thread-1] access.TableAuthManager(253): No permissions found for table=perms_test
2012-09-18 20:30:06,575 DEBUG [pool-1-thread-1] access.TableAuthManager(253): No permissions found for table=perms_test
2012-09-18 20:30:06,584 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZooKeeperWatcher(265): regionserver:56450-0x139db12b83f0001 Received ZooKeeper Event, type=NodeCreated, state=SyncConnected, path=/hbase/acl
2012-09-18 20:30:06,584 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): TestZKPermissionsWatcher_2-0x139db12b83f0007 Received ZooKeeper Event, type=NodeCreated, state=SyncConnected, path=/hbase/acl
2012-09-18 20:30:06,584 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): TestZKPermissionsWatcher_1-0x139db12b83f0006 Received ZooKeeper Event, type=NodeCreated, state=SyncConnected, path=/hbase/acl
2012-09-18 20:30:06,584 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeCreated, state=SyncConnected, path=/hbase/acl
2012-09-18 20:30:06,586 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZooKeeperWatcher(265): regionserver:56450-0x139db12b83f0001 Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/acl
2012-09-18 20:30:06,588 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 0 byte(s) of data from znode /hbase/acl/perms_test and set watcher; empty
2012-09-18 20:30:06,588 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/acl/perms_test
2012-09-18 20:30:06,589 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): TestZKPermissionsWatcher_2-0x139db12b83f0007 Retrieved 32 byte(s) of data from znode /hbase/acl/perms_test and set watcher; PBUF\x0A\x1A\x0A\x06george\x1...
2012-09-18 20:30:06,589 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): TestZKPermissionsWatcher_1-0x139db12b83f0006 Retrieved 32 byte(s) of data from znode /hbase/acl/perms_test and set watcher; PBUF\x0A\x1A\x0A\x06george\x1...
2012-09-18 20:30:06,589 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 32 byte(s) of data from znode /hbase/acl/perms_test and set watcher; PBUF\x0A\x1A\x0A\x06george\x1...
2012-09-18 20:30:06,590 DEBUG [pool-1-thread-1-EventThread] access.ZKPermissionWatcher(132): Updating permissions cache from node perms_test with data: PBUF\x0A\x1A\x0A\x06george\x12\x10\x08\x00\x08\x01\x12\x0Aperms_test
2012-09-18 20:30:06,590 DEBUG [pool-1-thread-1-EventThread] access.ZKPermissionWatcher(132): Updating permissions cache from node perms_test with data: PBUF\x0A\x1A\x0A\x06george\x12\x10\x08\x00\x08\x01\x12\x0Aperms_test
2012-09-18 20:30:06,590 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] access.ZKPermissionWatcher(132): Updating permissions cache from node perms_test with data: PBUF\x0A\x1A\x0A\x06george\x12\x10\x08\x00\x08\x01\x12\x0Aperms_test
2012-09-18 20:30:06,591 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 32 byte(s) of data from znode /hbase/acl/perms_test and set watcher; PBUF\x0A\x1A\x0A\x06george\x1...
2012-09-18 20:30:06,691 ERROR [pool-1-thread-1] zookeeper.RecoverableZooKeeper(443): Node /hbase/acl/perms_test already exists and this is not a retry
2012-09-18 20:30:06,693 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZooKeeperWatcher(265): regionserver:56450-0x139db12b83f0001 Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/acl/perms_test
2012-09-18 20:30:06,693 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): TestZKPermissionsWatcher_2-0x139db12b83f0007 Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/acl/perms_test
2012-09-18 20:30:06,693 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): TestZKPermissionsWatcher_1-0x139db12b83f0006 Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/acl/perms_test
2012-09-18 20:30:06,693 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/acl/perms_test
2012-09-18 20:30:06,857 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZKUtil(1141): regionserver:56450-0x139db12b83f0001 Retrieved 58 byte(s) of data from znode /hbase/acl/perms_test and set watcher; PBUF\x0A\x1A\x0A\x06george\x1...
2012-09-18 20:30:06,858 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 58 byte(s) of data from znode /hbase/acl/perms_test and set watcher; PBUF\x0A\x1A\x0A\x06george\x1...
2012-09-18 20:30:06,858 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): TestZKPermissionsWatcher_2-0x139db12b83f0007 Retrieved 58 byte(s) of data from znode /hbase/acl/perms_test and set watcher; PBUF\x0A\x1A\x0A\x06george\x1...
2012-09-18 20:30:06,858 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(1141): TestZKPermissionsWatcher_1-0x139db12b83f0006 Retrieved 58 byte(s) of data from znode /hbase/acl/perms_test and set watcher; PBUF\x0A\x1A\x0A\x06george\x1...
2012-09-18 20:30:06,859 INFO  [pool-1-thread-1] hbase.HBaseTestingUtility(747): Shutting down minicluster
2012-09-18 20:30:06,860 INFO  [pool-1-thread-1] client.HConnectionManager$HConnectionImplementation(1523): Closing zookeeper sessionid=0x139db12b83f0005
2012-09-18 20:30:06,861 DEBUG [pool-1-thread-1] util.JVMClusterUtil(223): Shutting down HBase Cluster
2012-09-18 20:30:06,861 INFO  [pool-1-thread-1] master.HMaster(2049): Cluster shutdown requested
2012-09-18 20:30:06,862 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.ServerManager(398): Waiting on regionserver(s) to go down hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,862 INFO  [hemera.apache.org,57673,1348000201449-CatalogJanitor] hbase.Chore(81): hemera.apache.org,57673,1348000201449-CatalogJanitor exiting
2012-09-18 20:30:06,862 INFO  [hemera.apache.org,57673,1348000201449-BalancerChore] hbase.Chore(81): hemera.apache.org,57673,1348000201449-BalancerChore exiting
2012-09-18 20:30:06,863 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZooKeeperWatcher(265): regionserver:56450-0x139db12b83f0001 Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/shutdown
2012-09-18 20:30:06,863 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/shutdown
2012-09-18 20:30:06,863 INFO  [pool-1-thread-1] regionserver.HRegionServer(1737): STOPPED: Shutdown requested
2012-09-18 20:30:06,863 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701-EventThread] zookeeper.ZKUtil(237): regionserver:56450-0x139db12b83f0001 /hbase/shutdown does not exist. Watcher is set.
2012-09-18 20:30:06,863 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZKUtil(237): master:57673-0x139db12b83f0000 /hbase/shutdown does not exist. Watcher is set.
2012-09-18 20:30:06,864 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.SplitLogWorker(522): Sending interrupt to stop the worker thread
2012-09-18 20:30:06,864 INFO  [SplitLogWorker-hemera.apache.org,56450,1348000201701] regionserver.SplitLogWorker(206): SplitLogWorker interrupted while waiting for task, exiting: java.lang.InterruptedException
2012-09-18 20:30:06,865 INFO  [SplitLogWorker-hemera.apache.org,56450,1348000201701] regionserver.SplitLogWorker(170): SplitLogWorker hemera.apache.org,56450,1348000201701 exiting
2012-09-18 20:30:06,865 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701.compactionChecker] hbase.Chore(81): RegionServer:0;hemera.apache.org,56450,1348000201701.compactionChecker exiting
2012-09-18 20:30:06,865 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701.logRoller] regionserver.LogRoller(118): LogRoller exiting.
2012-09-18 20:30:06,866 DEBUG [pool-1-thread-1.LruBlockCache.EvictionThread] hfile.LruBlockCache(418): Block cache LRU eviction started; Attempting to free -408721.42 KB of total=1.98 MB
2012-09-18 20:30:06,865 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701.cacheFlusher] regionserver.MemStoreFlusher(264): RegionServer:0;hemera.apache.org,56450,1348000201701.cacheFlusher exiting
2012-09-18 20:30:06,865 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(947): stopping server hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,866 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] catalog.CatalogTracker(257): Stopping catalog tracker org.apache.hadoop.hbase.catalog.CatalogTracker@9d267d
2012-09-18 20:30:06,866 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] client.HConnectionManager$HConnectionImplementation(1523): Closing zookeeper sessionid=0x139db12b83f0003
2012-09-18 20:30:06,867 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.CompactSplitThread(253): Waiting for Split Thread to finish...
2012-09-18 20:30:06,868 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.CompactSplitThread(253): Waiting for Large Compaction Thread to finish...
2012-09-18 20:30:06,868 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.CompactSplitThread(253): Waiting for Small Compaction Thread to finish...
2012-09-18 20:30:06,869 DEBUG [RS_CLOSE_META-hemera.apache.org,56450,1348000201701-0] handler.CloseRegionHandler(124): Processing close of .META.,,1.1028785192
2012-09-18 20:30:06,869 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(1091): Waiting on 2 regions to close
2012-09-18 20:30:06,869 DEBUG [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] handler.CloseRegionHandler(124): Processing close of -ROOT-,,0.70236052
2012-09-18 20:30:06,869 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(1095): {1028785192=.META.,,1.1028785192, 70236052=-ROOT-,,0.70236052}
2012-09-18 20:30:06,869 DEBUG [RS_CLOSE_META-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(954): Closing .META.,,1.1028785192: disabling compactions & flushes
2012-09-18 20:30:06,870 DEBUG [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(954): Closing -ROOT-,,0.70236052: disabling compactions & flushes
2012-09-18 20:30:06,870 DEBUG [RS_CLOSE_META-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(975): Updates disabled for region .META.,,1.1028785192
2012-09-18 20:30:06,870 DEBUG [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(975): Updates disabled for region -ROOT-,,0.70236052
2012-09-18 20:30:06,870 DEBUG [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(1481): Started memstore flush for -ROOT-,,0.70236052, current region memstore size 360.0
2012-09-18 20:30:06,870 INFO  [StoreCloserThread-.META.,,1.1028785192-1] regionserver.HStore(635): Closed info
2012-09-18 20:30:06,870 DEBUG [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(1528): Finished snapshotting -ROOT-,,0.70236052, commencing wait for mvcc, flushsize=360
2012-09-18 20:30:06,871 DEBUG [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(1538): Finished snapshotting, commencing flushing stores
2012-09-18 20:30:06,871 INFO  [RS_CLOSE_META-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(1023): Closed .META.,,1.1028785192
2012-09-18 20:30:06,871 DEBUG [RS_CLOSE_META-hemera.apache.org,56450,1348000201701-0] handler.CloseRegionHandler(168): Closed region .META.,,1.1028785192
2012-09-18 20:30:06,874 DEBUG [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] util.FSUtils(167): Creating file=hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/.tmp/46b0e31202e648a4ad90d0df7bcf667b with permission=rwxrwxrwx
2012-09-18 20:30:06,877 DEBUG [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] hfile.HFileWriterV2(142): Initialized with CacheConfig:enabled [cacheDataOnRead=true] [cacheDataOnWrite=false] [cacheIndexesOnWrite=false] [cacheBloomsOnWrite=false] [cacheEvictOnClose=false] [cacheCompressed=false]
2012-09-18 20:30:06,877 INFO  [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] regionserver.StoreFile$Writer(1021): Delete Family Bloom filter type for hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/.tmp/46b0e31202e648a4ad90d0df7bcf667b: CompoundBloomFilterWriter
2012-09-18 20:30:06,884 INFO  [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] regionserver.StoreFile$Writer(1241): NO General Bloom and NO DeleteFamily was added to HFile (hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/.tmp/46b0e31202e648a4ad90d0df7bcf667b) 
2012-09-18 20:30:06,885 INFO  [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] regionserver.HStore(767): Flushed , sequenceid=5, memsize=360.0, into tmp file hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/.tmp/46b0e31202e648a4ad90d0df7bcf667b
2012-09-18 20:30:06,895 DEBUG [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] regionserver.HStore(792): Renaming flushed file at hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/.tmp/46b0e31202e648a4ad90d0df7bcf667b to hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/info/46b0e31202e648a4ad90d0df7bcf667b
2012-09-18 20:30:06,908 INFO  [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] regionserver.HStore(815): Added hdfs://localhost:42338/user/jenkins/hbase/-ROOT-/70236052/info/46b0e31202e648a4ad90d0df7bcf667b, entries=2, sequenceid=5, filesize=863.0
2012-09-18 20:30:06,909 INFO  [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(1617): Finished memstore flush of ~360.0/360, currentsize=0.0/0 for region -ROOT-,,0.70236052 in 39ms, sequenceid=5, compaction requested=false
2012-09-18 20:30:06,911 INFO  [StoreCloserThread--ROOT-,,0.70236052-1] regionserver.HStore(635): Closed info
2012-09-18 20:30:06,911 INFO  [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] regionserver.HRegion(1023): Closed -ROOT-,,0.70236052
2012-09-18 20:30:06,912 DEBUG [RS_CLOSE_ROOT-hemera.apache.org,56450,1348000201701-0] handler.CloseRegionHandler(168): Closed region -ROOT-,,0.70236052
2012-09-18 20:30:06,927 INFO  [MASTER_TABLE_OPERATIONS-hemera.apache.org,57673,1348000201449-0] regionserver.HRegion(3834): creating HRegion _acl_ HTD == '_acl_', {NAME => 'l', DATA_BLOCK_ENCODING => 'NONE', BLOOMFILTER => 'NONE', REPLICATION_SCOPE => '0', COMPRESSION => 'NONE', VERSIONS => '10', TTL => '2147483647', MIN_VERSIONS => '0', KEEP_DELETED_CELLS => 'false', BLOCKSIZE => '8192', ENCODE_ON_DISK => 'true', IN_MEMORY => 'true', BLOCKCACHE => 'true'} RootDir = hdfs://localhost:42338/user/jenkins/hbase Table name == _acl_
2012-09-18 20:30:06,930 DEBUG [MASTER_TABLE_OPERATIONS-hemera.apache.org,57673,1348000201449-0] regionserver.HRegion(474): Instantiated _acl_,,1348000206499.1780fcc5fe1c340ecbcc64e37893e8a5.
2012-09-18 20:30:06,933 DEBUG [MASTER_TABLE_OPERATIONS-hemera.apache.org,57673,1348000201449-0] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,934 DEBUG [MASTER_TABLE_OPERATIONS-hemera.apache.org,57673,1348000201449-0] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,934 DEBUG [MASTER_TABLE_OPERATIONS-hemera.apache.org,57673,1348000201449-0] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,935 DEBUG [MASTER_TABLE_OPERATIONS-hemera.apache.org,57673,1348000201449-0] client.HConnectionManager$HConnectionImplementation(1131): locateRegionInMeta parentTable=-ROOT-, metaLocation={region=-ROOT-,,0.70236052, hostname=hemera.apache.org, port=56450}, attempt=0 of 100 failed; retrying after sleep of 1009 because: Connection refused
2012-09-18 20:30:06,935 DEBUG [MASTER_TABLE_OPERATIONS-hemera.apache.org,57673,1348000201449-0] client.HConnectionManager$HConnectionImplementation(933): Looking up root region location in ZK, connection=hconnection 0x2bfa91
2012-09-18 20:30:06,936 DEBUG [MASTER_TABLE_OPERATIONS-hemera.apache.org,57673,1348000201449-0] zookeeper.ZKUtil(1141): hconnection 0x2bfa91-0x139db12b83f0002 Retrieved 36 byte(s) of data from znode /hbase/root-region-server; data=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:06,936 DEBUG [MASTER_TABLE_OPERATIONS-hemera.apache.org,57673,1348000201449-0] client.HConnectionManager$HConnectionImplementation(938): Looked up root region location, connection=hconnection 0x2bfa91; serverName=hemera.apache.org,56450,1348000201701
2012-09-18 20:30:07,016 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701.leaseChecker] regionserver.Leases(123): RegionServer:0;hemera.apache.org,56450,1348000201701.leaseChecker closing leases
2012-09-18 20:30:07,016 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701.leaseChecker] regionserver.Leases(130): RegionServer:0;hemera.apache.org,56450,1348000201701.leaseChecker closed leases
2012-09-18 20:30:07,070 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(966): stopping server hemera.apache.org,56450,1348000201701; all regions closed.
2012-09-18 20:30:07,070 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701.logSyncer] wal.HLog$LogSyncer(1245): RegionServer:0;hemera.apache.org,56450,1348000201701.logSyncer exiting
2012-09-18 20:30:07,071 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] wal.HLog(1007): closing hlog writer in hdfs://localhost:42338/user/jenkins/hbase/.logs/hemera.apache.org,56450,1348000201701
2012-09-18 20:30:07,077 DEBUG [RegionServer:0;hemera.apache.org,56450,1348000201701] wal.HLog(975): Moved 1 log files to /user/jenkins/hbase/.oldlogs
2012-09-18 20:30:07,078 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.Leases(123): RegionServer:0;hemera.apache.org,56450,1348000201701 closing leases
2012-09-18 20:30:07,079 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.Leases(130): RegionServer:0;hemera.apache.org,56450,1348000201701 closed leases
2012-09-18 20:30:07,080 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeDeleted, state=SyncConnected, path=/hbase/rs/hemera.apache.org,56450,1348000201701
2012-09-18 20:30:07,080 INFO  [pool-1-thread-1-EventThread] zookeeper.RegionServerTracker(94): RegionServer ephemeral node deleted, processing expiration [hemera.apache.org,56450,1348000201701]
2012-09-18 20:30:07,081 INFO  [pool-1-thread-1-EventThread] master.ServerManager(446): Cluster shutdown set; hemera.apache.org,56450,1348000201701 expired; onlineServers=0
2012-09-18 20:30:07,081 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] master.HMaster(1067): Stopping service threads
2012-09-18 20:30:07,081 INFO  [pool-1-thread-1-EventThread] master.HMaster(2049): Cluster shutdown set; onlineServer=0
2012-09-18 20:30:07,081 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): master:57673-0x139db12b83f0000 Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/rs
2012-09-18 20:30:07,081 INFO  [Master:0;hemera.apache.org,57673,1348000201449.oldLogCleaner] hbase.Chore(81): Master:0;hemera.apache.org,57673,1348000201449.oldLogCleaner exiting
2012-09-18 20:30:07,081 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(995): stopping server hemera.apache.org,56450,1348000201701; zookeeper connection closed.
2012-09-18 20:30:07,082 ERROR [MASTER_TABLE_OPERATIONS-hemera.apache.org,57673,1348000201449-0] handler.CreateTableHandler(137): Error trying to create the table _acl_
java.io.IOException: Giving up trying to location region in meta: thread is interrupted.
	at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.locateRegionInMeta(HConnectionManager.java:1151)
	at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.locateRegion(HConnectionManager.java:950)
	at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.locateRegion(HConnectionManager.java:911)
	at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation$Process.submit(HConnectionManager.java:1886)
	at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation$Process.doRetry(HConnectionManager.java:1926)
	at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation$Process.processBatchCallback(HConnectionManager.java:2033)
	at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation$Process.access$900(HConnectionManager.java:1828)
	at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.processBatchCallback(HConnectionManager.java:1817)
	at org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.processBatch(HConnectionManager.java:1796)
	at org.apache.hadoop.hbase.client.HTable.flushCommits(HTable.java:1020)
	at org.apache.hadoop.hbase.client.HTable.doPut(HTable.java:832)
	at org.apache.hadoop.hbase.client.HTable.put(HTable.java:815)
	at org.apache.hadoop.hbase.catalog.MetaEditor.putsToMetaTable(MetaEditor.java:129)
	at org.apache.hadoop.hbase.catalog.MetaEditor.addRegionsToMeta(MetaEditor.java:209)
	at org.apache.hadoop.hbase.master.handler.CreateTableHandler.handleCreateTable(CreateTableHandler.java:164)
	at org.apache.hadoop.hbase.master.handler.CreateTableHandler.process(CreateTableHandler.java:132)
	at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:202)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)
2012-09-18 20:30:07,081 INFO  [Master:0;hemera.apache.org,57673,1348000201449.archivedHFileCleaner] hbase.Chore(81): Master:0;hemera.apache.org,57673,1348000201449.archivedHFileCleaner exiting
2012-09-18 20:30:07,083 INFO  [RegionServer:0;hemera.apache.org,56450,1348000201701] regionserver.HRegionServer(998): RegionServer:0;hemera.apache.org,56450,1348000201701 exiting
2012-09-18 20:30:07,084 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] zookeeper.ZKUtil(1141): master:57673-0x139db12b83f0000 Retrieved 36 byte(s) of data from znode /hbase/master; data=PBUF\x0A\x1E\x0A\x11hemera.ap...
2012-09-18 20:30:07,084 INFO  [Shutdown of org.apache.hadoop.hbase.fs.HFileSystem@1eae15f] hbase.MiniHBaseCluster$SingleFileSystemShutdownThread(186): Hook closing fs=org.apache.hadoop.hbase.fs.HFileSystem@1eae15f
2012-09-18 20:30:07,084 INFO  [pool-1-thread-1] util.JVMClusterUtil(263): Shutdown of 1 master(s) and 1 regionserver(s) complete
2012-09-18 20:30:07,085 DEBUG [Master:0;hemera.apache.org,57673,1348000201449] catalog.CatalogTracker(257): Stopping catalog tracker org.apache.hadoop.hbase.catalog.CatalogTracker@959fa1
2012-09-18 20:30:07,085 INFO  [hemera.apache.org,57673,1348000201449.timeoutMonitor] hbase.Chore(81): hemera.apache.org,57673,1348000201449.timeoutMonitor exiting
2012-09-18 20:30:07,085 INFO  [hemera.apache.org,57673,1348000201449.splitLogManagerTimeoutMonitor] hbase.Chore(81): hemera.apache.org,57673,1348000201449.splitLogManagerTimeoutMonitor exiting
2012-09-18 20:30:07,085 INFO  [hemera.apache.org,57673,1348000201449.timerUpdater] hbase.Chore(81): hemera.apache.org,57673,1348000201449.timerUpdater exiting
2012-09-18 20:30:07,086 INFO  [Master:0;hemera.apache.org,57673,1348000201449] master.HMaster(481): HMaster main thread exiting
2012-09-18 20:30:07,087 INFO  [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(238): Shutdown MiniZK cluster with all ZK servers
2012-09-18 20:30:07,088 INFO  [pool-1-thread-1] log.Slf4jLog(67): Stopped SelectChannelConnector@localhost:0
2012-09-18 20:30:07,187 DEBUG [Master:0;hemera.apache.org,57673,1348000201449-EventThread] zookeeper.ZooKeeperWatcher(265): hconnection 0x2bfa91-0x139db12b83f0002 Received ZooKeeper Event, type=None, state=Disconnected, path=null
2012-09-18 20:30:07,187 DEBUG [Master:0;hemera.apache.org,57673,1348000201449-EventThread] zookeeper.ZooKeeperWatcher(363): hconnection 0x2bfa91-0x139db12b83f0002 Received Disconnected from ZooKeeper, ignoring
2012-09-18 20:30:07,187 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): TestZKPermissionsWatcher_2-0x139db12b83f0007 Received ZooKeeper Event, type=None, state=Disconnected, path=null
2012-09-18 20:30:07,187 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(265): TestZKPermissionsWatcher_1-0x139db12b83f0006 Received ZooKeeper Event, type=None, state=Disconnected, path=null
2012-09-18 20:30:07,187 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(363): TestZKPermissionsWatcher_2-0x139db12b83f0007 Received Disconnected from ZooKeeper, ignoring
2012-09-18 20:30:07,187 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(363): TestZKPermissionsWatcher_1-0x139db12b83f0006 Received Disconnected from ZooKeeper, ignoring
2012-09-18 20:30:07,191 WARN  [org.apache.hadoop.hdfs.server.datanode.DataXceiverServer@1d4d493] datanode.DataXceiverServer(138): DatanodeRegistration(127.0.0.1:38765, storageID=DS-2065886277-140.211.11.27-38765-1348000200717, infoPort=49745, ipcPort=53190):DataXceiveServer:java.nio.channels.AsynchronousCloseException
	at java.nio.channels.spi.AbstractInterruptibleChannel.end(AbstractInterruptibleChannel.java:185)
	at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:159)
	at sun.nio.ch.ServerSocketAdaptor.accept(ServerSocketAdaptor.java:84)
	at org.apache.hadoop.hdfs.server.datanode.DataXceiverServer.run(DataXceiverServer.java:131)
	at java.lang.Thread.run(Thread.java:662)

2012-09-18 20:30:08,191 WARN  [DataNode: [/x1/jenkins/jenkins-slave/workspace/HBase-TRUNK/trunk/hbase-server/target/test-data/0d33b8f6-92e9-4547-8f41-896f54a6c1f9/dfscluster_f21fe306-e20e-4a9b-9d9f-61dae4f25f3e/dfs/data/data1,/x1/jenkins/jenkins-slave/workspace/HBase-TRUNK/trunk/hbase-server/target/test-data/0d33b8f6-92e9-4547-8f41-896f54a6c1f9/dfscluster_f21fe306-e20e-4a9b-9d9f-61dae4f25f3e/dfs/data/data2]] util.MBeans(73): Hadoop:service=DataNode,name=DataNodeInfo
javax.management.InstanceNotFoundException: Hadoop:service=DataNode,name=DataNodeInfo
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.getMBean(DefaultMBeanServerInterceptor.java:1094)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.exclusiveUnregisterMBean(DefaultMBeanServerInterceptor.java:415)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.unregisterMBean(DefaultMBeanServerInterceptor.java:403)
	at com.sun.jmx.mbeanserver.JmxMBeanServer.unregisterMBean(JmxMBeanServer.java:506)
	at org.apache.hadoop.metrics2.util.MBeans.unregister(MBeans.java:71)
	at org.apache.hadoop.hdfs.server.datanode.DataNode.unRegisterMXBean(DataNode.java:522)
	at org.apache.hadoop.hdfs.server.datanode.DataNode.shutdown(DataNode.java:737)
	at org.apache.hadoop.hdfs.server.datanode.DataNode.run(DataNode.java:1471)
	at java.lang.Thread.run(Thread.java:662)
2012-09-18 20:30:08,192 WARN  [pool-1-thread-1] util.MBeans(73): Hadoop:service=DataNode,name=FSDatasetState-UndefinedStorageId558675759
javax.management.InstanceNotFoundException: Hadoop:service=DataNode,name=FSDatasetState-UndefinedStorageId558675759
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.getMBean(DefaultMBeanServerInterceptor.java:1094)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.exclusiveUnregisterMBean(DefaultMBeanServerInterceptor.java:415)
	at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.unregisterMBean(DefaultMBeanServerInterceptor.java:403)
	at com.sun.jmx.mbeanserver.JmxMBeanServer.unregisterMBean(JmxMBeanServer.java:506)
	at org.apache.hadoop.metrics2.util.MBeans.unregister(MBeans.java:71)
	at org.apache.hadoop.hdfs.server.datanode.FSDataset.shutdown(FSDataset.java:2067)
	at org.apache.hadoop.hdfs.server.datanode.DataNode.shutdown(DataNode.java:799)
	at org.apache.hadoop.hdfs.MiniDFSCluster.shutdownDataNodes(MiniDFSCluster.java:566)
	at org.apache.hadoop.hdfs.MiniDFSCluster.shutdown(MiniDFSCluster.java:550)
	at org.apache.hadoop.hbase.HBaseTestingUtility.shutdownMiniDFSCluster(HBaseTestingUtility.java:503)
	at org.apache.hadoop.hbase.HBaseTestingUtility.shutdownMiniCluster(HBaseTestingUtility.java:752)
	at org.apache.hadoop.hbase.security.access.TestZKPermissionsWatcher.afterClass(TestZKPermissionsWatcher.java:83)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:36)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
	at org.junit.runners.Suite.runChild(Suite.java:128)
	at org.junit.runners.Suite.runChild(Suite.java:24)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
	at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
	at java.util.concurrent.FutureTask.run(FutureTask.java:138)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)
2012-09-18 20:30:08,193 WARN  [pool-1-thread-1] datanode.FSDatasetAsyncDiskService(121): AsyncDiskService has already shut down.
2012-09-18 20:30:08,193 INFO  [pool-1-thread-1] log.Slf4jLog(67): Stopped SelectChannelConnector@localhost:0
2012-09-18 20:30:08,295 WARN  [org.apache.hadoop.hdfs.server.namenode.FSNamesystem$ReplicationMonitor@1d2b9b7] namenode.FSNamesystem$ReplicationMonitor(2718): ReplicationMonitor thread received InterruptedException.java.lang.InterruptedException: sleep interrupted
2012-09-18 20:30:08,302 INFO  [pool-1-thread-1] hbase.HBaseTestingUtility(756): Minicluster is down

Attachments

Activity

People

Assignee:: Unassigned

Reporter:: Ted Yu

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 18/Sep/12 20:51

Updated:: 14/Jun/22 18:02

Resolved:: 08/Jan/15 08:36